[SOLVED] Prevent openhab from triggering rule multiple times

Maurice · January 7, 2019, 7:11pm

Platform information:
- Hardware: raspberry pi 3b+
- OS: openhabian
- openHAB version: 2.4

I am trying to create a presence detection in openhab. Therefore I created a group which detects if my wife or I am at home. We both have multiple devices and I only want to trigger gPresence if no device is left home. Thats why there are 2 further groups.

Group:Switch:OR(ON,OFF)   gPresence     "gPresence" <icon_presence>
Group:Switch:OR(ON,OFF)   gPresenceLinda     "gPresenceLinda" <icon_presence> (gPresence)
Group:Switch:OR(ON,OFF)   gPresenceMaurice     "gPresenceMaurice" <icon_presence> (gPresence)

rule "Thermostat presence"
when
    Item gPresence changed
then
    logInfo("presence", "gPresence.state == " + gPresence.state.toString)
    if (gPresence.state == ON) {
        logInfo("presence", "Welcome home")
        sendTelegram("jenkins", "Welcome back home.")
        gThermostatMode.sendCommand("AUTO-MODE")
    } else {
        logInfo("presence", "Everyone's gone. Set temperature to 18°C")
        sendTelegram("jenkins", "Everyone is gone. I'll take care.")
        gThermostatMode.sendCommand("AWAY-MODE")
    }
end

When gPresence switches to OFF the rule is triggered multiple times. When it switches to ON it just fires one time.

2019-01-07 19:57:04.311 [INFO ] [ipse.smarthome.model.script.presence] - gPresence.state == OFF

2019-01-07 19:57:04.311 [INFO ] [ipse.smarthome.model.script.presence] - gPresence.state == OFF

2019-01-07 19:57:04.311 [INFO ] [ipse.smarthome.model.script.presence] - gPresence.state == OFF

2019-01-07 19:57:04.318 [INFO ] [ipse.smarthome.model.script.presence] - Everyone’s gone. Set temperature to 18°C

2019-01-07 19:57:04.318 [INFO ] [ipse.smarthome.model.script.presence] - Everyone’s gone. Set temperature to 18°C

2019-01-07 19:57:04.320 [INFO ] [ipse.smarthome.model.script.presence] - Everyone’s gone. Set temperature to 18°C

Beside this my heater sometime fallback into an unpredicted state and I guess its because my rule fires multiple times and there is a race condition somewhere.

Is there anything I can do about this?

rossko57 · January 7, 2019, 8:33pm

This is the nature of Group aggregation. When one of its member Items changes, the Group iterates over its members and recalculates its state. This can result in multiple updates of Group state as it steps through one at a time.

You could preserve your Group setup and delay the guts of your rule by putting it in a Timer to run after the Group has settled down.

// define at top of file
var Timer changeTimer = null

rule "Thermostat presence"
when
    Item gPresence changed
then
    logInfo("presence", "triggered")
    if (changeTimer == null) {
         changeTimer  createTimer(now.plusSeconds(1), [ |
             logInfo("presence", "stable gPresence.state == " + gPresence.state.toString)
             if (gPresence.state == ON) {
                     logInfo("presence", "Welcome home")
                     sendTelegram("jenkins", "Welcome back home.")
                     gThermostatMode.sendCommand("AUTO-MODE")
              } else {
                     logInfo("presence", "Everyone's gone. Set temperature to 18°C")
                     sendTelegram("jenkins", "Everyone is gone. I'll take care.")
                     gThermostatMode.sendCommand("AWAY-MODE")
              }
              changeTimer = null // clear for another time
         ] )
   }  // else timer already running and we ignore trigger 
end

Maurice · January 7, 2019, 9:45pm

thanks for your reply.
But it still fails.

//edit I think there was an “=” missing. Added it but it still fails

log:

2019-01-07 22:47:42.195 [INFO ] [ipse.smarthome.model.script.presence] - triggered

2019-01-07 22:47:42.195 [INFO ] [ipse.smarthome.model.script.presence] - triggered

2019-01-07 22:47:42.195 [INFO ] [ipse.smarthome.model.script.presence] - triggered

2019-01-07 22:47:42.209 [ERROR] [model.script.actions.ScriptExecution] - Failed to schedule code for execution.

org.quartz.ObjectAlreadyExistsException: Unable to store Job : 'DEFAULT.2019-01-07T22:47:43.201+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {

logInfo(,)

org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1108998

.changeTimer =

} ]', because one already exists with this identification.

at org.quartz.simpl.RAMJobStore.storeJob(RAMJobStore.java:279) ~[?:?]

at org.quartz.simpl.RAMJobStore.storeJobAndTrigger(RAMJobStore.java:251) ~[?:?]

at org.quartz.core.QuartzScheduler.scheduleJob(QuartzScheduler.java:886) ~[?:?]

