Logging rule activation with Drools
This article shows another simple Drools logging technique. This is a recipe from the Lunatech Drools Cookbook - recipes for effective Drools use.
Problem
One of the reasons that you want to log debug messages from your rules is that you just want to see which rules are activated, how many times and in which order. This is frequently part of debugging a set of rules and part of understanding how a particular rule set works: you may need to see which rules were activated in order to understand final results, or you may wish to know whether a particular rule did or did not fire. However, adding a log statement to every rule’s right-hand side takes time and clutters the code.
Solution
Write an event listener that logs the activation of each rule, using a lower logging level so you can disable this logging independently of normal debug logging.
org.drools.event.rule.AgendaEventListener
defines an interface for an
event lister that handles events relating to the ‘agenda’ - the table of
rule activations that will be ‘fired’. In this case, we are interested
in the ‘before activation fired’ event, which occurs just before an
activation’s rule’s right-hand side is executed.
The org.drools.event.rule.DefaultAgendaEventListener
class implements
this interface with empty methods so that you only have to override the
methods that you are interested in, as in the following sub-class.
package com.lunatech.drools;
import org.apache.log4j.Logger;
import org.drools.definition.rule.Rule;
import org.drools.event.rule.BeforeActivationFiredEvent;
import org.drools.event.rule.DefaultAgendaEventListener;
public class EventListener extends DefaultAgendaEventListener {
@Override
public void beforeActivationFired(final BeforeActivationFiredEvent event) {
final Rule rule = event.getActivation().getRule();
final Logger log = Logger.getLogger(rule.getPackageName() + "." + rule.getName());
log.trace(event.getClass().getSimpleName());
}
}
To use this event listener, add it to the rules session before calling
fireAllRules()
.
final StatelessKnowledgeSession session = knowledgeBase.newStatelessKnowledgeSession();
session.addEventListener(new EventListener());
A rules session with rules in pricing.order
and pricing.shipment
packages might then generate output like the following.
15:42:02,851 pricing.order.Order line - BeforeActivationFiredEventImpl
15:42:02,851 pricing.order.Order line - BeforeActivationFiredEventImpl
15:42:02,852 pricing.order.Order line - BeforeActivationFiredEventImpl
15:42:02,853 pricing.shipment.Basic charge - BeforeActivationFiredEventImpl
15:42:02,854 pricing.shipment.Book - BeforeActivationFiredEventImpl
15:42:02,854 pricing.shipment.Book - BeforeActivationFiredEventImpl
15:42:02,855 pricing.shipment.DVD - BeforeActivationFiredEventImpl
15:42:02,857 pricing.shipment.Express shipping - BeforeActivationFiredEventImpl
How it works
This will generate a lot of output, in general, which is why the log
level is TRACE
.
The Logger ‘category’ is based on the rule’s package name and rule name,
instead of the EventListener
class itself. This means that the useful
part of the log output is the rule name, not the fixed log message: the
log output is effectively a list of executed rules.
Note that categorising log messages by package and rule name also makes it easy to filter the logging in the Log4J configuration. You can configure the log output to only include the subset of rules you are interested in.