Jumps in system-time

  • Platform information:
    • Hardware: Raspberry Pi 3b
    • OS: openHABian
    • Java Runtime Environment: openjdk version “1.8.0_322”
    • openHAB version: openHAB 2.5.12 (Release Build)
  • Issue of the topic:
    I’m running Openhab since several years, have some rollershutters with Shellies, a bunch of movement sensors (mainly Aqara via a ConbeeII stick), a few lights and a few items connected via MQTT.
    Sometimes - and I didn’t find out what triggers that - the time suddenly changes 2 hours forewards and sometimes later it changes 2 hours back. Attached is a logfile where those events happened quite close to each other. The problem is of course - if something (like the rollers) is timer controlled and falls under that timeframe than the whole houseautomation looks questionable.

In the attached log the time changed from 18:42 to 20:43 and 20:44 back to the real time.

2022-08-29 18:41:41.352 [GroupItemStateChangedEvent] - gMoveKorrEG changed from OFF to ON through EG_Korridor

2022-08-29 18:41:41.364 [GroupItemStateChangedEvent] - gMovement changed from OFF to ON through gMoveKorrEG

2022-08-29 18:41:43.964 [vent.ItemStateChangedEvent] - EG_Windfang_Helligkeit changed from 18.0 lx to 9.0 lx

2022-08-29 18:41:43.971 [vent.ItemStateChangedEvent] - EG_Windfang changed from OFF to ON

2022-08-29 18:42:46.884 [vent.ItemStateChangedEvent] - EG_Windfang_Helligkeit changed from 9.0 lx to 16.0 lx

2022-08-29 18:42:48.415 [vent.ItemStateChangedEvent] - EG_Korridor_Helligkeit changed from 4.0 lx to 14.0 lx

2022-08-29 20:43:11.162 [vent.ItemStateChangedEvent] - EG_Windfang changed from ON to OFF

2022-08-29 20:43:11.273 [vent.ItemStateChangedEvent] - EG_Korridor changed from ON to OFF

2022-08-29 20:43:11.307 [GroupItemStateChangedEvent] - gMoveKorrEG changed from ON to OFF through EG_Korridor

2022-08-29 20:43:11.331 [GroupItemStateChangedEvent] - gMovement changed from ON to OFF through gMoveKorrEG

2022-08-29 20:43:12.464 [ome.event.ItemCommandEvent] - Item 'Rollo_Kueche' received command DOWN

2022-08-29 20:43:12.510 [ome.event.ItemCommandEvent] - Item 'Rollo_Schreibtisch' received command DOWN

2022-08-29 20:43:12.516 [nt.ItemStatePredictedEvent] - Rollo_Kueche predicted to become DOWN

2022-08-29 20:43:12.581 [nt.ItemStatePredictedEvent] - Rollo_Schreibtisch predicted to become DOWN

2022-08-29 20:43:12.612 [vent.ItemStateChangedEvent] - Rollo_Kueche changed from 0.0 to 100

2022-08-29 20:43:12.661 [vent.ItemStateChangedEvent] - Rollo_Schreibtisch changed from 0.0 to 100

2022-08-29 20:43:12.678 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10A300:roller#event triggered ROLLER_CLOSE

2022-08-29 20:43:12.696 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10CD37:roller#event triggered ROLLER_CLOSE

2022-08-29 20:43:13.032 [vent.ItemStateChangedEvent] - Rollo_Kueche changed from 100 to 0.0

2022-08-29 20:43:13.053 [vent.ItemStateChangedEvent] - Rollo_Schreibtisch changed from 100 to 0.0

2022-08-29 20:43:29.782 [vent.ItemStateChangedEvent] - KE_Treppe changed from OFF to ON

2022-08-29 20:43:29.790 [GroupItemStateChangedEvent] - gMoveKorrEG changed from OFF to ON through KE_Treppe

2022-08-29 20:43:29.798 [GroupItemStateChangedEvent] - gMovement changed from OFF to ON through gMoveKorrEG

2022-08-29 20:43:29.805 [GroupItemStateChangedEvent] - gMoveKeller changed from OFF to ON through KE_Treppe

2022-08-29 20:43:32.647 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10CD37:roller#event triggered ROLLER_STOP

2022-08-29 20:43:33.103 [vent.ItemStateChangedEvent] - Rollo_Schreibtisch changed from 0.0 to 100.0

