☰

システムログの無効なタイムスタンプ

tag-icon • tag-icon systemd logs timestamps systemd-journald
システムログの無効なタイムスタンプ

私はホームサーバーのシステムログを読み取っていましたが、ログjournalctlのタイムスタンプが完全に間違っていることがわかりました。

私のサーバーのいくつかのログは次のとおりです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

...

ご覧のとおり、タイムスタンプの中断と前後に移動がたくさんあります。これは単なる断片に過ぎず、このような点がたくさんあります。

時間設定を確認しましたが、間違った点が見つかりませんでした。

$ 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

この混乱をどのように解決しますか？

私の環境：

  • 機器：4つの杖プレート（シングルボードコンピュータです）
  • オペレーティングシステム：Arch Linux ARM

答え1

私が見ると、システムクロックが正しく機能していないようです。それはおそらく、バッテリーが再起動中に時計を動作し続けるのに十分な電流を供給しないか、もはや提供しないからです。 （クロックチップが不良の場合は他のエラーが発生し、ntpdがそれを認識する必要があります）。

それで「UNIX時代」が始まった1970年にリブートをされたのです。

起動すると、ntpd世界中で時計が機能していないというニュースを聞き、それに応じて時間と日付を設定します。

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

終了時に日付を保存し、少なくとも1970年の代わりにその値を引き続き使用できるようにする必要がありますが、時計のバッテリーを交換することをお勧めします。

関連情報