Hi,

I am using the latest 5.1.1 (8/2010 release) Drools code to test out rules. What I see is when I try to retract/insert an object from the working memory, it doesn’t seem to take effect.

The example is as follows. I pump metrics into the rule engine at 4s interval. Drools is configured to run in STREAM mode to allow facts to expire and to use the sliding window feature of Fusion. There are 2 rules, the set rule says that if the minimum value is > set threshold over the sliding window interval, raise an alarm if not raised earlier (it also inserts an alarm into the working memory). The clear rule says that if the minimum value is < clear threshold over the sliding window interval and if alarm exists, then clear the alarm and retract it.

I use the pseudo clock and advance every time I insert an event. Now, if I use a data set, where all the values are > set threshold, then I see that an alarm is raised and only once (as expected). But if I use a data set that should cause a set/clear/set pattern, I see that after setting, the clear happens twice, followed by set, which happens twice again.

I used the Drools debugger within Eclipse and saw that I was hitting the RHS side twice in the clear/set rule. As I cannot put a break-point on the LHS to see why it decided to do fire in the first place, I can’t tell the behavior.

Its as if drools ignores the insert/retract of the alarm action.

Thanks in advance,

Here is the DRL:

package com.x.y.rules;

import java.util.Date;

import com.x.y.z.ruleengine.AlarmActionFactory;

import com.x.y.z.rule.Event.Srd;

import com.x.y.z.NaEvent;

import com.x.y.z.Common.SeverityLevels;

import com.x.y.z.Common.EventsStatus;

import com.x.y.z.rule.Event.Alarm;

global AlarmActionFactory actionFactory;

declare Srd

@role(event)

@expires(5s)

end

rule "Clear Srd threshold of 25.0 for 5s"

dialect "java"

when

$c : Srd(probeName == 'threstest1')

$SrdMin : Number(doubleValue <= 25.0) from accumulate(

Srd(probeName == $c.probeName,$v : value) over window:time(5s), min($v)

)

$alarm : Alarm(type == 'Srd' && probeName == 'threstest1')

then

if($alarm !=null)

{

System.out.println("Clearing alarm, since Srd went below 25.0 threshold for 5s. Srd: "+$SrdMin);

System.out.println("Removing alarm from system "+$alarm);

retract($alarm);

String desc = "Clearing alarm as SessionRequestDelayMilliSecs went below threshold 25.0 for probe threstest1";

actionFactory.logEvent(desc);

}

else

actionFactory.logEvent("WARN: clearing again, alarm doesnt exist for Srd metric with probename threstest1");

end

rule "Set Srd threshold of 50.0 for 5s"

dialect "java"

when

$c : Srd(probeName == 'threstest1')

$minsrd : Number(doubleValue >= 50.0) from accumulate(

Srd(probeName == $c.probeName,$v : value) over window:time(5s), min($v)

)

not Alarm(type == 'Srd' && probeName == 'threstest1')

then

System.out.println("Srd above 50.0 for 5s, raising alarm. min Srd: "+$minsrd);

Alarm a = new Alarm("Srd","threstest1");

insert(a);

String desc = "Raised alarm as SessionRequestDelayMilliSecs hit threshold 50.0 for probe threstest1";

actionFactory.logEvent(desc);

end

Here is the data set that is read by the java class pumping the events.

# the set/clear threshold in thres1_Srd.drl is set to 50/25.O

# the test program reads the values one line at a time

# the sliding window time and fact expiration time it set to 5s.

# the test program advances the pseudo clock by delta value

# which is the difference between the previous and the current token value

# read from this file.

# the alarm raising pattern for this data should be

# set/clear/set

# NOTE: first value is time, second value is the actual event value.

1358,60

5359,66

9360,62

13361,24

17362,23

21363,24

25364,28

29365,21

33366,27

37367,67

41367,89

45367,92

49367,72

53367,65

57367,99

Snippet of main method of the java class

KnowledgeBuilder kbuilder = KnowledgeBuilderFactory.newKnowledgeBuilder();

boolean useSrdMetric = true;

kbuilder.add(ResourceFactory.newClassPathResource("threstest1_Srd.drl", REAlarmFiringTest.class),

ResourceType.DRL);

// Check the builder for errors

if (kbuilder.hasErrors())

