0

I read systemd log of my home server using journalctl and I've noticed that the timestamp of log is totally out of order.

Here's some logs from my server using journalctl -o=short-iso --since=yesterday :

2015-06-17T06:00:22+0900 alarm smbd[463]: [2015/06/17 06:00:22.911093,  0] ../source3/printing/print_standard.c:69(std_pcap_cache_reload)
2015-06-17T06:00:22+0900 alarm smbd[463]: Unable to open printcap file /etc/printcap for read!
2015-06-17T06:13:23+0900 alarm smbd[463]: [2015/06/17 06:13:23.161572,  0] ../source3/printing/print_standard.c:69(std_pcap_cache_reload)
2015-06-17T06:13:23+0900 alarm smbd[463]: Unable to open printcap file /etc/printcap for read!
-- Reboot --
1970-01-01T09:00:06+0900 alarm systemd-journal[179]: Runtime journal is using 8.0M (max allowed 87.5M, trying to leave 131.2M free of 867.2M available <E2><86><92> current limit 87.5M).
-- Reboot --
1970-01-01T09:00:06+0900 alarm systemd-journal[177]: Permanent journal is using 336.0M (max allowed 2.9G, trying to leave 420.5M free of 25.2G available <E2><86><92> current limit 2.9G).
1970-01-01T09:00:06+0900 alarm systemd-journal[177]: Time spent on flushing to /var is 5.440ms for 2 entries.
1970-01-01T09:00:06+0900 alarm kernel: Booting Linux on physical CPU 0x0
1970-01-01T09:00:06+0900 alarm kernel: Initializing cgroup subsys cpuset

....

1970-01-01T09:00:21+0900 alarm systemd[1]: Started Update is Completed.
1970-01-01T09:00:21+0900 alarm systemd[1]: Started Create Volatile Files and Directories.
1970-01-01T09:00:21+0900 alarm systemd[1]: Starting Network Time Synchronization...
1970-01-01T09:00:21+0900 alarm systemd[1]: Starting Update UTMP about System Boot/Shutdown...
-- Reboot --
1970-01-01T09:00:05+0900 alarm systemd-timesyncd[187]: System clock time unset or jumped backwards, restoring from recorded timestamp: Thu 2014-07-03 18:46:22 UTC
2014-07-04T03:46:22+0900 alarm systemd[1]: Time has been changed
2014-07-04T03:46:22+0900 alarm systemd[1]: Started Network Time Synchronization.
2014-07-04T03:46:22+0900 alarm systemd[1]: Starting System Time Synchronized.
2014-07-04T03:46:22+0900 alarm systemd[1]: Reached target System Time Synchronized.

...

2014-07-04T03:50:45+0900 alarm dhcpcd[324]: eth0: adding default route via 192.168.0.1
2014-07-04T03:50:45+0900 alarm systemd-timesyncd[187]: Network configuration changed, trying to establish connection.
2014-07-04T03:50:45+0900 alarm systemd-timesyncd[187]: Network configuration changed, trying to establish connection.
2014-07-04T03:50:46+0900 alarm systemd-timesyncd[187]: Using NTP server 216.239.32.15:123 (time4.google.com).
2014-08-30T12:21:54+0900 alarm systemd[255]: Time has been changed
2014-08-30T12:21:54+0900 alarm systemd-timesyncd[187]: interval/delta/delay/jitter/drift 32s/+4955468.150s/0.322s/0.000s/+0ppm
2014-08-30T12:21:54+0900 alarm systemd[1]: Time has been changed
2014-08-30T12:21:54+0900 alarm systemd[1]: Starting Verify integrity of password and group files...

...

2014-08-30T14:12:57+0900 alarm systemd-timesyncd[185]: Network configuration changed, trying to establish connection.
2014-08-30T14:12:57+0900 alarm systemd-timesyncd[185]: Network configuration changed, trying to establish connection.
2014-08-30T14:13:27+0900 alarm systemd-timesyncd[185]: Using NTP server 216.239.36.15:123 (time3.google.com).
2014-09-05T20:47:48+0900 alarm systemd[1]: Time has been changed
2014-09-05T20:47:48+0900 alarm systemd-timesyncd[185]: interval/delta/delay/jitter/drift 32s/+542061.386s/0.335s/0.000s/+0ppm
2014-09-05T20:48:21+0900 alarm systemd-timesyncd[185]: interval/delta/delay/jitter/drift 64s/+0.002s/0.338s/0.001s/+0ppm
2014-09-05T20:49:35+0900 alarm systemd-timesyncd[185]: Timed out waiting for reply from 216.239.36.15:123 (time3.google.com).

