ZonedDateTime not equal to openHAB event time

No, but even it did it would be consistently different. So it’s not a two-clocks problem.

The actual clock in use will be that provided by the Java environment, which may or may not be the same as the host system.

But none of us can see that. What we can see is a message that your rule sent to the logger, and the logger then put a timestamp on it.

It’s not that uncommon to find timestamps arriving in the log file out of order when events occur close together, which is a good hint that the log timestamping is not quite as straightforward as it appears.

Tell us more about the scheduling that you think is going wrong. Tell us more about “Whenever I run it, it is working” - run how?. Which is related to what in the events log snippet?

May we know exactly what is not working?

It is very easy to inadvertently build rules in openHAB that are subject to race conditions, based on false assumptions about how it all works. I couldn’t say if that is your problem, as the nature of your real problem is a secret at the moment.

Example -

rule "race demo"
when
   Item someItem received command
then
   logInfo("test", "my state is " + someItem.state.toString)
   logInfo("test" "but I expected it to be " + receivedCommand.toString)
end

The results may or may not be different.

Well, it’s not working. How do we know you’ve posted all the relevant information? How do we know anything beyond what you’ve posted? How do we know you are a the head of development or anything.

All we know is what you’ve written. When you redact, you are not helping yourself and you’re not helping us. You may know how to debug but you don’t know how to ask for help on this forum.

You say that but you’ve not actually posted evidence to us that says that. We don’t know anything you haven’t told us. The logs you’ve posted are not logging now so we don’t know what now actually is when the rule runs. All we have is the timestamp on the logs and the hour and minutes from the new LocalTime you’ve created in your rule.

You’re not using now.getLocalTime() and instead are creating a new LocalTime with the hours and minutes from now. Have you looked at how that code works? It’s not openHAB’s code so we don’t know. It’s a third party library.

Have you looked into Log4j2 and how it applies the timestamps to log statements? All logging goes through log4j2. If something is going on there, that’s where you’ll find out.

Some other useful information we could use:

  • what are the specific triggers, the fact that the logs are three to four seconds after 08:30 could be relevant

  • what have you already tried when trying to figure out what is going on; by neglecting to tell us how are we to know and provide suggestions for things you’ve already done, or waisting our time reproducing the same steps you’ve already done

In the end, there is only one clock used in openHAB, the Java one which is driven by the system clock (though might have different locale and timezone settings from the system one). But we are dealing with two third party libraries, joda-js and Log4j2. Maybe there is something going on unexpectedly there. Maybe there is something going on in the system that is causing the timestamps on the log statements to be delayed.

All three of these replied have offered a bunch of ideas you can use to gather more information. Maybe one will lead you to a solution. Maybe you’ve already tried them, but how would we know?

I think what the OP is saying is that he has a rule that’s SCHEDULED to run at 8:30 and when that rule is executed, now followed by localtime call returned 8:29. Ignore the log4j timestamps

So it seems that the scheduler fired too early.

It would’ve made more sense had now been 8:31 due to lag in processing. But being early seemed weird.

1 Like

Agreed but without knowing the specific rule triggers :woman_shrugging:

The reason how I react is due to the fact, that it is not the first time, that your are unfriendly. I told you all relevant information in my first post. If you have further questions, just ask, instead of telling me that I’m stupid and that everything is correct but I’m to stupid to understand what I have to expect.

I told you, that I have a Rule which is running at: 8:00, 8:30, etc. and at civil dusk / dawn event.
I told you, that now() returns 7:59, 8:29 when the script is running by that rule, which has to start at 8:00, 8:30, etc.

My script checks if 08:00 == 08:00, and if 8:30 == 8:30, etc. if true, something is happening, if false, nothing is happening. Sometimes it is working, because 08:00 == 08:00, sometimes it is not working, because now() returns 7:59 so that 07:59 == 8:00 is false.

triggers:
  - id: "1"
    configuration:
      thingUID: astro:sun:local
      channelUID: astro:sun:local:civilDusk#event
    type: core.ChannelEventTrigger
  - id: "2"
    configuration:
      thingUID: astro:sun:local
      channelUID: astro:sun:local:civilDawn#event
    type: core.ChannelEventTrigger
  - id: "5"
    configuration:
      time: 07:45
    type: timer.TimeOfDayTrigger
  - id: "7"
    configuration:
      time: 08:00
    type: timer.TimeOfDayTrigger
  - id: "3"
    configuration:
      time: 08:20
    type: timer.TimeOfDayTrigger
  - id: "8"
    configuration:
      time: 08:30
    type: timer.TimeOfDayTrigger
  - id: "4"
    configuration:
      time: 09:00
    type: timer.TimeOfDayTrigger
  - id: "6"
    configuration:
      time: 13:00
    type: timer.TimeOfDayTrigger

