Troubleshooting a bad business rule
When Dovetail Rulemanager has a problem processing a business rule for some reason, it logs the problem. We can use these logs to help determine exactly what the problem is, and how to fix it.
We’ll walk through an example on troubleshooting a specific issue.
In this scenario, Rulemanager logged an error:
2015-06-12 10:23:07 [Consumer7] ERROR
FChoice.RuleManager.OperandException – FChoice.RuleManager.OperandException: (-1)
Invalid operand format for an IsIn operator.
It looks like there was a problem with a rule condition that uses an IsIn operator. So how do we know which rule this is referring to? There may be hundreds of rules in the system.
All of the needed information is contained in the log file. But since Rulemanager is a super busy application, and it’s multi-threaded, the logs contain a LOT of information.
In a log file I recently received from a customer, there’s over 650,000 lines in a single log file. How do I narrow this down?
Narrow by Thread
In the error message, take note of the information that comes after the timestamp. In this case “Consumer7”. This is the thread. We can use this to narrow down our logs to just contain the information for this thread.
Since I love my UNIX tools, I can easily extract just the logs for this thread into a separate log file using cat and grep.
cat RuleManager.log | grep -i “consumer7” > consumer7.log
That creates a file named consumer7.log, and narrows me down from 650,000 lines to just 3500. Much more manageable to work with.
Now I simply open that consumer7.log file using my text editor and search for the error. In this case, I search for “Invalid operand format for an IsIn operator”
Logs
Now that I have just the thread logs, I simply start reading up the file.
Here’s the log entries showing the error as well as the handful of entries immediately before the error (I’ve removed the timestamps and class names for brevity)
Found Start event “DISPATCH” for Rule “Cashiering subcases”.
Evaluating condition 268451782: Property: “Current Queue”, Right operand: “(Cashiering’)”, Operator: “IsIn”, Type: “String”
Item “Current Queue” was retrieved from the Repository cache.
Path “case_currq2queue:title” expands to SQL command “SELECT T1.objid, T1.TITLE FROM table_case T0, table_queue T1 WHERE T0.objid = {0} AND T0.case_currq2queue = T1.objid ORDER BY T1.objid DESC”
Property “Current Queue” using “case_currq2queue:title” expands to “Escalation”
RuleManager.ConditionOperators.IsIn – Forcing both operands to be of type “String”
RuleManager.OperandException: (-1) Invalid operand format for an IsIn operator.
Log Entries, One by One
So, looking at the logs just for this thread, we can see exactly what happened:
1. Found Start event “DISPATCH” for Rule “Cashiering subcases”.
We have a rule named “Cashiering subcases”, and it has a start event of Dispatch
2. Evaluating condition 268451782: Property: “Current Queue”, Right operand: “(Cashiering’)”, Operator: “IsIn”, Type: “String”
We have a rule condition that looks like: Current Queue Is In (Cashiering’)
3. Item “Current Queue” was retrieved from the Repository cache.
Rulemanager has already cached the path to the Current Queue, so it already knows how to traverse from case to queue without going to the database.
4. Path “case_currq2queue:title” expands to SQL command “SELECT T1.objid, T1.TITLE FROM table_case T0, table_queue T1 WHERE T0.objid = {0} AND T0.case_currq2queue = T1.objid ORDER BY T1.objid DESC”
This is the SQL that retrieves the Current Queue property for this case
5. Property “Current Queue” using “case_currq2queue:title” expands to “Escalation”
The Current Queue property for this case resolves to “Escalation”
6. RuleManager.ConditionOperators.IsIn – Forcing both operands to be of type “String”
Make both conditions be a String datatype, for proper comparison.
7. RuleManager.OperandException: (-1) Invalid operand format for an IsIn operator.
And here’s our error.
So what happened was that we ended up with a rule condition that looks like:
‘Escalation’ Is In (Cashiering’)
And the comparison fails because of the mismatched quotes in the operand, namely: (Cashiering’)
The operand should be: (‘Cashiering’)
Note the missing quote in the original.
Find the rule that has this condition
Now that we know what condition is failing, going back up the log chain tells us which rule this condition is for:
Found Start event “DISPATCH” for Rule “Cashiering subcases”.
It’s the “cashiering subcases” rule that has the bad condition. We can now use the Business Rule UI within Dovetail Admin to fix the condition, and quote the string properly.
Plan B
Alternatively, since we know the objid of the rule condition from the logs:
Evaluating condition 268451782: Property: “Current Queue”, Right operand: “(Cashiering’)”, Operator: “IsIn”, Type: “String”
We can use SQL with that objid to find the specific business rule:
select title from table_com_tmplte where objid = (select parentrule2com_tmplte from table_rule_cond where objid = {RuleConditionObjid})
So in our case, it would be:
select title from table_com_tmplte where objid = (select parentrule2com_tmplte from table_rule_cond where objid = 268451782)
And this again gives us the name of the business rule with the bad condition: Cashiering subcases
We can now use the Business Rule UI within Dovetail Admin to fix the condition, and quote the string properly.
Summary
Dovetail Rulemanager is a critical component of a Dovetail/Clarify implementation. When something doesn’t work as it should, spending a few minutes tracking down the issue is typically well worth it.
Even though the Rulemanager logs can be very verbose, they can also be super helpful in tracking down an issue. Hopefully this post gave you a few ideas of how to make this process easier.
Related Readings
How Do I Get Notifications When Dovetail Rulemanager Cannot Process A Timebomb?
Troubleshooting Bad Time Bombs