at org.quartz.impl.StdScheduler.scheduleJob(StdScheduler.java:249) ~[?:?]

at org.eclipse.smarthome.model.script.actions.ScriptExecution.makeTimer(ScriptExecution.java:132) ~[?:?]

at org.eclipse.smarthome.model.script.actions.ScriptExecution.createTimer(ScriptExecution.java:92) ~[?:?]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1086) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1061) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1047) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:865) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:224) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:1212) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:216) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:460) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:244) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]

at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]

at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]

at org.eclipse.smarthome.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:82) ~[?:?]

at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.lambda$2(RuleEngineImpl.java:341) ~[?:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]

at java.lang.Thread.run(Thread.java:748) [?:?]

2019-01-07 22:47:43.209 [INFO ] [ipse.smarthome.model.script.presence] - stable gPresence.state == OFF

2019-01-07 22:47:43.217 [INFO ] [ipse.smarthome.model.script.presence] - Everyone’s gone. Set temperature to 18°C

2019-01-07 22:47:43.217 [INFO ] [ipse.smarthome.model.script.presence] - stable gPresence.state == OFF

2019-01-07 22:47:43.230 [INFO ] [ipse.smarthome.model.script.presence] - Everyone’s gone. Set temperature to 18°C

I wonder why it triggers multiple times nevertheless.
when Item gPresence changed. This should only trigger if the state changes. 3x OFF should trigger only once.
Otherwise I would use command received or something like that.

Is this kind of behavior seen as correct or is it a bug?

rossko57 · January 7, 2019, 10:41pm

Indeed I missed two =, null being a funny comparison

