ZonedDateTime not equal to openHAB event time

  • Platform information:
    • Hardware: Intel x86-x64
    • OS: Windows 10 x64 Pro
    • Java Runtime Environment: Zulu JDK 11.54.23
    • openHAB version: openHAB 3.3.0.M1

I have the following script:

console.log("Skriptausführung Rollladensteuerung - START");

var now = time.ZonedDateTime.now();
var nowZeit = time.LocalTime.of(now.hour(), now.minute());

console.log("Skriptausführung Rollladensteuerung - " + nowZeit);

This script will be called by a rule at different times (e.g. at 08:00, 08:30, etc.) and when civil dusk / dawn events fired by astro binding.

Sometimes ZonedDateTime.now() is BEFORE (!) the time when the script is called, which makes no sense to me. How does this happens? How can I fix this wrong time?

Log:

2022-03-06 08:20:03.747 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 08:20:03.778 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:20
2022-03-06 08:30:03.758 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 08:30:03.790 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:30
2022-03-06 09:00:03.758 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 09:00:03.789 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 09:00
2022-03-06 13:00:03.760 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 13:00:03.807 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 13:00
2022-03-06 18:36:04.038 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 18:36:04.070 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 18:35
2022-03-06 18:46:48.867 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 18:46:48.929 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 18:46
2022-03-06 19:09:04.023 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 19:09:04.054 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 19:08
2022-03-07 06:47:00.027 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 06:47:00.042 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 06:46
2022-03-07 07:21:00.023 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 07:21:00.039 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 07:20
2022-03-07 07:45:04.674 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 07:45:04.720 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 07:44
2022-03-07 08:00:04.677 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 08:00:04.693 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 07:59
2022-03-07 08:20:04.670 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 08:20:04.702 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:19
2022-03-07 08:30:04.687 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 08:30:04.702 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:29
2022-03-07 08:46:23.053 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 08:46:23.131 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:46
2022-03-07 09:00:04.693 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-07 09:00:04.725 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 09:00

As you can see in the log, the script e.g. starts at 08:30:04, but ZonedDateTime.now() returns 08:29:xx. It makes sense if now() is AFTER the time when the scripts starts, but not BEFORE.

When things don’t make sense, reconsider your assumptions. There is a whole lot going on here at the same time, maybe your assumptions are not correct? Maybe it’s the log statement that’s being delayed (writing to disk takes some time). I think it’s the case that the timestamp of the log gets generated before it gets written, not when the log statement itself is created. How does joda-js’s time.LocalTime.of() work? Maybe it does some unexpected rounding. What’s it do for the seconds and nanos when they are not supplied?

Don’t assume anything and devise experiments that will help confirm or refute your hypothesis.

As I look at the logs I’m not seeing this behavior very often. But some of the first things I would do:

  • why create a new LocalTime? Just use now.getLocalTime(). But before deleting what you are doing now, compare the two and see if there is a difference. That will tell you that something is going on in that of() function.

  • what is your CPU, RAM, disk IO and overall system load doing when the problem occurs? If the script truly was called at 08:30, why did it take almost four seconds for the rule to run or at least for the logs from the rule to be written to the file?

  • Log out the seconds and nanoseconds too. How close are these two time stamps really? Are they far or are they within a second of each other? For that matter, add a log out of time.ZonedDateTime.now() to both log statements. That will tell you what time the rule actually ran and confirm or deny my hypothesis (see below).-

Actually no, that’s not what I see, at least for that time. I see

2022-03-06 08:30:03.758 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - START
2022-03-06 08:30:03.790 [INFO ] [n.script.ui.SkriptRollladensteuerung] - Skriptausführung Rollladensteuerung - 08:30

Timestamp is 08:30:03.790 and LocalTime is logged as 08:30. No problem there, just as expected. I do see the problem in later log statements from above though. Make sure you are seeing the logs as they are rather than what you expect. It’s easy to get lost among the START and second log statement.

My assumption here is not that the time.LocalTime is too early but that the log statements are somehow being delayed and it’s those timestamps that are off. But further experiments are necessary.

1 Like

Thanks for your help, but it is as I said, otherwise I wouldn’t say that!

I don’t care about the timestamp in the log file. But it shows the issue visually and the timestamp is correct.

My script is working fine without any errors. Always. Whenever I run it, it is working. Sometimes, WITHOUT ANY CHANGES it is not working. Of course my Log contains a lot more information to find out what is the problem. So I found out, it is the time and nothing else. That’s why I posted all necessary information.

I said:

I created a Rule which runs e.g. at 08:00. The rule calls my script. First of all, my script logs the start of the script, so this is run before ZonedDateTime.now() is called. Of course the script is never called at 08:00:00 due to the fact a lot code is running by openHAB. That’s why we see, that the script is called e.g. at 08:00:04. That’s fine and now problem. But a problem is, that now() returns 7:59 at this time. That’s what you are seeing in the log and nothing else. It doesn’t matter WHEN the log is really written and whats the timestamp. Yes it maybe alot later, in my case it isn’t later, but as said, it doesn’t matter, because in the log you see the output of now() which is e.g. 7:20 when it is has to be 7:21, it is 7:44 when it has to be 7:45, it is 8:29 when it has to be 8:30.

I’m a head of development. I know how to debug, how to find out whats wrong. So that’s why I created this thread, because I found out, that now() returns a time which is BEFORE the time openHAB runs a rule by scheduler. If a rule is running at 08:00:xx and now() returns 07:59:xx something is wrong and makes no sense.

So what’s the reason? Does openHAB scheduler use a different mechanism to get the current time than the javascript which is running by openHAB? Both should use the system time and both should always return the same time (a difference of a few ticks or milliseconds is ok, but not a few seconds, because thats a very huge amount!).

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