JimT
(jimtng)
March 8, 2022, 7:59pm
21
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)
March 21, 2022, 8:31am
22
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
(Rossko57)
March 21, 2022, 9:40am
23
Sascha_L:
or JAVA
This is still very reminiscent of -
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.