Everything happens 51 minutes too late

Setup, Configuration and Use Scripts & Rules
1

Hi.
I had to shut down my OH server yesterday due to power outage. After restarting it again everything seemed to work nice, but now I have discovered something really strange. All rules that are supposed to execute at a certain time are actually executed exactly 51 minutes too late. No error messages, no nothing. The server clock is correct (according to the “date” command). It could be that the server was shut down for 51 minutes, but how the heck could that end up in this? I’m kinda stumped, this is just strange. Anyone got any ideas?

  • Platform information:
    • Hardware: Radxa RockPi4
    • OS: Armbian 21.08.6 Buster
    • Java Runtime Environment: openjdk 11.0.9.1 (Zulu)
    • openHAB version: 3.2.0
2

Hi,
just this morning I have the same issue, in my case rules are off by 10 Minutes.
I have OH running on Debian in a VM on Hyper-V and had to restart my server yesterday which paused the VM OH is running on for about 10 minutes.
As with Daniel the OS clock is correct just OH is missing 10 Minutes.

I have not yet restarted OH as I’m still investigating.

Best regards,
Florian

1 Like
3

Do the log files ( openhab.log, events.log ) show the same offset ?
E.g. do a tail -f on /var/log/openhab/events.log or use logtail viewer and make sure that an event is created. A log entry should be created. Is there any offset for that entry ( time ) and the current time ?

4

No, the timestamps in the logfiles are correct. For example this line:

2022-01-20 06:51:49.944 [INFO ] [org.openhab.core.model.script.Morgon] - It’s six a’clock!

…written by a rule that’s supposed to be executed at six in the morning, was written in the log at 06:51.

5

So your system time seems to be out of sync, which is an OS issue, but not openHAB.

6

Did you actually read what I wrote before posting that comment? No, system time is definitely completely correct.

7

Is this a rule you wrote after your server restart, or an existing rule from before the shutdown?

8

Interesting question! It’s an old rule. I double checked the rule now (in case it’s changed in some way), the trigger looks like this:

triggers:
  - id: "2"
    configuration:
      time: 06:00
    type: timer.TimeOfDayTrigger
9

I wonder what result you’d get if you wrote a brand new rule of the same kind - is the trigger still 51 minutes behind?

In general though, I think there’s three clocks that need checking:

  • OS
  • Java
  • openHAB
10

Good thinking. I made a rule now that’s supposed to trigger in five minutes, we’ll see…

I know how to check the OS clock, but how do I check the other two? I didn’t even know they had their own clocks…

11

Java time is used for logging, and for scheduling. Cron based rule triggers are therefore triggered by the Java clock.

openHAB derives a clock from Java, but can apply its own locale timezone etc. This is what you get in timestamp profiles, ‘now’ in rules, and so on.

What a new-fangled GUI TimeOfDayTrigger works off, I don’t know. Maybe cron, maybe not.

You see why the question about log timestamps now.
I suppose a helpful diagnostic would be to trigger a rule at a fixed time and have it log what it thinks ‘now’ is, compare to logger’s timestamping, and tell us which you think is accurate.

1 Like
12

Tested now. Seems newly created rules execute correctly, so I guess this only affect old rules. I guess that means I can solve it by recreating my old rules (or maybe just recreating their triggers?), but it also means it will be harder continuing to debugging…

13

Interesting. I don’t know much about this, to be honest. Maybe openHAB has some old timers still running? I know that the Astro binding sets up all its timers for the day at midnight. But this is just guessing.

If it were me I’d go nuclear and clear the cache and restart.

14

Sounds maybe like your time-of-day rules were scheduled during a start-up process, while the clock was wrong, and then the clock corrected. I think this will shake itself out as each runs and reschedules?

Might be kinder to just restart in the first instance, cache blitzing introduces new alarming messages.

Would you confirm the exact nature of your rule triggers, GUI time-of-day, old-fashioned cron, etc?

15

You’re right, though I tend to ignore most log messages during startup - ignorance is bliss!

16

In my case it’s cron rules that are off by 10 minutes. I normally start my heaters at 6:30 in the morning by cron rule, yesterdays log was:

2022-01-19 06:30:00.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZE_Heating_PresetTempNormal' changed from 17.0 to 21.0
2022-01-19 06:30:00.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZW_Heating_PresetTempNormal' changed from 17.0 to 21.0
2022-01-19 06:30:00.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OF_Heating_PresetTempNormal' changed from 17 °C to 20 °C

Todays log was:

2022-01-20 06:40:31.617 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZE_Heating_PresetTempNormal' changed from 17.0 to 21.0
2022-01-20 06:40:31.617 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'WZW_Heating_PresetTempNormal' changed from 17.0 to 21.0
2022-01-20 06:40:31.617 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'OF_Heating_PresetTempNormal' changed from 17 °C to 20 °C

The rule is always the same and it is not the only rule firing 10 minutes off. As stated, yesterday I restarted my Hyper-V server which took about 10 minutes, my VMs are paused before shutdown and continue after reboot of the server is done.
Before yesterday I gacefully suht down the VM runinng OH and did a fresh restart after the reboot is done, I never had an issue with the clock inside JAVA/OH being out of sync.
So the solution in my case is probably quite easy - but it seems that there is an underlying problem that probably should be addressed.

Best regards,
Florian

17

Yes, the hard part would be finding a volunteer who can repeatably demonstrate it :wink:

I wonder if VM use has something to do with it.

18

This might actually be it. I have no rtc clock in my server, so until it has communicated with ntp I think the clock might be set to whatever it was at the last shutdown. So if the server was down for 51 minutes this makes sense. I guess the simple solution is to fiddle with the startup so that openhab isn’t started until after ntp,

I have also restarted my OH now, I’ll report back later today if everything triggers as it should (since I have no old rules due until later tonight).

2 Likes
19

In reality it might be easier behind the scenes to spot when the clock makes a large correction and re-schedule any pending tasks. I vaguely recall something like that for OH2, but I think the scheduler changed for OH3.

Did anyone spot if this messed up Astro events too?

I’ve got an idea the scheduler calculates an offset into the future. Great, that takes care of daylight saving time because we can do that in the calculation. But changing the clock after calculation ruins it.

20

I’d just like to notice that after my restart yesterday everything has worked like it should again. So it seems plausible we have found the problem, ie the OS clock being set wrongly when OH is starting up and the scheduling not recovering from that. I don’t know, should we report this as a bug?

Regarding Astro I don’t know, never used any of that.