Triggering rule with event state

Setup, Configuration and Use Scripts & Rules
1

I want to implement an alarm notification and send an E-Mail and a WhatsApp when an event is triggered (ON) as well when it ends (OFF). I have various alarm sources and don’t want to have a rule for every object. So I defined a group gAlarm, which includes all items triggering an alarm.

In general it works, but when the rule is triggered (which could take a noticeable delay for whatever reason) I got only the current state of the item, which leads into the situation that the rule was triggered for the ON event (?), but when executed the item state is already OFF so I could not find reliable the item, which triggered the rule (the sensor triggering the alarm).

How to get the item and item state, which triggered the rule?

Current implementation:

val String houseId    = "Home"
val String mailTo     = "xxx"
val String mailFooter = "\n\nContact:\nxxxx\n"
val String smsNumber  = "+49170XXXXXXX"

val Functions$Function5<String, String, String, String, String, Boolean> reportAlarm = [
	String houseId,
	String mailTo,
	String alarm_text,
	String alarm_info,
	String mailFooter|	
		logInfo ("Alarm", alarm_text+": "+alarm_info)
		var String body = alarm_info + mailFooter
		sendMail(mailTo, houseId+": "+alarm_text, body)
		WhatsAppMessage_Out.sendCommand(smsNumber + ":" + alarm_text)
		true
	]

rule "Alarm detected"
when
	Member of gAlarm changed
then
	var message = "An event was triggered: " + triggeringItem.name + ", state=" + triggeringItem.state
	logInfo("Alarm", message)

	if (triggeringItem.state  == ON) {
		message = message + "\n\nAlarm status (all):\n"
		gAlarm?.allMembers.forEach[sw|
			message = message + sw.name + ": " + sw.state.toString + "\n"
			alarm = true;
		]

	reportAlarm.apply(houseId, mailTo, "Alarm "+triggeringItem.name+" triggered!", message, mailFooter)		
	}
end

The Things als items where defined in PaperUI, the item assigned to the group gAlarm.

openhab.log:

2019-01-14 10:19:25.397 [INFO ] [eclipse.smarthome.model.script.Alarm] - Alarm Alarm_LaundryRoom_Flood triggered!: An event was triggered: Alarm_LaundryRoom_Flood, current state=OFF

Alarm status (all):
COSensorKeller_AlarmGeneral: NULL
Smoke_FlurUG_Heat: OFF
COSensorJonietz_AlarmCO: NULL
Smoke_Kueche_Alarm: OFF
Alarm_LaundryRoom_Flood: OFF
Smoke_Keller_Smoke: OFF
Smoke_FlurUG_Alarm: NULL
Smoke_JanN_Heat: OFF
Smoke_FlurOG_Alarm: OFF
COSensorKeller_Alarm: NULL
Smoke_JanN_Smoke: OFF
COSensorJonietz_AlarmGeneral: NULL
Smoke_Kueche_Heat: OFF
Smoke_Keller_Heat: OFF
Alarm_FloordSensorLaundryRoom_Burglar: OFF
Smoke_FlurOG_Heat: OFF
COSensorJonietz_AlarmBurglar: OFF
Alarm_FloodaundryRoom: NULL
COSensorKeller_Sensor: OFF
Smoke_JanN_Alarm: OFF
COSensorJonietz_Sensor: OFF
Smoke_FlurUG_Smoke: NULL
COSensorJonietz_AlarmSystem: NULL
Smoke_Keller_Alarm: OFF
Alarm_FloodSensorLaundryRoom_General: OFF
Siren_1: OFF
Smoke_FlurOG_Smoke: OFF
  • Platform information:
    • Hardware: Raspberry Pi 3
    • OS: Raspbian 2.4
    • openHAB Version: 2.4 stable
  • Issue of the topic: Rule triggered with “old” state
  • Please post configurations (if applicable):
2

At first I thought the log makes no sense, as the first line of var message states that the state of the triggering item = OFF, and the rest of the code only is executed when the state == ON.
So that got me confused… (And still does)

But primarily I would at the cause of the long delay that you mention. Do you have a typical example of a rule that changes one of the members of gAlarm?

3 
when
    Member of gAlarm changed to ON

When the rule triggers, you will know it was because somethng’s state changed to ON. You will know which something because it is in triggeringItem.

4 
when
	Member of gAlarm changed

I want to know when the alarm was fired (ON) and when the condition was solved (OFF)

It seems that the trigger gets queued, but not with the item state at this time. So when the rue is fired you get the current state, which might be reset already OFF, because the condition is clear.

I want to catch both conditions, so triggering the rule when the Item changes to ON (process the alarm, send message) and condition is clear (OFF, just log the status). And in fact we are talking about a design question, which means that you are never get the state associated with the rule trigger.

