Order of sent events via triggerChannel received in rules engine

I’m experimenting with the triggerChannel concept and I’ve implemented several different trigger channels for different things and I’ve seen a strange behaviour for the order of the sent events when I trigger them in rules.

I’ve got a separate rule per trigger channel that just does an info print when the rule has been triggered.

The order in which each thing handler called the triggerChannel(channel, event) method was:

2020-06-01 21:57:27.368 [DEBUG] [nternal.handler.VerisureThingHandler] - SmartLockThingHandler trigger event UNLOCK
2020-06-01 21:57:27.373 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041133 Last Event time: 1591038674
2020-06-01 21:57:27.375 [DEBUG] [nternal.handler.VerisureThingHandler] - Trigger event DOORWINDOW_STATE_CHANGE_OPENED on thing 
2020-06-01 21:57:27.376 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-01 21:57:27.381 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041155 Last Event time: 1591038674
2020-06-01 21:57:27.383 [DEBUG] [nternal.handler.VerisureThingHandler] - Trigger event DOORWINDOW_STATE_CHANGE_CLOSED on thing 
2020-06-01 21:57:27.385 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-01 21:57:27.390 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041156 Last Event time: 1591038674
2020-06-01 21:57:27.392 [DEBUG] [nternal.handler.VerisureThingHandler] - Trigger event DOORWINDOW_STATE_CHANGE_CLOSED on thing 
2020-06-01 21:57:27.395 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-01 21:57:27.399 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041156 Last Event time: 1591038674
2020-06-01 21:57:27.401 [DEBUG] [nternal.handler.VerisureThingHandler] - Trigger event DOORWINDOW_STATE_CHANGE_OPENED on thing 
2020-06-01 21:57:27.402 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-01 21:57:27.408 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041158 Last Event time: 1591038674
2020-06-01 21:57:27.411 [DEBUG] [nternal.handler.VerisureThingHandler] - Trigger event LM on thing 
2020-06-01 21:57:27.412 [DEBUG] [nternal.handler.VerisureThingHandler] - SmartLockThingHandler trigger event LOCK
2020-06-01 21:57:27.418 [DEBUG] [nternal.handler.VerisureThingHandler] - Event time: 1591041366 Last Event time: 1591038674

But the order they were printed in my rules.log file was:

2020-06-01 21:57:29.606 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-01 21:57:29.612 [INFO ] [eclipse.smarthome.model.script.RULES] - A SmartLock trigger event was detected:verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered LOCK
2020-06-01 21:57:29.616 [INFO ] [eclipse.smarthome.model.script.RULES] - A SmartLock trigger event was detected:verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered UNLOCK

So order sent:

  • SmartLockThingHandler - UNLOCK
  • DoorWindowThingHandler - DOORWINDOW_STATE_CHANGE_OPENED
  • DoorWindowThingHandler - DOORWINDOW_STATE_CHANGE_CLOSED
  • DoorWindowThingHandler - DOORWINDOW_STATE_CHANGE_CLOSED
  • DoorWindowThingHandler - DOORWINDOW_STATE_CHANGE_OPENED
  • SmartLockThingHandler - LOCK

Order received in rule engine:

  • DOORWINDOW_STATE_CHANGE_CLOSED
  • LOCK
  • UNLOCK

So 3 events for DoorWindowThingHandler were lost and the order for SmartLockThingHandler was reversed. What can explain that behaviour?

I’m running on OH Core 2.5.0 and add-ons 2.5.3.

The Event Bus is asychronous. It is also not built to be used real-time, but you are sending events within milliseconds of each other. How many times did you repeat your test and we’re the results consistent?

I have not repeated them, but I can do that later today.

Since I poll the API every 10 minutes I can get quite many events between polls that I then use for the triggerChannel(channel, event) method call.

Since the order of the events is important for the user who wants to proper take action on them, is there some other way of guaranteeing received order using triggerChannel method call and having 10-15 events to send for each API poll?

Can we see a sample rule you used to detect this?
Can we see the events.log version of events?

There is something of a fine art in handling very rapidfire events in openHAB rules. It’s not hard to see the potential for problems if events come quicker than the rules acting on them can execute. Bottom line, it’s not very good at it, don’t get into that situation if you can help it.

What’s going on here, remote reading a events history and blurting everything out at once?

Sure, I will fix that later today.

Sample rules:

rule "Verisure SmartLock Event Triggers"
when
    Channel "verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel" triggered
then
    logInfo("RULES", "A SmartLock trigger event was detected:" + receivedEvent.toString())
end

rule "Verisure DoorWindow Event Triggers"
when
    Channel "verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel" triggered
then
    logInfo("RULES", "A DoorWindow trigger event was detected:" + receivedEvent.toString())
end

verisure.log:

