[rules-users] Confusing behavior for StatefulKnowledgeSession.fireAllRules() with negated conditions.

[bill simms]

Hello again,

Recently while continuing to work on a complex event processing project I
have encountered strange,
but interesting, situations where the fireAllRules() method of a
StatefulKnowledgeSession appears to
return before actually emptying the activations on the agenda.  I was under
the impression that this
method only returns after all activations, including subsequent activations,
have been completed and
removed from the agenda.  If I'm incorrect then feel free to disregard the
rest of this message.

[Drools v 5.0.1, JUnit 4.0, Spring 2.5.6]

The behavior I have noticed begins when working with a rule such as "Find
Missing Input Events"
(in file test.drl):
------------------------------------------------------------------------
package org.drools.test

import org.drools.test.*

declare Event
    @role( event )
    @timestamp( beginning )
    @duration( length )
    @expires( 1h )
end

declare Fault
    @role( event )
    @timestamp( beginning )
    @duration( length )
    @expires( 1h )
end

query "getFaults"
    $fault: Fault() from entry-point "faults"
end

rule "Find Missing Input Events"
    when
        $a: Event()
            from entry-point "input"
        $b: Event( this after $a)
            from entry-point "input"
        not (Event( (this after $a || this metby $a), (this before $b ||
this meets $b))
            from entry-point "input")
        not (Fault(this metby $a, this meets $b)
            from entry-point "faults")
    then
        entryPoints["faults"].insert(new Fault($a, $b));
end

rule "Print Faults"

    when
        $f: Fault() from entry-point "faults"
    then
        System.out.println($f);
end
------------------------------------------------------------------------

The purpose of this rule is to detect when one or more events are missing in
an event sequence.  The
events in question are supposed to continue from one to the next without any
time in-between.  If this
rule does discover a gap/absence between two events a Fault is created for
further processing.  (*Note
that the Event and Fault classes that I used only contain two fields,
beginning and length, to be used as
the time-stamp and duration respectively.)  I noticed the unexpected
behavior shortly after creating this
unit test:

------------------------------------------------------------------------
public class FireAllRulesTest {

    KnowledgeBase knowledgeBase;

    StatefulKnowledgeSession session;

    /**
     * @throws java.lang.Exception
     */
    @Before
    public void setUp() throws Exception {
        KnowledgeBuilder builder =
KnowledgeBuilderFactory.newKnowledgeBuilder();

builder.add(ResourceFactory.newFileResource("target/test-classes/test.drl"),
ResourceType.DRL);

        if(builder.hasErrors()){
            throw new RuntimeException(builder.getErrors().toString());
        }
        KnowledgeBaseConfiguration configuration =
KnowledgeBaseFactory.newKnowledgeBaseConfiguration();
        configuration.setOption(EventProcessingOption.STREAM);

        knowledgeBase =
KnowledgeBaseFactory.newKnowledgeBase(configuration);
        knowledgeBase.addKnowledgePackages(builder.getKnowledgePackages());

        session = knowledgeBase.newStatefulKnowledgeSession();
        WorkingMemoryConsoleLogger logger = new
WorkingMemoryConsoleLogger(session);
    }

    @Test
    public void testAbsence(){
        System.out.println("Running...");
        //Record the rules that have fired.
        ActivationTrackingEventListener listener = new
ActivationTrackingEventListener();
        session.addEventListener(listener);

        //Start at 0, go to 100.
        Event first = new Event(0,100);

        //Start at 1000, go to 1100. Absence of 900.
        Event second = new Event(1000, 100);

        //Start at 1100, go to 1200.  No absence.
        Event third = new Event(1100, 100);

        //Start at 1200, go to 1300.  No absence.
        Event fourth = new Event(1200, 100);

        //Start at 2000, go to 2100.  Absence of 700.
        Event fifth = new Event(2000, 100);

        WorkingMemoryEntryPoint ingest =
session.getWorkingMemoryEntryPoint("input");
        ingest.insert(first);
        ingest.insert(second);
        ingest.insert(third);
        ingest.insert(fourth);
        ingest.insert(fifth);

        System.out.println("All events have been inserted.");

        session.fireAllRules();

        System.out.println("Rules have finished firing.");

        //Expect that "Find Missing Input Events" has fired and that there
are two faults as a result.
        assertTrue(listener.hasRuleFired("Find Missing Input Events"));
        assertEquals(2,faultCount());

        System.out.println("Test completed.");
    }

    public int faultCount(){
        QueryResults results = session.getQueryResults("getFaults");
        return results.size();
    }

}
------------------------------------------------------------------------

