9

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?

  • Is the shown timestamps actual timestamps? Do you have more examples to show? – Kusalananda Aug 7 '18 at 7:59
  • Are the servers in question blade servers? If so, then the blade chassis management unit might be attempting to sync the clocks of individual server blades. Knowing the actual server model would be necessary for looking up known clock hardware bugs. – telcoM Aug 7 '18 at 8:04
  • Can you also monitor HW time - hwclock ? If it changes at that time too... – Jaroslav Kucera Aug 7 '18 at 8:22
  • 2
    Note that syslogd simply writes the contents of the message it was sent from whatever process to the appropriate log file; the timestamp is actually sent within the message, it's not generated by syslogd. So perhaps something is corrupting the messages, or if it is one type of process, perhaps that process is sending buggy syslog messages. FYI the format is described by RFC3164; the date/time part is sent in plain ASCII. – wurtel Aug 7 '18 at 9:15
  • Please put all of the information from the multi-posted duplicate at superuser.com/questions/1298404 in the question. – JdeBP Aug 7 '18 at 11:31
0

The relevant aspects are the kernel versions and these lines from early in the boot process:

kernel: Fast TSC calibration using PIT
...
kernel: Calibrating delay loop (skipped), value calculated using timer frequency..
...
kernel: Switching to clocksource tsc

YMMV and you may not be using TSC or PIT

AFAIK this is a bug that's caused by the clock of at least one of your CPUs being out of sync, in your case probably running too fast.

It should be easy to confirm by running this:

for cpu in {0..8} ; do taskset -c $cpu date ; done

which will run date against each cpu (assuming you have up to 8 cores/threads). If my guess is correct then one of your CPUs will consistently have the wrong time.

If that's the case then you should first try upgrading the kernel and if that doesn't work, fiddle with the clocksource boot parameter (assuming it's x86-64):

clocksource=    Override the default clocksource
                Format: <string>
                Override the default clocksource and use the clocksource
                with the name specified.
                Some clocksource names to choose from, depending on
                the platform:
                [all] jiffies (this is the base, fallback clocksource)
                [ACPI] acpi_pm
                ...
                [X86-64] hpet,tsc

See also the output of this:

cat /sys/devices/system/clocksource/clocksource*/available_clocksource
0

It looks like the hardware clock on your controller server is not a stable resource of information about the time. You should configure your controller to sync it's type with more reliable atomic clock.

This is the command you can use to update your hardware clock: hwclock -s

See also:

   -s, --hctosys
          Set the System Time from the Hardware Clock.

          Also set the kernel's timezone value to the local timezone as indicated by the TZ environment variable and/or /usr/share/zoneinfo, as tzset(3) would interpret them.  The obsolete tz_dsttime field of the kernel's time‐
          zone value is set to DST_NONE.  (For details on what this field used to mean, see settimeofday(2).)

          This is a good option to use in one of the system startup scripts.

   -w, --systohc
          Set the Hardware Clock to the current System Time.
0

copied from: CRON messages being delayed for arbitrary long time in syslog:

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 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.