{

System.out.println(kbuilder.getErrors().toString());

throw new RuntimeException("Unable to compile "

+ ("Srd".equals(args[0]) ? "thres1_Srd.drl" : "thres1_Owd.drl"));

}

// get the compiled packages (which are serializable)

Collection<KnowledgePackage> pkgs = kbuilder.getKnowledgePackages();

// to use sliding windows, have to run the engine in stream mode

// default is cloud mode..where there are no concept of time and

// event ordering

KnowledgeBaseConfiguration kbaseconfig = KnowledgeBaseFactory.newKnowledgeBaseConfiguration();

kbaseconfig.setOption(EventProcessingOption.STREAM);

// add the packages to a knowledgebase (deploy the knowledge packages).

KnowledgeBase kbase = KnowledgeBaseFactory.newKnowledgeBase(kbaseconfig);

kbase.addKnowledgePackages(pkgs);

KnowledgeSessionConfiguration conf = KnowledgeBaseFactory.newKnowledgeSessionConfiguration();

conf.setOption(ClockTypeOption.get("pseudo"));

StatefulKnowledgeSession ksession = kbase.newStatefulKnowledgeSession(conf, null);

// get clock to manually advance and test firing..

SessionPseudoClock clock = ksession.getSessionClock();

logger.info("Pseudo clock current time initialized to " + clock.getCurrentTime());

// we will have one helper class AlarmActionFactory, that will provide

// static methods for all the possible actions that can be taken

// when an alarm fires, including logging events.

ksession.setGlobal("actionFactory", AlarmActionFactory.newInstance());

// this will send data to the std err stream

ksession.addEventListener(new DebugAgendaEventListener());

ksession.addEventListener(new DebugWorkingMemoryEventListener());

// setup the audit logging

KnowledgeRuntimeLogger krlogger = KnowledgeRuntimeLoggerFactory.newFileLogger(ksession, destdir

+ ("Srd".equals(args[0]) ? "srdaudit" : "owdaudit"));

BufferedReader bf = new BufferedReader(new FileReader(args[1]));

String s;

int time = 0;

int count = 0;

int lastime = 0;

int delta = 0;

// NOTE: the drl are setup with a sliding window of 5s.

// We will insert objects into the RE every 4s, so that the

// previous objects linger long enough to contribute to the calc

while ((s = bf.readLine()) != null)

{

if (s.startsWith("#"))

continue;

String[] vals = s.split(",");

Event event = new Srd();

event.setValue(Integer.parseInt(vals[1]));

// set in ms

// for the first time, initialize time and lastime

// to the value read in from the first line.

time = Integer.parseInt(vals[0]);

if (count == 0)

{

lastime = time;

logger.info("Initialized lastime to " + lastime);

// this is basically time t0 when the first event gets inserted

clock.advanceTime(time, TimeUnit.MILLISECONDS);

} else

{

// advance based on the read in time in ms

// do it only from the second insert onwards

// note that the time delta should be around 4s

delta = (int) (time - lastime);

clock.advanceTime(delta, TimeUnit.MILLISECONDS);

logger.info("Pseudo clock advanced " + delta + "ms");

}

event.setTimestamp(time);

// the probename has to be threstest1 as the drls are configured with

// that probe name. so do not change this value.

event.setProbeName("threstest1");

logger.info("Inserted event " + event);

logger.info("Count: " + count + " Pseudo clock current time: " + clock.getCurrentTime());

ksession.insert(event);

logger.info("calling drools fire rules");

ksession.fireAllRules();

count++;

lastime = time;

}

System.out.println("Inserted facts, current time is " + new Date());

krlogger.close();

ksession.dispose();

bf.close();

System.out.println("Closed audit logger, disposing session, exiting..");

Here is the log output of the run of the program above: Note the EVENT MESSAGE green/red output, which gets printed as a consequence of the rule firing. Red indicates it fired again without any other insertion of event.

2010-09-24 11:53:17,039-INFO -[main]: Pseudo clock current time initialized to 0

2010-09-24 11:53:17,053-INFO -[main]: Initialized lastime to 1358

2010-09-24 11:53:17,054-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=1358, value=60.0]

2010-09-24 11:53:17,054-INFO -[main]: Count: 0 Pseudo clock current time: 1358

2010-09-24 11:53:17,074-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,076-INFO -[main]: EVENT MESSAGE: Raised alarm as SessionRequ

