Timing/race condition if mixing UI rules-actions with JSScripting?

Setup, Configuration and Use Scripts & Rules
1 
runtimeInfo:
  version: 3.2.0
  buildString: Release Build
locale: de-DE
systemInfo:
  configFolder: /etc/openhab
  userdataFolder: /var/lib/openhab
  logFolder: /var/log/openhab
  javaVersion: 11.0.13
  javaVendor: Azul Systems, Inc.
  javaVendorVersion: Zulu11.52+13-CA
  osName: Linux
  osVersion: 5.4.0-92-generic
  osArchitecture: i386
  availableProcessors: 2
  freeMemory: 264820136
  totalMemory: 536870912

I am transitioning from text-based config and Rules-DSL to mostly UI. I got a fairly simple rule for day/time management (based on Rich’s stuff):

grafik
grafik798Ă—399 38.8 KB

All it does it trigger on an Astro-event, set two items (and log this using JSScripting:

configuration: {}
triggers:
  - id: "1"
    configuration:
      thingUID: astro:sun:quellenweg
      event: START
      channelUID: astro:sun:quellenweg:rise#event
    type: core.ChannelEventTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      itemName: dt_NightState
      state: OFF
    type: core.ItemStateUpdateAction
  - inputs: {}
    id: "3"
    configuration:
      itemName: dt_LateNightState
      state: OFF
    type: core.ItemStateUpdateAction
  - inputs: {}
    id: "4"
    configuration:
      type: application/javascript;version=ECMAScript-2021
      script: >
        console.log("NightState updated, --> NightState set to",
        items.getItem("dt_NightState").state);
    type: script.ScriptAction
  - inputs: {}
    id: "5"
    configuration:
      type: application/javascript;version=ECMAScript-2021
      script: >
        console.log("LateNightState updated, --> LateNightState set to",
        items.getItem("dt_LateNightState").state);
    type: script.ScriptAction

So I am manipulating item-states in UI-rule actions and then want to access these in the scripts.
What happens is that the item-states get updated (events.log):

2022-01-12 08:23:00.000 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:quellenweg:rise#event triggered START
2022-01-12 08:23:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:quellenweg:civilDawn#event triggered END
2022-01-12 08:23:00.004 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START
2022-01-12 08:23:00.004 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'TimeOfDay' received command DAY
2022-01-12 08:23:00.007 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END
2022-01-12 08:23:00.008 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'dt_NightState' changed from ON to OFF
2022-01-12 08:23:00.008 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'dt_LateNightState' changed from ON to OFF
2022-01-12 08:23:00.009 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'TimeOfDay' changed from BED to DAY

(just look at the timestamps from the two dt* items).

My script log actions actually seem to execute a fraction of a second earlier and the first one logs (aka fetches) the old state:

2022-01-12 08:23:00.003 [INFO ] [model.script.rules_tools.Time of Day] - Transitioning to DAY
2022-01-12 08:23:00.005 [INFO ] [org.openhab.automation.script       ] - NightState updated, --> NightState set to ON
2022-01-12 08:23:00.007 [INFO ] [org.openhab.automation.script       ] - LateNightState updated, --> LateNightState set to OFF

My expectation was that each of the steps in the rule-body are executed in sequence. I also have not found anything in the docs that discourages mixing different rule-languages in a rule.
Of course I could put all the item-manipulations and logging in a single script but my point was to use UI as much as possible and leverage the power of the UI rules-actions.

So question: is this to be expected if mixing rule-engines and manipulating & accessing the same items within a rule multiple times ?
Or should that work and I’m having side effects of the other “Time of day” rules from marketplace/Rich (they do not touch/use the two dt* items) ?

Thanks
-Markus

2

They do. But the Items don’t. Issuing an update or a command to an Item kicks off a whole cascade of stuff that happens (in parallel). And the call to postUpdate or sendCommand does not block until all that is done. It can take some time (or never in the case of a command) for the Item to actually update to a new state in response.

Almost never can you postUpdate or sendCommand and then pull the state of the Item immediately after and have the Item reflect the new state.

That’s not a problem. You can mix and match as needed. I do that myself sometimes as a few things are easier to do in Rules DSL than JS Scripting.

What I usually do not do, though, is mix Script Actions with other Actions in the same rule. If you have to fall back to a Script Action, you may as well do it all in the one script action. But that’s not going to do anything here because even in a single Script Action your log statements will occur before the Item has had a chance to change state.

3

Thanks Rich !
I must admit I did these things in the past in rules-DSL, because I am lazy (re-using & copying the log-lines where needed):

rule "Switch LateNightState to ON at 22h00"
when
    Time cron "0 0 22 1/1 * ? *"
then
	postUpdate(LateNightState, ON)
    logInfo("LateNightState updated", "--> LateNightState set to " + LateNightState.state)
end

But I assume I did not pay as much attention to the logs compared to today while I am in the process of migrating to make sure stuff works as intended.

So takeaway: a changed item-state can’t be immediatly retrieved reliably (in contrast to traditional programming languages) even in a single JSScript. If needed one would use a new variable like “futurestate”, postupdate the item with that and textually log the “futurestate” instead of the real item.

1 Like
4

Treat Items like devices, not variables.
Remember, they are designed to be representations or models of real world devices. If you instruct “open that window” you would not expect “window open” reported completely instantaneously, action-response takes time.
It’s not about programming language, it’s about the chain of events that Item processing is exactly intended to model.

2 Likes
5

The only thing I’ll add is the methods are named “sendCommand” and “postUpdate” on purpose. In both cases they emit a message into OH. Typically, in message based event driven systems like OH, it’s does not block until the message is precessed and acted upon. It’s only blocks long enough for the message to be sent.