So there are the follwing options

  • The scheduler is wrong and runs code at e.g. 7:59 when it has to run at 8:00
  • ZonedDateTime.now() returns the wrong time (7:59 when it has to be 8:00)
  • time.LocalTime.of(now.hour(), now.minute()); has a bug and returns 7:59 when 8:00 is given as parameter (that makes no sense, if it is working correct sometimes and sometimes not)

In my case the timestamps of the log file are correct. I checked that live, but as already said, it is not about the timestamps in my log file, it’s about the fact, that the time when the rule is running is greater than the time of now() in the script called by that rule.

Also it’s weird, that it is correct sometimes, and sometimes not.

It seems to me that likely the timeofday trigger has a bug?

Out of curiosity, I’ll play around with this in a bit and see.

In the mean time you could write extra code to compensate by adding a further delay or timer if it is too early.

Alternatively try using cron trigger instead. However, even cron trigger may have some fudge factor if I remember correctly.

Out of all the possibilities you’ve listed, I’d tend to trust zoneddatetime and localtime to be true

Thanks! I also thought about using a delay, or check if the time is equal OR up to one minute in the past. But I suspect that this workaround is not an all time solution. I don’t know whether if the delay is the same in a few months, maybe it is two or three minutes then.

So it would be better to find out why this happening and then to fix it or to understand how this happens and which workaround would fit for ever. I will also try getLocalTime() instead of time.LocalTime.of() as suggested.

The reason why I used it, is:

var zeit0745 = time.LocalTime.of(7,45);
var zeit0800 = time.LocalTime.of(8,0);
var zeit0820 = time.LocalTime.of(8,20);
var zeit0830 = time.LocalTime.of(8,30);
var zeit0900 = time.LocalTime.of(9,0);
var zeit1300 = time.LocalTime.of(13,0);

if (nowZeit.equals(zeit1300))

and so on....

I am using this to have a comfortable and easy to read solution to check which time it is and run that specific code (roller shutter down, up, set at a specific level). I also check other things like temperature, weekend, holiday, home office, vacation, etc.

So if the openHAB scheduler is running the rule to early in my case, how can I check this? Will setting the log file to DEBUG or TRACE level show when the scheduler starts the rule? Then I will check this…

It looks like the TimeOfDayTrigger is implemented as a cron schedule inside openhab-core. So maybe trying to use cron would yield a similar result. I’m curious though, have you ever tried to log the second/millisecond/nanosecond of now?

Also curious why such precision is important? I know, this still seems like a “bug” somewhere, either in openhab, java library, java vm, or the hardware…

Is the PC overclocked? I am not familiar at all with the issues of time keeping so this is just a wild guess.

If I understand this correctly, perhaps the best solution is to split up the rules, so you won’t need to perform the time check in your rule. To elaborate: you’ll have one rule with time trigger for 8:00, another rule with time trigger 8:30, and so on.

jruby scripting allows you to “attach” a certain “tag” / data / object to each trigger, so within your rule, you can know exactly which of the multiple triggers was the cause of the rule execution.

You could perhaps achieve something similar in UI rule by having that common rule in a trigger-less rule, (so you can have a common code) and then have multiple rules, one for each time trigger, which then run that trigger-less rule. And if you want to know which trigger occurred, you could use a virtual item as your variable.

Another way to skin the cat is to employ some sort of “tolerance” in your code, e.g. if abs(now - 8:00) < 3 minutes then it's the 8:00 trigger. You could use java.time.Duration.between(zdt1, zdt2) for this.

1 Like

“early triggering” by scheduler eventually rang a bell with me - see

The potential identified there was that if the Java clock is adjusted (say by NTP update) the scheduler re-calculates any current scheduled jobs, and here rounding errors etc. may creep in.
Any such effect will be highly dependent on versions involved, plus the underlying RTC is managed by Windows this time.

It remains difficult to see how the logger timestamping and Java “now” in a rule can come up grossly different.

Thanks for your ideas! I will look into it deeper.

In general I like to prefer a clean and simple solution. So I don’t like the idea of using so many rules. This case is just one of a lot of other use cases (light controlling, aeration controlling, etc.).

In this case it is enough to know which trigger triggered, so your idea with a tag for each trigger should work great. Of course I don’t need the precision, it is no problem if the script runs at 8:01 instead of 8:00 or at 7:59.