2022-08-29 20:43:33.622 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10A300:roller#event triggered ROLLER_STOP

2022-08-29 20:43:33.869 [vent.ItemStateChangedEvent] - Rollo_Kueche changed from 0.0 to 100.0

2022-08-29 20:43:42.063 [GroupItemStateChangedEvent] - gMoveKeller changed from ON to OFF through KE_Treppe

2022-08-29 20:43:42.069 [GroupItemStateChangedEvent] - gMovement changed from ON to OFF through gMoveKeller

2022-08-29 20:43:42.076 [GroupItemStateChangedEvent] - gMoveKorrEG changed from ON to OFF through KE_Treppe

2022-08-29 20:43:42.082 [vent.ItemStateChangedEvent] - KE_Treppe changed from ON to OFF

2022-08-29 20:43:42.088 [GroupItemStateChangedEvent] - gMovement changed from ON to OFF through gMoveKorrEG

2022-08-29 20:44:12.458 [ome.event.ItemCommandEvent] - Item 'Rollo_Terassentuer' received command DOWN

2022-08-29 20:44:12.484 [ome.event.ItemCommandEvent] - Item 'Rollo_Couch' received command DOWN

2022-08-29 20:44:12.489 [nt.ItemStatePredictedEvent] - Rollo_Terassentuer predicted to become DOWN

2022-08-29 20:44:12.507 [nt.ItemStatePredictedEvent] - Rollo_Couch predicted to become DOWN

2022-08-29 20:44:12.534 [vent.ItemStateChangedEvent] - Rollo_Terassentuer changed from 0.0 to 100

2022-08-29 20:44:12.539 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 0.0 to 100

2022-08-29 20:44:12.564 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:C4C90F:roller#event triggered ROLLER_CLOSE

2022-08-29 20:44:13.041 [vent.ItemStateChangedEvent] - Rollo_Terassentuer changed from 100 to 0.0

2022-08-29 20:44:13.054 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 100 to 0.0

2022-08-29 18:44:32.852 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 0.0 to 100.0

2022-08-29 18:44:39.369 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:C4C90F:roller#event triggered ROLLER_STOP

2022-08-29 18:44:39.790 [vent.ItemStateChangedEvent] - Rollo_Terassentuer changed from 0.0 to 100.0

2022-08-29 18:44:46.068 [ome.event.ItemCommandEvent] - Item 'Rollo_Kueche' received command UP

2022-08-29 18:44:46.106 [nt.ItemStatePredictedEvent] - Rollo_Kueche predicted to become UP

2022-08-29 18:44:46.131 [vent.ItemStateChangedEvent] - Rollo_Kueche changed from 100.0 to 0

2022-08-29 18:44:46.161 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10A300:roller#event triggered ROLLER_OPEN

2022-08-29 18:44:46.656 [vent.ItemStateChangedEvent] - Rollo_Kueche changed from 0 to 100.0

2022-08-29 18:44:49.223 [ome.event.ItemCommandEvent] - Item 'Rollo_Couch' received command UP

2022-08-29 18:44:49.260 [nt.ItemStatePredictedEvent] - Rollo_Couch predicted to become UP

2022-08-29 18:44:49.288 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 100.0 to 0

2022-08-29 18:44:49.834 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 0 to 100.0

2022-08-29 18:44:54.067 [vent.ItemStateChangedEvent] - OG_Korridor_Helligkeit2 changed from 22.0 lx to 8.0 lx

2022-08-29 18:45:06.833 [vent.ItemStateChangedEvent] - Rollo_Couch changed from 100.0 to 0.0

2022-08-29 18:45:07.368 [vent.ChannelTriggeredEvent] - shelly:shelly25-roller:10A300:roller#event trig

I thought my main time-source is a FRITZBox, which provides the time for the whole network (ntp.1und1.de). Dont see anything strange in the logfiles there. A few month ago I added an entry in etc/systemd/timesyncd.conf

openhabian@openhabian:/etc/systemd $ cat timesyncd.conf
#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
#
# See timesyncd.conf(5) for details.

[Time]
NTP=fritz.box
FallbackNTP=0.debian.pool.ntp.org 1.debian.pool.ntp.org 2.debian.pool.ntp.org 3.debian.pool.ntp.org
#RootDistanceMaxSec=5
#PollIntervalMinSec=32
#PollIntervalMaxSec=2048