....

2014-09-06T22:48:10+0900 alarm systemd[1]: Starting Shutdown.
2014-09-06T22:48:10+0900 alarm systemd[1]: Reached target Shutdown.
2014-09-06T22:48:10+0900 alarm systemd[1]: Starting Final Step.
2014-09-06T22:48:10+0900 alarm systemd[1]: Reached target Final Step.
2014-09-06T22:48:10+0900 alarm systemd[1]: Starting Power-Off...
2014-09-06T22:48:10+0900 alarm systemd[1]: Shutting down.
2014-09-06T22:48:10+0900 alarm systemd-shutdown[1]: Sending SIGTERM to remaining processes...
2014-09-06T22:48:10+0900 alarm systemd-journal[167]: Journal stopped
-- Reboot --
1970-01-01T09:00:04+0900 alarm systemd-journal[169]: Runtime journal is using 8.0M (max allowed 87.5M, trying to leave 131.2M free of 867.2M available <E2><86><92> current limit 87.5M).
1970-01-01T09:00:04+0900 alarm systemd-journal[169]: Runtime journal is using 8.0M (max allowed 87.5M, trying to leave 131.2M free of 867.2M available <E2><86><92> current limit 87.5M).
1970-01-01T09:00:04+0900 alarm kernel: Booting Linux on physical CPU 0x0

...

As you can see, there are lots of discontinuation and jump back and forward of timestamp. This is only a snippet and there are much more such points.

I've checked my time setting but I couldn't find anything wrong:

$ timedatectl status
      Local time: Thu 2015-06-18 16:46:44 KST
  Universal time: Thu 2015-06-18 07:46:44 UTC
        RTC time: Thu 2015-06-18 07:46:44
       Time zone: Asia/Seoul (KST, +0900)
     NTP enabled: yes
NTP synchronized: yes
 RTC in local TZ: no
      DST active: n/a

How can I fix this mess?

My environment:

  • Device: Wandboard Quad(it's a single board computer)
  • OS: Arch Linux ARM
1

It looks to me that your systems clock is not functioning, probably because of the battery not, or no longer providing enough current to keep the clock going during restart. (If the clock chip where bad, you should get a different error, ntpd should notice).

That is why you reboot in 1970 when the "Unix era" starts.

When ntpd starts it hears from the rest of the world that the clock was not working and sets the time & date accordingly

1970-01-01T09:00:21+0900 alarm systemd[1]: Starting Network Time Synchronization...
1970-01-01T09:00:21+0900 alarm systemd[1]: Starting Update UTMP about System Boot/Shutdown...
-- Reboot --
1970-01-01T09:00:05+0900 alarm systemd-timesyncd[187]: System clock time unset or jumped backwards, restoring from recorded timestamp: Thu 2014-07-03 18:46:22 UTC

You should be able to save the date on shutdown and at least continue with that value instead of 1970, but it is better to replace the clock's battery.

  • Hmm, I'm using a single board computer for my server so-called Wandboard Quad. I don't see any battery on device. Maybe, I have to change the external power supply, then. Thank you. – xylosper Jun 18 '15 at 8:29
  • @xylosper That machine doesn't seem to [have a timer at all}(digikey.com/~/media/Images/Product%20Highlights/W/Wandboard/…) that would mean it cannot retain the time between reboots. Saving the time before shutdown and restoring it with ntpdate or something similar would at least set the time to something closer to the current time. – Anthon Jun 18 '15 at 8:34
  • @xylosper Maybe this can help you out. – Anthon Jun 18 '15 at 8:40
  • Thank you. I've just rebooted my device but I cannot see any discontinuation in log: Jun 18 17:51:11 alarm systemd-journal[171]: Journal stopped -- Reboot -- Jun 18 17:51:26 alarm systemd-journal[161]: Runtime journal ...<omit> – xylosper Jun 18 '15 at 8:53
  • Oops, sorry. I've just tried cold reset and yeah, it resets timestamp. Thank you. I'll try your suggestion. Jun 18 17:53:26 alarm systemd[1]: Starting Update DDNS for dnszi.com... -- Reboot -- Jan 01 09:00:08 alarm systemd-timesyncd[258]: System clock time unset or jumped backwards, restoring from recorded timestamp: Thu 2015-06-18 17:53:45 KST Jun 18 17:53:45 alarm systemd[1]: Time has been changed – xylosper Jun 18 '15 at 8:57

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.