8

I saw a strange system time changing behavior in some (hardware) servers: in /var/logs/syslog, the date time preceding each log message sometimes change to a random one and gets back to normal in the next message, like the following:

Feb 22 2018 09:09:30 ...
Feb 22 2018 09:09:32 ...
Jan 13 2610 15:37:42 ...
Feb 22 2018 09:09:33 ...
Feb 22 2018 09:09:34 ...

As in the example, the sudden change of date time can be as far as hundreds of years away.

I can confirm that the log messages having the strange time stamps does not come from any specific process - it just can happen randomly for every one.

And duration between 2 abnormal time changes varies between a few minutes to a few hours (however, I suspect the abnormal time changes could happen more frequently but many of them are not revealed in the syslog, since it is not writing logs every second).

Also, since it happens on more than one server, I assume it is not a hardware problem.

More info about the severs: they are an openstack installation with one controller and a few compute nodes. Each server has ntp service running. The controller is configured to take time from its own hardware clock, and the compute node servers sync time from the controller. Note that each server have abnormal time changes at its own pace - looks like the "wrong time" is not synchronized from the controller through ntp.

I was suspecting the guest systems (virtual machines) on compute nodes could affect their host system time. But this can not explain why the controller has the same problem while not running any virtual machine.

I need a method to detect: who changed the system time and how does it happen?

  • 2
    Can you show the output of a hwclock loop? Something as: while true; do hwclock; sleep 5; done – shodanshok Aug 9 '18 at 8:27
  • each server has ntp service running: as client or as server? via systemd or outside of systemd via "old" ntp service? for me this looks like a providing ntp time issue. we had this issue that we did write logfiles before our time was synced (before having network connectivity, resulting in jumps of timestamps) systemd has a target you might want to rely on systemd[1]: Time has been changed systemd[1]: Reached target System Time Synchronized. – Dennis Nolte Aug 14 '18 at 10:27
  • it looks like some date fetching is running as a cron and doesn't have very good time checking. Find it, remove it and replace with ntpd which doesn't respond to large time drifts. – danblack Aug 18 '18 at 6:11
  • We have new findings and found the problem can be narrowed down to CRON messages being delayed in syslog. So I posted another question . Please take a look there. – Zhaohui Yang Aug 21 '18 at 4:25
  • 3
    Maybe this is your error: Unexplainable time jumps in CRON it was patched in rsyslog - 7.4.4-1ubuntu2.7. – Stone Sep 3 '18 at 12:50
1

This script will tell you when a time drift occurs and the difference in the process tree, and this should help identify this if it is caused by a process changing the system time. It will print to the terminal as well as log into timedrift.log inside the current working directory.

#!/bin/bash

oldTime="$(date +%s)"
oldPsOutput="$(ps faux)"
while true; do
  sleep 1;
  currentTime="$(date +%s)"
  oldTimeplusfive="$((($oldTime+5)))"
  currentPsOutput="$(ps faux)"
  if [[ "$currentTime" -lt "$oldTime" ||  "$currentTime" -gt "$oldTimeplusfive"  ]]
  then
    (
        echo -e '\n\n======================='
        echo "currentTime=$currentTime oldTime=$oldTime oldTimeplusfive=$oldTimeplusfive"
        echo '-----------------------'
        echo "$oldPsOutput"
        echo '::::::::::::::::::::::::::'
        echo "$currentPsOutput"
    ) | tee -a timedrift.log
  fi
  oldPsOutput=$currentPsOutput
  oldTime=$currentTime
done

Credit to the original script in the Unexplainable time jumps in CRON bug that Stone mentioned as a comment.

Can you also comment as if you are using rsyslog and if so what version? Do you see it outside the realm of rsyslog (ie. apache logs, etc). This bug looks simmlar, and it would nice to confirm it or rule it out either way.

0

Actually this is a duplicate of @Stone 's comment. Just make it clear to everyone this do have an answer.

In short, there is a bug in the version of rsyslog I'm using. Which will delay syslog message it received for arbitrary length of time. Bug report is here. And upgrading rsyslog solved the problem. It is not the kernel or CRON's fault.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.