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
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:
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
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
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
Some news from my side. Those days I checked an update for the connected ConbeeII stick. When checking the settings in the Phoscon-Interface I suddenly discovered a “timezone” setting, which was set to GMT. I do not remember that I touched this in the past, probably it came with an update and was left on default. Did set it to my actual timezone. Since my last post I did not spot any timeslips - so no idea if this was the reason and the correction fixed it.
Cheers Frank
