Menu

Official website

Logging rule activation with Drools

author image Peter Hilton

26 Sep 2011

min read

java drools en

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.

expand_less