but it seems it didnt help. Any thoughts ? I can provide other info, will most probably require some assistance to dig it out - as I’m not very firm with linux.
Cheers Frank

“jumping” by an exact two hours suggests something to do with timezones.

There are at least three places where timezones can be configured that affects openHAB. The operating system, the Java system, and OH itself. All potentially may have timezone/locale set to something different.

In addition to these three amigos, if you use a local NTP service there’s another source of confusion, as that might be set up to a different zone.

In the case of log timestamping, the logger is using Java time (not OH time), so we know that one is being altered at least.

As an openhabian user … I don’t know, but does that set up an NTP for you? So maybe you have two NTP sources with conflicting opinions about locale?

As a first look, establish your three host timezone settings, also the Fritz, and review what openhabian might have done with NTP

1 Like

Hi there,
meanwhile I checked a few things.

  1. Openhab Paper UI is set to Europe/Berlin.
  2. operating system gives
openhabian@openhabian:~ $ timedatectl status
               Local time: Wed 2022-09-14 19:57:43 CEST
           Universal time: Wed 2022-09-14 17:57:43 UTC
                 RTC time: n/a
                Time zone: Europe/Berlin (CEST, +0200)
System clock synchronized: no
              NTP service: inactive
          RTC in local TZ: no

So this explains, why obviously the NTP service from my router is not used. I did change the NTP source from my ISP to PtB, because I thought it may be my ISP a week ago.
I had today again a jump and at that time I did check the logging in my router - which still had the correct time. But again - if NTP is not used then it doesnt matter at all.
So I checked the operating system again with this command and output:

timedatectl show-timesync --all
LinkNTPServers=
SystemNTPServers=
FallbackNTPServers=0.debian.pool.ntp.org 1.debian.pool.ntp.org 2.debian.pool.ntp                                          .org 3.debian.pool.ntp.org
ServerName=0.debian.pool.ntp.org
ServerAddress=(null)
RootDistanceMaxUSec=5s
PollIntervalMinUSec=32s
PollIntervalMaxUSec=34min 8s
PollIntervalUSec=0
Frequency=0

So my problem is obviously that OH is without NTP. But as I have posted above I did edit timesyncd.conf. Could it be worth a trial to replace “fritz.box” by the IP adress? Or do I need to configure it somewhere else?
Thanks and cheers

Don’t forget to check Java locale/timezone. This is independent of both host OS and openHAB settings.

To be honest I don’t find it. I did find that there should be zone.information in Java/lib/zi but I dont have that folder. I have Zulu8-jdk active.

java -version
openjdk version "1.8.0_322"
OpenJDK Runtime Environment (Zulu 8.60.0.21-CA-linux_aarch32hf) (build 1.8.0_322-b06)
OpenJDK Client VM (Zulu 8.60.0.21-CA-linux_aarch32hf) (build 25.322-b06, mixed mode)

But isn’t the problem that NTP service is not active at all on my Raspi??

timesysnc daemon/service is running and status is ok ?

sudo systemctl status systemd-timesyncd.service

In system log file you see that the service is syncing the time ?

sudo fgrep timesync /var/log/syslog /var/log/syslog.1

It happens to me that the timesyncd-service is not coming up after a server-restart. But here a small workaround:

vi /usr/lib/systemd/system/systemd-timesyncd.timer
[Unit]
Description=Start time synchronisation (workaround)

[Timer]
OnBootSec=30

[Install]
WantedBy=timers.target
systemctl daemon-reload

systemctl start systemd-timesyncd.timer
systemctl enable systemd-timesyncd.timer
systemctl status systemd-timesyncd.timer

I’m not sure how a service that is not running is going to change your timer clock like you describe happening.
Having a working NTP auto-update is just going to change it back, not stop it messing about.

My suspicion would still be that there is some hidden NTP doing the wrong thing periodically.
Alternatively, something somewhere is changing Java locale setting (not the clock itself), then changing it back. Seems really unlikely.

I think you can do this on the console to find what Java thinks

Hi there,
I try to comment on everything

  1. env | grep timezone shows nothing
    2)sudo systemctl status systemd-timesyncd.service shows

lines 1-14/14 (END)
● systemd-timesyncd.service - Network Time Synchronization
     Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2022-09-14 20:07:26 CEST; 21h ago
       Docs: man:systemd-timesyncd.service(8)
   Main PID: 12638 (systemd-timesyn)
     Status: "Initial synchronization to time server 178.215.228.24:123 (0.debian.pool.ntp.org)."
      Tasks: 2 (limit: 2178)
        CPU: 876ms
     CGroup: /system.slice/systemd-timesyncd.service
             └─12638 /lib/systemd/systemd-timesyncd

