time jumping back

Tue Feb 25 18:45:08 UTC 2014

Michal Jaegermann wrote:

> On Tue, Feb 25, 2014 at 11:12:49AM +0100, Miroslav Lichvar wrote:
>> On Sun, Feb 23, 2014 at 01:00:11PM -0700, Chris Murphy wrote:
>> 
>> Are there any interesting messages in syslog near that jump? Both ntpd
>> and chronyd in their default configuration log a message when they
>> step the clock, but chronyd steps the clock only on start.
> 
> AFAIK both chronyd and ntpd are not supposed to force any significant
> time jumps in a normal operation, except when forced on a startup to
> perform an initial adjustment, and only vary slightly frequencies for a
> gradual synchronization.
> 
> As a matter of fact I did not omit any log entries around both jumps
> when I qouted what I found in initial messages.
> 
>> Also,
>> chronyd will log a message if it detects that something else has
>> stepped the clock backwards.
> 
> Searching through an output of journalctl when time was messed up
> turns out to be not that obvious and I may missed some clues.
> Apparently the first backjump may have happened about the same time.
> Maybe.   In any case these are timelines I managed to dig out.
> 
> On a machine with chronyd:
> 
> Feb 21 09:25:46  --- dbus-daemon reports failure for unit
> 'dbus-org.freedesktop.ModemManager1.service'
> Jan 02 13:40:22  ---- systemd[750]: Time has been changed
>      The system clock has been changed to REALTIME microseconds after January
>      1st, 1970.
> Jan 02 13:40:22 --- systemd[1]: Time has been changed ....
> Jan 02 13:40:22 --- systemd[10804]: Time has been changed ....
> Jan 02 13:41:57 --- dbus-daemon tries again and fails
> 'dbus-org.freedesktop.ModemManager1.service'
> ........   (more "Time has been changed" from various systemd processes
>             followed by some messages from chronyd at last)
> Jan 02 14:15:07 --- chronyd[495]: Backward time jump detected!  (correction
> 4302802.2 +- 1.0 seconds) Jan 02 14:16:22 --- chronyd[495]: Selected source
> 198.245.50.148 Jan 02 14:16:22 --- chronyd[495]: System clock wrong by
> 4302802.312517 seconds, adjustment started
> Jan 02 14:16:22 --- smartd[502]: System clock time adjusted to the past. 
> Resetting next wakeup time.
> 
> 198.245.50.148 is vela.z0p.org but it is not selected explicitely but
> one of pool time servers and this likely be something else on the next
> startup.  In any case chronyd detected a wrong clock but skewing that
> amount will take a long while.
> 
> On the other machine with ntpd this looks like follows (with multiple
> time gaps):
> 
> Feb 21 09:10:16 --- dbus-daemon reports failure for unit
> 'dbus-org.freedesktop.ModemManager1.service' Feb 20 23:22:01 --- systemd[1]:
> Time has been changed Feb 20 23:22:01 --- systemd[12162]: Time has been
> changed Feb 20 23:22:01 --- systemd[2717]: Time has been changed
> ............. (various unrelated activities)
> Feb 20 00:01:02 --- systemd[2717]: Time has been changed    !!!!!!
> Feb 20 00:01:02 --- systemd[12162]: Time has been changed  (and more of
> similar) Feb 20 00:14:39 --- dbus[557]: [system] Activation via systemd failed
> for unit 'dbus-org.freedesktop.ModemManager1.service' Feb 20 23:01:01 ---
> systemd[12162]: Time has been changed
> ............  (followed by the first log entry from ntpd)
> Feb 20 23:18:20 --- ntpd[602]: 0.0.0.0 0618 08 no_sys_peer
> .....
> Feb 21 01:05:55 --- ntpd[602]: 0.0.0.0 0617 07 panic_stop +36679 s; set clock
> manually within 1000 s. Feb 21 01:05:55 --- systemd[1]: ntpd.service: main
> process exited, code=exited, status=255/n/a Feb 21 01:05:55 --- systemd[1]:
> Unit ntpd.service entered failed state.
> 
> Time was restored when I caught up and started ntpd manually
> 
> So far nothing like that happened again.
> 
>    Michal

Don't know if it's related, but I just saw this:

Feb 25 12:06:18 nbecker7 kernel: [   59.015938] Ebtables v2.0 registered
Feb 25 12:06:18 nbecker7 kernel: [   59.601221] ip6_tables: (C) 2000-2006 
Netfilter Core Team
Feb 25 12:06:18 nbecker7 kernel: [   65.646938] Bridge firewalling registered
Feb 25 12:06:18 nbecker7 kernel: [   65.671316] device virbr0-nic entered 
promiscuous mode
Feb 25 12:06:18 nbecker7 kernel: [   66.410670] virbr0: port 1(virbr0-nic) 
entered listening state
Feb 25 12:06:18 nbecker7 kernel: [   66.410678] virbr0: port 1(virbr0-nic) 
entered listening state
Feb 25 12:06:18 nbecker7 kernel: [   66.410724] IPv6: ADDRCONF(NETDEV_UP): 
virbr0: link is not ready
Feb 25 12:06:18 nbecker7 kernel: [   66.668588] virbr0: port 1(virbr0-nic) 
entered disabled state
Feb 25 12:06:54 nbecker7 kernel: [  109.855407] fuse init (API version 7.22)
Jan  8 10:48:32 nbecker7 systemd: Stopped target Graphical Interface.
Jan  8 10:48:32 nbecker7 systemd: Stopping Multi-User System.
Jan  8 10:48:32 nbecker7 systemd: Stopped target Multi-User System.
Jan  8 10:48:32 nbecker7 systemd: Stopping ABRT kernel log watcher...
Jan  8 10:48:32 nbecker7 systemd: Stopping Command Scheduler...
Jan  8 10:48:32 nbecker7 systemd: Stopping Install ABRT coredump hook...
Jan  8 10:48:32 nbecker7 systemd: Stopping ABRT Xorg log watcher...