Rule being triggered multiple times in a row per event

Hi all,

in my setup I have a motion sensor “FS20 PIRA” that should trigger a rule.

I created three rules, one using “Item Pir receive command”, another using “Item Pir receive update” and a third one with simple “Item Pir change” each with logInfo(…) to understand what happens.

The result is, that only “receive update” was triggered when the motion sensor fired an event, but it seems, that the rule is triggered multiple times in a row per single event and that the amount of these triggers is always increased by at least one message (not counted, but it seemed to).
The log always says, the items previousState was “OFF”, while the items “state” is “undefined” (or something similar).

  1. why is the rule being triggered so often in a row?
  2. how can I kind of “cleanup” the trigger message queue to decrease the amount of messages received to one per event?
  3. any idea why the rule “changed” is not triggered?

thanks in advance for any useful hints

cheers
Dirk

Would it be possible to see your item definition for the Pir item (and any other items you are triggering on), and the rules? You say one rule’s trigger is “Item Pir change” but it should be “Item Pir changed”, which out to trigger when the item’s state changes.

Hi Watou,

sorry there was a typo indeed.

My setup is for the item:

Switch PirGartentor "Bewegung Gartentor [%s]"	{ fs20="557A00" }

and the rule is

rule PIR1
when
	Item PirGartentor received command
then
	logInfo("RULES", "PIR received command: " + PirGartentor.state + " - " + PirGartentor.previousState) 
end

rule PIR2
when
	Item PirGartentor changed
then
	logInfo("RULES", "PIR changed: " + PirGartentor.state + " - " + PirGartentor.previousState) 
end

rule PIR3
when
	Item PirGartentor received update
then
	logInfo("RULES", "PIR received update: " + PirGartentor.state + " - " + PirGartentor.previousState) 
end

I doubt that the received update trigger is useful to you, because you are probably only interested in the item changing state to OFF or ON. So rule PIR2 is probably closest to what you are trying to do. You might want two separate rules, one triggered on Item PirGartentor changed to OFF and Item PirGartentor changed to ON, but that depends what you are trying to accomplish.

Also, rule PIR1 probably doesn’t make sense for a passive infrared sensor, since no one would be sending commands to it. But in any case, the rule PIR1 is logging the current and previous state of the item, but the rule is triggering on the item receiving a command, so that’s possibly causing confusion. Here is what you might mean:

rule PIR1
when
	Item PirGartentor received command
then
	logInfo("RULES", "PIR received command: " + receivedCommand) 
end

I see your point that the “received update” might not be the best solution as this will always be called, more often as only per status change. But I it seemed, that both other rules are not triggered at all, so if I cannot/should not use “received update”, what other option can I use?
The role with “Item … changed” might be the right one, but has not been called yet.

Thats the latest log output: only “received update” was triggered, 18 times in 2 seconds.

2015-09-02 20:40:25.548 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.781 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.799 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.819 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.836 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.858 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.871 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.896 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.905 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.964 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.987 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:25.996 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.012 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.029 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.044 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.061 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.075 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF
2015-09-02 20:40:26.091 [INFO ] [org.openhab.model.script.RULES] - PIR received update: Undefined - 02.09.2015 20:40:00: PirGartentor -> OFF

I will delete all rules related to that Item and create the rules you mentioned using “changed to OFF” and “changed from ON”.

That does look like strange behaviour from the binding. Perhaps temporarily remove all these rules and add the following line to your logback.xml file:

<logger name="org.openhab.binding.fs20" level="DEBUG"/>

The fs20 binding should send lots of debug information to the log which might shed light on why these strange-looking updates are happening.

This is the log output with DEBUG level for the FS20 binding: 36 lines in milliseconds.

2015-09-02 21:18:56.158 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.159 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.161 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.162 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.163 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.162 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.161 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.162 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.165 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.165 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.166 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.169 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.170 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.170 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.171 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.173 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.172 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.172 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.171 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.171 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.175 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.176 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.176 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.176 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.174 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.178 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.177 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.175 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.180 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received FS20 message: F557A003A6F03
2015-09-02 21:18:56.179 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.181 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.182 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.184 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.185 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.185 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00
2015-09-02 21:18:56.189 [DEBUG] [.o.b.fs20.internal.FS20Binding] - Received command UNKOWN for device 557A00

I doubt that is expected behaviour but I don’t know anything about the hardware. You should probably seek out other users of the binding to help explain what this log means and what to do. Maybe tag this topic with fs20 and/or start a new topic tagged for the binding and hopefully someone who uses it can chime in.

It may be that the item definition is lagging some more information.

I’m not familiar with FS20 but fiddled a bit with homematic. There you need to provide a bit more of insight about the type of the device you want to assign to the switch.
e.g. the definition for a reed contact in homematic looks like this:

Switch Garage “Garage [MAP(window.map):%s]” {homematic="address=LEQ1241665, channel=1, parameter=STATE"}

Maybe you want to go down the road and try and find out if similar information is required for FS20

Btw. do you have more FS20 hardware in use?

I have checked the binding wiki page as well as the source code and no other definition besides the house code seems to be expected or necessary.

That my set of hardware (among other, non FS20/FHT/CUL devices):
FS20 SU-3
FS20 S6A
FS20 S4A
FS20 AS4
FS20 PIRA, the motion sensors I mentioned above
FS20 KSE Funk-Klingelsignal-Erkennung
as well as several heating controls and window/door contacts FHT8V / FHT80TF-2

All devices are working well, except the motion sensors.