estDelayMilliSecs hit threshold 50.0 for probe threstest1

2010-09-24 11:53:17,077-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,077-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=5359, value=66.0]

2010-09-24 11:53:17,077-INFO -[main]: Count: 1 Pseudo clock current time: 5359

2010-09-24 11:53:17,077-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,077-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,078-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=9360, value=62.0]

2010-09-24 11:53:17,078-INFO -[main]: Count: 2 Pseudo clock current time: 9360

2010-09-24 11:53:17,080-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,080-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,080-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=13361, value=24.0]

2010-09-24 11:53:17,080-INFO -[main]: Count: 3 Pseudo clock current time: 13361

2010-09-24 11:53:17,081-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,082-INFO -[main]: EVENT MESSAGE: Clearing alarm as SessionRe

questDelayMilliSecs went below threshold 25.0 for probe threstest1

2010-09-24 11:53:17,082-INFO -[main]: EVENT MESSAGE: WARN: clearing again, alarm

doesnt exist for Srd metric with probename threstest1

2010-09-24 11:53:17,082-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,083-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=17362, value=23.0]

2010-09-24 11:53:17,083-INFO -[main]: Count: 4 Pseudo clock current time: 17362

2010-09-24 11:53:17,083-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,083-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,083-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=21363, value=24.0]

2010-09-24 11:53:17,084-INFO -[main]: Count: 5 Pseudo clock current time: 21363

2010-09-24 11:53:17,084-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,084-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,084-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=25364, value=28.0]

2010-09-24 11:53:17,085-INFO -[main]: Count: 6 Pseudo clock current time: 25364

2010-09-24 11:53:17,085-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,085-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,085-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=29365, value=21.0]

2010-09-24 11:53:17,086-INFO -[main]: Count: 7 Pseudo clock current time: 29365

2010-09-24 11:53:17,086-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,086-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,087-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=33366, value=27.0]

2010-09-24 11:53:17,087-INFO -[main]: Count: 8 Pseudo clock current time: 33366

2010-09-24 11:53:17,087-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,088-INFO -[main]: Pseudo clock advanced 4001ms

2010-09-24 11:53:17,088-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=37367, value=67.0]

2010-09-24 11:53:17,088-INFO -[main]: Count: 9 Pseudo clock current time: 37367

2010-09-24 11:53:17,088-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,089-INFO -[main]: Pseudo clock advanced 4000ms

2010-09-24 11:53:17,089-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=41367, value=89.0]

2010-09-24 11:53:17,089-INFO -[main]: Count: 10 Pseudo clock current time: 41367

2010-09-24 11:53:17,090-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,090-INFO -[main]: EVENT MESSAGE: Raised alarm as SessionRequ

estDelayMilliSecs hit threshold 50.0 for probe threstest1

2010-09-24 11:53:17,090-INFO -[main]: EVENT MESSAGE: Raised alarm as SessionRequ

estDelayMilliSecs hit threshold 50.0 for probe threstest1

2010-09-24 11:53:17,091-INFO -[main]: Pseudo clock advanced 4000ms

2010-09-24 11:53:17,091-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=45367, value=92.0]

2010-09-24 11:53:17,091-INFO -[main]: Count: 11 Pseudo clock current time: 45367

2010-09-24 11:53:17,092-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,092-INFO -[main]: Pseudo clock advanced 4000ms

2010-09-24 11:53:17,092-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=49367, value=72.0]

2010-09-24 11:53:17,092-INFO -[main]: Count: 12 Pseudo clock current time: 49367

2010-09-24 11:53:17,093-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,093-INFO -[main]: Pseudo clock advanced 4000ms

2010-09-24 11:53:17,093-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=53367, value=65.0]

2010-09-24 11:53:17,093-INFO -[main]: Count: 13 Pseudo clock current time: 53367

2010-09-24 11:53:17,094-INFO -[main]: calling drools fire rules

2010-09-24 11:53:17,094-INFO -[main]: Pseudo clock advanced 4000ms

2010-09-24 11:53:17,094-INFO -[main]: Inserted event Srd [probeName=threstest1,

destIp=10.155.21.81, srcIp=10.155.21.82, timestamp=57367, value=99.0]

2010-09-24 11:53:17,094-INFO -[main]: Count: 14 Pseudo clock current time: 57367

2010-09-24 11:53:17,095-INFO -[main]: calling drools fire rules