ZonedDateTime not equal to openHAB event time

[JimT (jimtng)]

@Sascha_L

If my script runs every minute for example, I’m able to save the information whether the ‘8:00 code’ already run, so it would be no problem if the script runs at 7:59 and the next time at 8:01. It also has the advantage that the roller shutter also open/close if the server crashes/restarts at 8:00, 9:00, etc. or power is lost at that specific time. The script would catch up on everything when it is running again.

That is indeed a useful thing. In my rules I often do the same thing.

Example (in jruby):

rule 'Pool: Chlorinator start' do
  every 5.minutes
  changed things['mqtt:topic:poolpump-switch'], :to => :online # trigger when the pump is turned on from the wall
  between '9am'...'2pm'
  run { Pool_Chlorinator.ensure.on }
end

Instead of scheduling the chlorinator to start at 9am, I would check every 5 minutes, so if openhab was shut down at 9am, and started up at 10am, the chlorinator would still start for that day albeit late.
Note:

• ensure above would not send the ON command if the item is already ON.
• It also has another trigger when a thing came online

Yes I could send the schedule to the actual smart switch too so it would start/stop even when openhab is down, but that’s a different discussion.

[Sascha_L (Sascha)]

So, as promised, here are new logs. It seems that the issue occurs after a few days.

Log:

2022-03-10 08:20:02.759 [TRACE] [ore.internal.scheduler.SchedulerImpl] - Scheduled task is run now.
2022-03-10 08:20:02.759 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'RegelRollladensteuerung' is triggered.
2022-03-10 08:20:02.759 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=openhab] {topic=openhab/rules/RegelRollladensteuerung/state, source=RuleEngineImpl, type=RuleStatusInfoEvent, payload={"status":"RUNNING","statusDetail":"NONE"}, timestamp=1646896802759}
2022-03-10 08:20:02.759 [TRACE] [automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.monitor.internal.EventLogger).
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.rest.sse.internal.listeners.SseEventSubscriber).
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.monitor.internal.metrics.RuleMetric).
2022-03-10 08:20:02.759 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2022-03-10 08:20:02.759 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=openhab] {topic=openhab/rules/SkriptRollladensteuerung/state, source=RuleEngineImpl, type=RuleStatusInfoEvent, payload={"status":"RUNNING","statusDetail":"NONE"}, timestamp=1646896802759}
2022-03-10 08:20:02.759 [TRACE] [automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.monitor.internal.EventLogger).
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.rest.sse.internal.listeners.SseEventSubscriber).
2022-03-10 08:20:02.759 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.monitor.internal.metrics.RuleMetric).
2022-03-10 08:20:02.759 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2022-03-10 08:20:02.759 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-10 08:20:02.759 [DEBUG] [.monitor.internal.metrics.RuleMetric] - Rule RegelRollladensteuerung RUNNING - updating metric.
2022-03-10 08:20:02.759 [DEBUG] [.monitor.internal.metrics.RuleMetric] - Rule SkriptRollladensteuerung RUNNING - updating metric.
2022-03-10 08:20:02.759 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-10T08:20:00.426+01:00[SYSTEM]"
2022-03-10 08:20:02.790 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:20
2022-03-10 08:20:02.790 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'SkriptRollladensteuerung' is executed.
2022-03-10 08:20:02.790 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'RegelRollladensteuerung' is executed.

----

2022-03-14 08:19:59.151 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-14 08:19:59.151 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-14T08:20:00.275+01:00[SYSTEM]"

----

2022-03-14 08:29:59.146 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-14 08:29:59.146 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-14T08:30:00.270+01:00[SYSTEM]"

----

2022-03-14 08:59:59.144 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-14 08:59:59.144 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-14T09:00:00.269+01:00[SYSTEM]"

---

2022-03-15 18:51:00.010 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-15 18:51:00.010 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-15T18:50:56.773+01:00[SYSTEM]"

----

2022-03-15 19:25:00.019 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-15 19:25:00.019 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-15T19:24:56.783+01:00[SYSTEM]"

-----

2022-03-16 06:45:00.017 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered START
2022-03-16 06:45:00.017 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-16 06:45:00.032 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-16T06:44:56.780+01:00[SYSTEM]"

2022-03-16 07:00:00.022 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-16 07:00:00.022 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-16T06:59:56.781+01:00[SYSTEM]"

------

2022-03-16 08:00:04.235 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-16 08:00:04.235 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-16T08:00:00.997+01:00[SYSTEM]"

-----

2022-03-19 18:52:04.736 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-19 18:52:04.736 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-19T18:51:59.999+01:00[SYSTEM]"
2022-03-20 06:45:00.015 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-20 06:45:00.015 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-20T06:44:55.278+01:00[SYSTEM]"
2022-03-20 08:00:05.682 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-20 08:00:05.682 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-20T08:00:00.943+01:00[SYSTEM]"
2022-03-20 18:54:03.888 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-20 18:54:03.888 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-20T18:53:55.269+01:00[SYSTEM]"
2022-03-21 06:45:00.019 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-21 06:45:00.019 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-21T06:44:51.400+01:00[SYSTEM]"

As you can see ZonedDateTime.now() returns a time, which is up to 8 seconds BEFORE the time the script is called. I posted the times, when the script is called in one of my previous posts. Besides those time values I also use civil dusk and dawn trigger.

As you cann see in the log:
astro:sun:local:civilDawn#event triggered START

the trigger starts at 6:45:00. That’s the correct time which comes from the astro binding. My script is then called immediately, but you can see, that ZonedDateTime.now() returns 6:44:56.

So there is a very big time issue. I don’t know what is causing this. Either openHAB has a bug or JAVA or JS Joda (which is used for ZonedDateTime.now() in ECMA 2021 scripts?).

The Server is idling while this issue happens. Neither openHAB nor Windows doing anything at those time frames. I also cheched System / Windows time and set the energy options to High Performance to avoid variable cpu clock speeds.

[rossko57]

@Sascha_L

or JAVA

This is still very reminiscent of -

Scheduler Delayed // Openhab 3.0.2 and 3.1.0M5

The puzzler is why, if say the clock ticks slow so that scheduled events are “late” … why would the system clock not read slow as well. A quick internet dive threw up some stuff beyond my pay grade, but suggesting that Java scheduler does some jiggery-pokery if the system clock is changed. This jiggery-pokery is flawed apparently, and errors can accrue. Have you got NTP configured somewhere here, and if so how frequently is it tweaking system clock? It might work better to tweak less often. …

where corrections to Java clock (by NTP say) can cause scheduler to recalculate new future triggers. But it’s a bit flawed, and errors accumulate over many corrections.

So far as I know that kicks in for significant corrections, and tiny changes do not invoke it. So many tiny corrections may also cause an apparent displacement of scheduled tasks, too.

How Java derives its clock in a Windows environment, no idea. What Windows might do to the clock using NTP etc. is problaly easier to investigate.