Sep 14 20:07:25 openhabian systemd[1]: Starting Network Time Synchronization...
Sep 14 20:07:26 openhabian systemd[1]: Started Network Time Synchronization.
Sep 14 20:07:26 openhabian systemd-timesyncd[12638]: Initial synchronization to time server 178.215.228.24:123 (0.debian.pool.ntp.org).

lines 1-14/14 (END)

I wonder what happened yesterday - I did neither reboot nor spotted a timeslip

  1. sudo fgrep timesync /var/log/syslog /var/log/syslog.1 shows
 sudo fgrep timesync /var/log/syslog /var/log/syslog.1
/var/log/syslog:Oct 30 12:30:13 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 11:40:29 openhabian systemd-timesyncd[621]: Initial synchronization to time server 176.9.1.211:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 11:43:22 openhabian systemd-timedated[2972]: Set NTP to enabled (systemd-timesyncd.service).
/var/log/syslog:Mar  4 13:28:52 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 13:29:05 openhabian systemd-timesyncd[626]: Initial synchronization to time server 192.168.200.1:123 (192.168.200.1).
/var/log/syslog:Mar  4 13:29:05 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 13:29:06 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 13:29:07 openhabian systemd-timesyncd[721]: Initial synchronization to time server 203.29.242.183:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 13:31:34 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 13:31:49 openhabian systemd-timesyncd[610]: Initial synchronization to time server 203.29.242.183:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 13:39:51 openhabian systemd-timesyncd[317]: System clock time unset or jumped backwards, restoring from recorded timestamp: Fri 2022-03-04 13:39:50 CET
/var/log/syslog:Mar  4 13:39:53 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 13:41:22 openhabian systemd-timesyncd[608]: Initial synchronization to time server 131.188.3.223:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 14:07:08 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:07:25 openhabian systemd-timesyncd[608]: Initial synchronization to time server 131.234.220.232:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 14:22:45 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:23:01 openhabian systemd-timesyncd[614]: Initial synchronization to time server 192.168.200.1:123 (192.168.200.1).
/var/log/syslog:Mar  4 14:23:02 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:23:02 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:23:03 openhabian systemd-timesyncd[709]: Initial synchronization to time server 130.255.77.87:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 14:32:10 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:32:27 openhabian systemd-timesyncd[608]: Initial synchronization to time server 85.214.46.39:123 (0.debian.pool.ntp.org).
/var/log/syslog:Mar  4 14:50:23 openhabian systemd[1]: systemd-timesyncd.service: Succeeded.
/var/log/syslog:Mar  4 14:50:40 openhabian systemd-timesyncd[617]: Initial synchronization to time server 213.239.234.28:123 (0.debian.pool.ntp.org).
grep: /var/log/syslog: binary file matches
grep: /var/log/syslog.1: No such file or directory

the IP adress 192.168.200.1 is my FritzBox - so it seems to work “sometimes”

Sorry

  1. shows something of course:
openhab> env | grep timezone
String          user.timezone   Europe/Berlin

but sometime / long time ago …
Entries seem to be from october resp. march …

I could certainly try to investigate on the timezones again, if I spot a timeslip. If one of the 3 timezone settings is to blame, then I should see one or more of them different.
The problem is only, that I spot the timeslip only, if a timer fires wrongly - and then I need to be at my PC. So it could take months or even not happen at all. Probably need a script which reads entries in the log and alerts if an entry is 2hours upfront the previous entry.
Cheers Frank

Feeling in my gut is not really about static system timezone settings; more about getting NTP style ‘corrections’ from two different sources, one of which has an incorrect timezone set.
I’ve no idea how you track down all possible NTP influences.

Well the only thing which could help more is the change to “winter time”. There we will have only one hour difference to GMT. If I spot a slip during winter and this time the slip will only be one hour, than this would point at a time zone/ conversion error - something like a process gets time and converts this to local time by adding one hour (but in reality it gets already local time).
Not sure if this makes sense - and no idea, how to “catch” the timeslip. Really aiming at a quite stable “smart home” here but probably the frequency of spotted errors is not high enough to cause huge effort.
Cheers