I also thought about a completly different approach: Running my script every minute to check if on the neccessary time points are reached. If no, nothing else is happening, if yes, my following code will execute. I decided to use the way with a rule and triggers to prevent unnecessary CPU performance. My CPU has enough power, so I could also use the ‘every minute’ alternative. But for the future I also want to know, what exactly is the reason for the time difference and if this can be fixed, because it could be a problem for other rules/scripts too.

The CPU is not overclocked.

I changed my script to log the whole time string of now(). It will come back with the results tomorrow.

But what if you “missed” it, e.g. it fired 7:59:50, then 8:01:01

Anyway, code in jruby would look like this:

rule 'run stuff' do
  channel 'astro:sun:local:civilDusk#event', attach: :dusk
  channel 'astro:sun:local:civilDawn#event', attach: :dawn
  every :day, at: '7:45', attach: :T0745
  every :day, at: '8:00', attach: :T0800
  every :day, at: '8:20', attach: :T0820
  every :day, at: '8:30', attach: :T0830
  every :day, at: '9:00', attach: :T0900
  every :day, at: '13:00', attach: :T1300
  run do |event|
    case event.attachment
    when :dusk
      # do stuff here
    when :dawn
      #do stuff here
    when :T0745
      # you get the idea...
    end
  end
end

Note this “attach” feature is only available when using file-based rules. Whilst you can use jruby rule with UI based rules, and it would still be far easier to use than js / jython etc, the trigger is defined by the UI, so there’s not much that can be done there.

Another note, if you’re unfamiliar with ruby, something that starts with a colon like :dusk is called a symbol. But you don’t have to attach a symbol. You can attach a number, a string, or whatever.

Here’s an example if you want to attach a string:

rule 'run stuff' do
  channel 'astro:sun:local:civilDusk#event', attach: 'dusk'
  channel 'astro:sun:local:civilDawn#event', attach: 'dawn'
  every :day, at: '7:45', attach: 'T0745'
  every :day, at: '8:00', attach: 'T0800'
  every :day, at: '8:20', attach: 'T0820'
  every :day, at: '8:30', attach: 'T0830'
  every :day, at: '9:00', attach: 'T0900'
  every :day, at: '13:00', attach: 'T1300'
  run do |event|
    case event.attachment
    when 'dusk'
      # do stuff here
    when 'dawn'
      #do stuff here
    when 'T0745'
      # you get the idea...
    end
  end
end

And… if you are lazy like me and don’t want to type too much:

rule 'run stuff' do
  channel 'astro:sun:local:civilDusk#event', attach: 'dusk'
  channel 'astro:sun:local:civilDawn#event', attach: 'dawn'
  %w[07:45 08:00 08:20 08:30 09:00 13:00].each { |time| every :day, at: time, attach: time}
  run do |event|
    case event.attachment
    when 'dusk'
      # do stuff here
    when 'dawn'
      #do stuff here
    when '07:45'
      # you get the idea...
    end
  end
end

Explanation:
%w[07:45 08:00 08:20 08:30 09:00 13:00] is just a way of writing a string of array without enclosing the elements in double quotes. It’s equivalent to ["07:45", "08:00", "08:20", "08:30", "09:00", "13:00"]
(which you can write instead, if you prefer… but most people wouldn’t)

Then you would loop through that array using .each… and for each element of the array, call every ..... to define your trigger for that element.

1 Like

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.

jruby is totally new for me. I will read up on it.

By the way, currently now() returns the correct value, so I have to wait until tomorrow. But I’m still a little bit confused:

2022-03-08 13:00:04.903 [INFO ] [n.script.ui.SkriptRollladensteuerung] - "2022-03-08T13:00:04.904+01:00[SYSTEM]"
console.log("Skriptausführung Rollladensteuerung - START");

var now = time.ZonedDateTime.now();
console.log(now);

If now () is called before log() is called and if log() also needs time to write the string to file, why is the timestamp of the log entry before now()? Yes I know, it is only 1 ms, but I would expect that it is vice versa.

Try changing that to nowxx or something, risk of a keyword at play here

That would be the really useful thing to understand yes, and it does not involve scheduler complications.
The logger is independent of openhab core and gets its times from Java clock. The question then is where does rules ‘now’ from?

You need worry no longer about my unfriendly responses. If you had provided all the relevant info in your first post our initial replies might have been different.

Nowhere did I say you were stupid not did I say everything is correct. I outlined my thought process to figure out how to figure out what is going on. I outlined what I would think and say to myself and what I would do to start figuring out what is going on.

If that’s me calling you dumb then I must be the stupidest MF on this whole forum.

But since my stupidity comes across as unfriendly to you, I won’t respond to your requests for help in future.

I did ask questions and Im did give suggestions for how to gather more information. But if that’s

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.

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.

This is still very reminiscent of -

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.