2020-06-02 19:20:41.806 [DEBUG] [nternal.handler.VerisureThingHandler] - SmartLockThingHandler trigger event LOCK
2020-06-02 19:20:41.825 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-02 19:20:41.830 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-02 19:20:41.846 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-02 19:20:41.852 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-02 19:20:41.872 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-02 19:20:41.878 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-02 19:20:41.883 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_CLOSED
2020-06-02 19:20:41.912 [DEBUG] [nternal.handler.VerisureThingHandler] - DoorWindowThingHandler trigger event DOORWINDOW_OPENED
2020-06-02 19:20:41.918 [DEBUG] [nternal.handler.VerisureThingHandler] - SmartLockThingHandler trigger event UNLOCK

event.log:

2020-06-02 19:20:41.817 [vent.ChannelTriggeredEvent] - verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered LOCK
2020-06-02 19:20:41.836 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.840 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.849 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.869 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.885 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.888 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.910 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.915 [vent.ChannelTriggeredEvent] - verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.938 [vent.ChannelTriggeredEvent] - verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered UNLOCK

rules.log:

2020-06-02 19:20:41.841 [INFO ] [eclipse.smarthome.model.script.RULES] - A SmartLock trigger event was detected:verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered LOCK
2020-06-02 19:20:41.886 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.888 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.905 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.907 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.914 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.922 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.934 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_OPENED
2020-06-02 19:20:41.940 [INFO ] [eclipse.smarthome.model.script.RULES] - A DoorWindow trigger event was detected:verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered DOORWINDOW_CLOSED
2020-06-02 19:20:41.959 [INFO ] [eclipse.smarthome.model.script.RULES] - A SmartLock trigger event was detected:verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered UNLOCK

In this case the rule engine swapped events for DOORWINDOW_OPENED/DOORWINDOW_CLOSED but the LOCK/UNLOCK came in correct order.

What I’ve seen so far is the order sent in the versure.log always consistent with the event.log, but the rules.log file contains events in wrong order, so it must be something with the rule engine that causes this.

What’s going on here, remote reading a events history and blurting everything out at once?

The binding polls an API every 10 minutes, all new events since last poll will then be sent on triggerChannels. So the number of events will differ, but between 5-15 at certain API polls is not so uncommon depending on what you trigger in your house :slight_smile:

To rephrase, the rule engine probably started multiple instances of the same rule, and there are no guarantees about how fairly they share resources. Second to start may finish first, including any logging along the way.

Even if they introduce reentrant locks to try and serialize things, your shotgun approach is going to give users trouble. Consider throttling your events generation.

Since the data is already up to 10 minutes old, just add a small delay between them to let the bus respond in the correct order. The delay should probably be configurable in the binding, since slower machines may need more delay. Although, it could work the other way and you might find the rules trigger in order in a slower machine.

Hwever, it would be interesting to see if the new rule engine performs any better than the old one, which will be removed in OH 3.0. The new rule engine processes triggers of the ame rule sequentially, so I expect everything will work as expected when using it. If you set this up…

… here are your DSL rules migrated to Jython and the helper libraries…

from core.rules import rule
from core.triggers import when

@rule("Verisure SmartLock Event Triggers")
@when("Channel verisure:smartLock:f1191aab:2B55ABBA:smartLockTriggerChannel triggered")
def smartlock_events(event):
    smartlock_events.log.info("A SmartLock trigger event was detected: {}".format(event.event))

@rule("Verisure DoorWindow Event Triggers")
@when("Channel verisure:doorWindowSensor:f1191aab:2BEGABBA:doorWindowTriggerChannel triggered")
def doorwindow_events(event):
    doorwindow_events.log.info("A DoorWindow trigger event was detected: {}".format(event.event))

just add a small delay between them to let the bus respond in the correct order.

What is the best way om implementing the delay? I guess that a Thread.sleep(500) is not a preferred way of doing it?

Hwever, it would be interesting to see if the new rule engine performs any better than the old one, which will be removed in OH 3.0.

If I configure the new rule engine, can I then run both engines in parellell or do I need to change all my rules to python?

An addon maintainer would be the best person to ask, but Thread.sleep looks like the right way to go. Search the openhab-addons repo to see others have implemented this. Again though, I do not think you will need it in OH 3.0.

Yes, you can run both simultaneously.

Once you see it in action, you will WANT to migrate your rules!

Once you see it in action, you will WANT to migrate your rules!

:slight_smile: I’ll give it a try during the week-end!

1 Like

Comment; careful about designing add-on with behaviour that say, one rule engine allows it to get away with, but some other service might not e.g. persistence.
Examples; persistence services can work on time slices. Events arriving in same slice will get compressed into one i.e. you won’t persist all your events.
Examples; even with rule queuing, a sequence A-B-B-B-A where you may have different rules to process A and B type events, the last A will be processed before the last B.

@jannegpriv , a blast of very rapid events in openHAB is just going to give surprises and unintended consequences. If these are some kind of mirror of remote events over time anyway, there’s no need to do it that way.
If the order and separate integrity of events is important to your users, pass the events out at a manageable rate.

A simple way is to load them into a queue, and a time-ticker plods through taking each one off the queue until exhausted.
You should find other bindings with this kind of queue mechanism, though it is more usually used for outbound data to avoid flooding networks e.g. zwave