The typical result of this test is a failure about 90% of the time.
Strangely, the other 10% of the time this exact
same test is run it will pass, without any modifications.  Equally
interesting is the output of the WorkingMemoryLogger:

------------------------------------------------------------------------
Running...
OBJECT ASSERTED value:org.drools.test.Event at 1b994de factId: 1
BEFORE ACTIVATION FIRED rule:Find Missing Input Events activationId:Find
Missing Input Events [2, 1, 0]
      declarations: $b=org.drools.test.Event at 2803d5(2);
$a=org.drools.test.Event at 1b994de(1)
ACTIVATION CREATED rule:Find Missing Input Events activationId:Find Missing
Input Events [2, 1, 0]
      declarations: $b=org.drools.test.Event at 2803d5(2);
$a=org.drools.test.Event at 1b994de(1)
OBJECT ASSERTED value:org.drools.test.Event at 2803d5 factId: 2
OBJECT ASSERTED value:org.drools.test.Event at 1b32627 factId: 3
OBJECT ASSERTED value:org.drools.test.Event at ad157f factId: 4
ACTIVATION CREATED rule:Find Missing Input Events activationId:Find Missing
Input Events [5, 4, 0]
      declarations: $b=org.drools.test.Event at 1bfa3d3(5);
$a=org.drools.test.Event at ad157f(4)
OBJECT ASSERTED value:org.drools.test.Event at 1bfa3d3 factId: 5
All events have been inserted.
***Rules have finished firing.
ACTIVATION CREATED rule:Print Faults activationId:Print Faults [6, 0]
declarations: $f=org.drools.test.Fault at 159780d(6)
OBJECT ASSERTED value:org.drools.test.Fault at 159780d factId: 6
AFTER ACTIVATION FIRED rule:Find Missing Input Events activationId:Find
Missing Input Events [2, 1, 0]
      declarations: $b=org.drools.test.Event at 2803d5(2);
$a=org.drools.test.Event at 1b994de(1)
BEFORE ACTIVATION FIRED rule:Print Faults activationId:Print Faults [6, 0]
declarations: $f=org.drools.test.Fault at 159780d(6)
org.drools.test.Fault at 159780d
AFTER ACTIVATION FIRED rule:Print Faults activationId:Print Faults [6, 0]
declarations: $f=org.drools.test.Fault at 159780d(6)
BEFORE ACTIVATION FIRED rule:Find Missing Input Events activationId:Find
Missing Input Events [5, 4, 0]
      declarations: $b=org.drools.test.Event at 1bfa3d3(5);
$a=org.drools.test.Event at ad157f(4)
ACTIVATION CREATED rule:Print Faults activationId:Print Faults [7, 0]
declarations: $f=org.drools.test.Fault at c26b16(7)
OBJECT ASSERTED value:org.drools.test.Fault at c26b16 factId: 7
AFTER ACTIVATION FIRED rule:Find Missing Input Events activationId:Find
Missing Input Events [5, 4, 0]
      declarations: $b=org.drools.test.Event at 1bfa3d3(5);
$a=org.drools.test.Event at ad157f(4)
BEFORE ACTIVATION FIRED rule:Print Faults activationId:Print Faults [7, 0]
declarations: $f=org.drools.test.Fault at c26b16(7)
org.drools.test.Fault at c26b16
AFTER ACTIVATION FIRED rule:Print Faults activationId:Print Faults [7, 0]
declarations: $f=org.drools.test.Fault at c26b16(7)
------------------------------------------------------------------------

It seems that the rule is indeed firing correctly, but that it is doing so
only after returning from fireAllRules method.
I have marked line that follows fireAllRules() with *** above.  So the rule
fires, but the test fails because the firing
takes place after the junit  assertions are checked.

But that's not all, it gets more interesting.  Looking back at the rule
file, when you comment out the last condition:

    not (Fault(this metby $a, this meets $b)
                from entry-point "faults")

The problem with the unit test disappears.  After much thought I'm still not
sure why this is, but the last condition is
critical to avoid creating redundant Faults (Because a lot of the Events are
redundant as well.  It just comes with the
problem being solved).  The problem also disappears if you put a
Thread.sleep(1000) after firing the rules, which is
why I suspect a timing issue between the rules firing and the unit test
assertions being evaluated.  This could explain
why the test sometimes works, and sometimes doesn't.

I'm hopeful that someone will understand why this is happening, and point
how how to prevent it.  Thank you in advance.

Bill
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/rules-users/attachments/20090908/4f3e4a9d/attachment.html