While writing this response I remember previousItemState
So may I could do
if ((Item.state == ON) || (Item.State == OFF && (Item.previousState.state == ON))
but this would also depend on timing

  • There are defiantly inconsistencies in the timing when rules get triggered. I see the same with other rules, e.g. controlling my multimedia equipment. Sometimes it takes 15s between the log message “Item xxx changed”, but the rule triggers 5-15s later. I saw this issue already in 2.3 (up to 10s) and it got even worth with 2.4 (up to 15s) - could be specific to my installation. I saw also other posts mentioning that effect.
  • All items, which could triggered an alarm and part of gAlarm. So the device fires the alarm itself, which is member of gAlarm and the group-related rule above will be fired.
5

Sure. I didn’t spell out that you would also have a rule triggering from changed to OFF

Yes. This is a workaround if you like, you do know what the trigger was.

6

Just as some general comments and to narrow down the issue a bit, it might be worth to add the following rules:

rule "Alarm detected 2"
when
	Member of gAlarm received update
then
	var message = "An a member of gAlarm received an update: " + triggeringItem.name + ", state=" + triggeringItem.state
	logInfo("Alarm", message)
end

rule "Alarm detected 3"
when
	Member of gAlarm received command
then
	var message = "An a member of gAlarm received a command: " + triggeringItem.name + ", state=" + receivedCommand
	logInfo("Alarm", message)
end

I think it might be really usefull to monitor what happens in terms of timing, so which rule gets triggered first and, in terms of the state of the triggering item over time.

7

good next setp

I changed/added the following rules:

rule "Alarm detected"
when
	Member of gAlarm changed
then
	var message = "An event was triggered: " + triggeringItem.name + ", current state=" + triggeringItem.state + " - check for alarm report"
	logInfo("Alarm", message)

	if (triggeringItem.state  == ON) {
		message = message + "\n\nAlarm status (all):\n"

		gAlarm?.allMembers.forEach[sw|
			message = message + sw.name + ": " + sw.state.toString + "\n"
			alarm = true;
		]

	reportAlarm.apply(houseId, mailTo, "Alarm "+triggeringItem.name+" triggered!", message, mailFooter)		
	}
end

rule "Alarm detected receivedON"
when
	Member of gAlarm changed to ON
then
	logInfo("Alarm", "A member of gAlarm received ON: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

rule "Alarm detected receivedOFF"
when
	Member of gAlarm changed to OFF
then
	logInfo("Alarm", "A member of gAlarm received OFF: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

rule "Alarm detected receivedON_OFF"
when
	Member of gAlarm changed from ON to OFF
then
	logInfo("Alarm", "A member of gAlarm changed from ON to OFF: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

rule "Alarm detected receivedOFF_ON"
when
	Member of gAlarm changed from OFF to ON
then
	logInfo("Alarm", "A member of gAlarm changed from OFF to ON: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

rule "Alarm detected receivedUpdate"
when
	Member of gAlarm received update
then
	logInfo("Alarm", "A member of gAlarm received an update: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

rule "Alarm detected receivedCommand"
when
	Member of gAlarm received command
then
	logInfo("Alarm", "A member of gAlarm received a command: " + triggeringItem.name + ", state=" + triggeringItem.state)
end

Example showing the delay between the alarm and rule trigger:

==> /usr/share/openhab2/log/events.log <==
2019-01-14 18:14:24.833 [vent.ItemStateChangedEvent] - Alarm_LaundryRoom_Tamper changed from NULL to ON
2019-01-14 18:14:34.283 [vent.ItemStateChangedEvent] - VPN_TPH_RTIME changed from 162.0 to 150.0
2019-01-14 18:14:34.297 [vent.ItemStateChangedEvent] - network_pingdevice_tph_oh_lastseen changed from 2019-01-14T18:13:34.088+0100 to 2019-01-14T18:14:34.255+0100

==> /usr/share/openhab2/log/openhab.log <==
2019-01-14 18:14:45.437 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:14:45.442 [INFO ] [lipse.smarthome.model.script.Holiday] - Check for public holiday
2019-01-14 18:14:45.485 [INFO ] [lipse.smarthome.model.script.DayTime] - nNow=1814,nSunset=0,nSunrise=0isNight=false,isWeekend=false
2019-01-14 18:14:45.487 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Update sunrise and sunset': Unparseable date: "2019-1-14 NULL"
2019-01-14 18:14:45.487 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received ON: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:14:45.505 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:14:45.509 [INFO ] [eclipse.smarthome.model.script.Alarm] - An event was triggered: Alarm_LaundryRoom_Tamper, current state=ON - check for alarm report

==> /usr/share/openhab2/log/events.log <==
2019-01-14 18:14:49.222 [vent.ItemStateChangedEvent] - Alarm_LaundryRoom_Tamper changed from ON to OFF

==> /usr/share/openhab2/log/openhab.log <==
2019-01-14 18:14:54.427 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm changed from ON to OFF: Alarm_LaundryRoom_Tamper, state=OFF
2019-01-14 18:14:54.427 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=OFF
2019-01-14 18:14:54.429 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Alarm detected': Couldn't invoke 'assignValueTo' for feature JvmVoid:  (eProxyURI: zwave.rules#|::0.2.0.2.0.2.1.0.1.7.0.1.0.1::0::/1)
2019-01-14 18:14:54.446 [INFO ] [eclipse.smarthome.model.script.Alarm] - An event was triggered: Alarm_LaundryRoom_Tamper, current state=OFF - check for alarm report
2019-01-14 18:14:54.452 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received OFF: Alarm_LaundryRoom_Tamper, state=OFF
2019-01-14 18:14:54.461 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=OFF
  • Alarm was triggered (ON): 2019-01-14 18:14:24.833
  • The first rule executes at 2019-01-14 18:14:45.437 = 21sec delay!
  • There are other events in between, so OH can’t be blocked in general
  • OFF at 2019-01-14 18:14:49.222, first execution at 2019-01-14 18:14:54.427 = 5sec delay

Another examples shows the exact difference:

2019-01-14 18:21:39.611 [vent.ItemStateChangedEvent] - Alarm_LaundryRoom_Tamper changed from OFF to ON

==> /usr/share/openhab2/log/openhab.log <==
2019-01-14 18:21:39.648 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:21:39.652 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received ON: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:21:39.659 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm changed from OFF to ON: Alarm_LaundryRoom_Tamper, state=ON
2019-01-14 18:21:39.675 [INFO ] [eclipse.smarthome.model.script.Alarm] - An event was triggered: Alarm_LaundryRoom_Tamper, current state=ON - check for alarm report
2019-01-14 18:21:39.686 [INFO ] [eclipse.smarthome.model.script.Alarm] - A member of gAlarm received an update: Alarm_LaundryRoom_Tamper, state=ON
  • ON at 2019-01-14 18:21:39.611, rule execution at 2019-01-14 18:21:39.648 - delay of 37ms vs. 5/21sec!
  • same rules, same setup

I couldn’t catch the situiation I had this afternoon where the state was already back to OFF when the “changed rule” was triggered.

So I have 2 issues

  • why are there delays between 37ms and 21sec?
  • how to handle safely the asynchronous execution of the trigger and rule execution so I know that there was a change to ON even the current state was already reset (OFF)
8

Have a look at (OH 1.x and OH 2.x Rules DSL only] Why have my Rules stopped running? Why Thread::sleep is a bad idea to see if any of that applies. I suspect that you have some long running rules that are using up all your Rules runtime threads which will block the execution of all other Rules until they complete.

Honestly, don’t even bother with this until you solve the problem with the delay in your Rules executing. Until you fix this problem anything else you do will be IMHO wasted effort as it is just trying to work around a problem. Better to actually solve the root problem first.

But, as rossko57 indicates, if you trigger the Rule by Member of gAlarm changed to ON then you know that when the Rule executes that triggeringItem changed to ON to trigger the Rule. A corresponding Member of gAlarm changed to OFF Rule will tell you that when the Rule triggered triggeringItem changed to OFF.

But because of the problem with the delay in execution of the Rule, you cannot guarantee that the ON Rule runs before the OFF Rule does. This is why you need to solve the root problem first.

9

The first given example of poor response time around 18:14, the 21 secs incident, appears to happen during a system boot period? (There is mention of “startup rule”) Or perhaps having just saved an edited rules file?
Either way, it’s not a fair measurement - the system is expected to be busy.

Please try to catch a case of delay during “normal running”?

Log does provide a useful reminder - a “return to normal” event should really be triggered changed from ON to OFF - guessing you would not usually want to report UNDEF/NULL -> OFF transitions from zwave

10

I have nomaleepsmin a rule, no long running ones etc - at least what I‘m aware of. can‘t say if this is caused by a binding.

The examples were not captured at startup. The system was more or less idle (e.g. only 2 orher log messages at that time)

If now added an ON->OFF and a OFF->ON, but it‘s not guaranteed that they get processed in the right order nor that triggeredItem.state shows the state, which triggered the event.

I need to look for the blocking condition even I have no clue were to statt

11

What’s a “normal sleep”? Any sleep at all should be used rarely and with caution. There is no such thing as a “normal sleep”. Any sleep is abnormal.

12

maybe executeCommandLine is a candidate to check

13

Absolutely. As is sendHttp*Request.

14

Just be aware that neither will trigger for an UNDEF → ON transition. That may or may not be what you want.

That’s true enough. I believe the OH event bus is good at keeping things in order, but if you have rules getting blocked there is no guarantee which lines might get executed where next.

You already know exactly what the state was at the trigger time, you specified it in the trigger. And you have triggeringItem.state, so you have both “now” and “then”. It’s up to you which you use.

What are those errors in the log samples about? Error conditions can cause delay.

15

I still have the delayed rule execution

  • I have no Thread::sleep() (checked with grep)
  • I put all executeCommandLines in createTimer()
  • I don’t use sendHttpGetRequest so far (checked with grep)
  • no while loop at all

What’s about rules with a Cron expression?

I applied the mentioned “Aspiriin” and increased number of threads to 5 - lets see

16

For me they typically run within 50 ms after the actual Cron time, and no problems with respect to delays whatsoever.

Another idea, quite a bit cumbersome though:
In each rule, add a log command at the first line of the then part, stating something like “Rule … started” and at the last line, just before end, add a log command stating something like “Rule… ended”. In that way you can check if you have any rules that either take very long or take forever to complete and in that way fill up the limited number of rules running simultaneously.