[rules-users] retract/insert in drl seems to not take effect, causing rules to fire twice.

Fri Sep 24 14:19:03 EDT 2010

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,

sb

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/rules-users/attachments/20100924/a56dd4ea/attachment.html 