if (changeTimer === null) {
     changeTimer  = createTimer(now.plusSeconds(1), [ |

“it” the rule? As before, when a Group member gets an update, the Group recalculates and updates at each step… So if a member of gPresenceLinda updates, gPresenceLinda will update N times. As gPresenceLinda is a member of gPresence … gPresence will update N times plus more times as it checks its other members as well (gPresenceMaurice in this case).

Looking at my rule again, there’s still a race condition where multiple copies of rules fired in quick succession could pass the changeTimer===null comparison before the front runner populates changeTimer. Need some other method.

I think we can exploit Member of triggers here, this should be ‘singular’ for the sub-group members

rule "Thermostat presence"
when
    Member of gPresenceLinda changed or
    Member of gPresenceMaurice changed
then
    Thread::sleep(200)   // let the Groups settle down
    logInfo("presence", "gPresence.state == " + gPresence.state.toString)
    if (gPresence.state == ON) {
        logInfo("presence", "Welcome home")
        sendTelegram("jenkins", "Welcome back home.")
        gThermostatMode.sendCommand("AUTO-MODE")
    } else {
        logInfo("presence", "Everyone's gone. Set temperature to 18°C")
        sendTelegram("jenkins", "Everyone is gone. I'll take care.")
        gThermostatMode.sendCommand("AWAY-MODE")
    }
end

Maurice · January 7, 2019, 11:09pm

I get you. My problem is with the definition of Item xxx changed.
The rule get triggered even though the value hasn’t changed. My guess is that there are multiple threads invoked and the value is updated later on. Otherwise I don’t know what happens here.
If so, I would consider this as a bug. This should be an atomic operation.

Nvm. The solution with Member of doesn’t work as well. Crap. I tought it would be a simple solution. I am fighting with this for a few weeks now. Debugging is kinda hell.

//edit

Funny thing I noticed. This only happens if the state sets to OFF.
If gPresence get set to ON the rule get triggered only once.

I appreciate your help

rossko57 · January 7, 2019, 11:47pm

It’s been this way since OH 0.1 I think. That doesn’t mean it’s right, but you’d need to make a case for enhancement

I believe that’s a consequence of the OR aggregate function. Other functions probably behave differently.

It should act once per change, presuming only one of your bottom-level Items changes at a time. Can you show us event.log for that as well as openhab.log? There may be more than meets the eye.

The rule has no throttling and would be expected to spit out messages for every change - that’s a different requirement

Maurice · January 7, 2019, 11:56pm

I should add that I toggled the gPresence group itself to test my code.
Thats why the order in the log is that way.

events.log

136836 2019-01-07 22:47:41.662 [ome.event.ItemCommandEvent] - Item 'gPresence' received command OFF
136837 2019-01-07 22:47:41.670 [ome.event.ItemCommandEvent] - Item 'gPresenceLinda' received command OFF
136838 2019-01-07 22:47:41.680 [ome.event.ItemCommandEvent] - Item 'gPresenceMaurice' received command OFF
136839 2019-01-07 22:47:41.706 [ome.event.ItemCommandEvent] - Item 'AndroidLinda_Online' received command OFF
136840 2019-01-07 22:47:41.763 [ome.event.ItemCommandEvent] - Item 'AndroidMaurice_Online' received command OFF
136841 2019-01-07 22:47:41.766 [ome.event.ItemCommandEvent] - Item 'IPhoneMaurice_Online' received command OFF
136842 2019-01-07 22:47:41.772 [nt.ItemStatePredictedEvent] - AndroidLinda_Online predicted to become OFF
136843 2019-01-07 22:47:41.778 [GroupItemStateChangedEvent] - gPresence changed from OFF to ON through gPresenceLinda
136844 2019-01-07 22:47:41.781 [nt.ItemStatePredictedEvent] - AndroidMaurice_Online predicted to become OFF
136845 2019-01-07 22:47:41.786 [nt.ItemStatePredictedEvent] - IPhoneMaurice_Online predicted to become OFF
136846 2019-01-07 22:47:41.792 [vent.ItemStateChangedEvent] - AndroidLinda_Online changed from ON to OFF
136847 2019-01-07 22:47:41.795 [vent.ItemStateChangedEvent] - AndroidMaurice_Online changed from ON to OFF
136848 2019-01-07 22:47:41.797 [vent.ItemStateChangedEvent] - IPhoneMaurice_Online changed from ON to OFF
136849 2019-01-07 22:47:42.007 [GroupItemStateChangedEvent] - gPresence changed from ON to OFF through gPresenceMaurice
136850 2019-01-07 22:47:43.540 [ome.event.ItemCommandEvent] - Item 'gThermostatMode' received command AWAY-MODE
136851 2019-01-07 22:47:43.545 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Thermostat_Mode' received command AWAY-MODE
136852 2019-01-07 22:47:43.548 [ome.event.ItemCommandEvent] - Item 'GF_Bathroom_Thermostat_Mode' received command AWAY-MODE
136853 2019-01-07 22:47:43.554 [ome.event.ItemCommandEvent] - Item 'GF_KidsRoom_Thermostat_Mode' received command AWAY-MODE
136854 2019-01-07 22:47:43.557 [ome.event.ItemCommandEvent] - Item 'FF_Bedroom_Thermostat_Mode' received command AWAY-MODE
136855 2019-01-07 22:47:43.566 [ome.event.ItemCommandEvent] - Item 'GF_Dining_Thermostat_Mode' received command AWAY-MODE
136856 2019-01-07 22:47:43.569 [ome.event.ItemCommandEvent] - Item 'GF_LivingRoom_Thermostat_1_Mode' received command AWAY-MODE
136857 2019-01-07 22:47:43.571 [ome.event.ItemCommandEvent] - Item 'GF_LivingRoom_Thermostat_2_Mode' received command AWAY-MODE
136858 2019-01-07 22:47:43.588 [ome.event.ItemCommandEvent] - Item 'gThermostatMode' received command AWAY-MODE

rossko57 · January 7, 2019, 11:59pm

Oh, you’re sending a command to the top level group. Naturally many underlying Items change to OFF and the rule runs many times. That’s expected behaviour.

What sends the command, could you tag the home/away analysis to that?

Maurice · January 8, 2019, 12:01am

Oh i’m just hitting the switch in the basic ui

       Frame label="Anwesenheit" icon="parents_2_2" {
           Switch item=gPresence icon="parents_2_2" label="Anwesend"
           Text label="Personen" icon="parents_2_2" {
               Switch item=gPresenceMaurice icon="man_2" label="Maurice"
               Switch item=gPresenceLinda icon="woman_2" label="Linda"
           }
       }

rossko57 · January 8, 2019, 12:03am

That’s a bad test. Results are as expected. I’d make the group sitemap type a Text so you can’t alter it - you want the state based on members, no?

Maybe make a dummy Switch item and add it to one of your groups for testing purposes. You can always comment it out of your sitemap later.

Maurice · January 8, 2019, 12:07am

Definitively. I just needed a quick way to test my rule. I didn’t knew that this will result in an arbitrary behavior.

If I test it by setting the member groups each, it seems to be working now. (Using your Member of hack)

But it doesnt fixed my strange heater bug But thats an other story.

I thank you for your help and kindness.

rossko57 · January 8, 2019, 11:42am

I’ll guess if you now have the rule triggering reliably, you might want to think about anti-flap methods. i.e. if someone dashes out to the car and back in a minute, what do you want to happen?

Perhaps if changing away->home, immediate action. Perhaps if home->away, wait for 5 mins and check if still away before action.

vzorglub · January 8, 2019, 11:49am

That’s what I wanted to say but I couldn’t find a way.
Thanks

rlkoshak · January 8, 2019, 5:11pm

Posing just because what you are trying to implement is very similar to Generic Presence Detection

krzyk · April 16, 2019, 9:54am

Looks like I have exactly the same problem here: Item update fires rule multiple times

I can’t find any bug report for that which is quite surprising.