HOWTO use journalctl when faced with time warps #908

marc-hb · 2022-05-20T00:00:41Z

marc-hb
May 20, 2022
Maintainer

Summary: in case of time warps, always look at A SINGLE BOOT AT A TIME thanks to the journalctl -b -N option. Otherwise journalctl will (wrongly?) sort log statements based on their (possibly wrong) timestamps and interleave logs from different boots, which is extremely confusing.

See example below where the start of the second boot with wrong time 11:45:22 was moved up and interleaved with the previous boot.

Context: for testing purposes we usually disconnect laptop batteries in the lab. This allows power-cycling them remotely. With most laptops this is OK but with some power cycling can cause "time warps" which make the output of journalctl (and of probably other similar logging systems) extremely confusing.

Desktop systems with a coin cell battery are not affected.

Every journalctl record has a __BOOT_ID field which unlike timestamps is always correct. You can see the __BOOT_ID of each line using journalctl -o json-pretty

journalctl prints a -- Reboot -- everytime the __BOOT_ID changes. So -- Reboot -- does NOT mean there was actually a reboot! In the example below you can see that there are many more -- Reboot -- lines than actual reboots.

You must mentally translate -- Reboot -- into: now showing you some logs from a different boot. It's normally because of a reboot but not always.

The -b option selects a single __BOOT_ID which is great because the __BOOT_ID is always correct.

Caveat: I do not guarantee that using -b is a silver bullet and it solves every time warp issue but in this example below it is a silver bullet and it does get rid of the interleaving completely.

Warning you cannot fully trust the timestamps in the output of journalctl --list-boots either. But again, thanks to the magic of the _BOOT_ID the number of boots in --list-boots is correct.

        __BOOT_ID

 -3 727fb0d118e242a68faa463e44a47208 Thu 2022-05-19 09:22:23 UTC—Thu 2022-05-19 11:30:04 UTC
 -2 a41196ed0b5a4ae9810a9c222aa83deb Thu 2022-05-19 11:30:26 UTC—Thu 2022-05-19 11:44:29 UTC
 -1 4aafbba1586740878938eb06b0748218 Thu 2022-05-19 11:44:50 UTC—Thu 2022-05-19 11:50:02 UTC    <== end time 11:50:02 is wrong and does not match anything. Last time in that boot was 12:11:59
  0 4ac6834046f84e7296e46399f554fd33 Thu 2022-05-19 12:01:53 UTC—Thu 2022-05-19 22:36:21 UTC    <== start time does not match the `journalctl -b 0` output. It matches "restoring from recorded timestamp..."

PS: I wonder why boots and records don't have a simple sequence number.

May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Reboot.
May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd[1]: Reached target Reboot.
May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd[1]: Shutting down.
May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd-shutdown[1]: Syncing filesystems and block devices.
May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd-shutdown[1]: Sending SIGTERM to remaining processes...
May 19 11:44:29 jf-tglu-sku0a32-sdca-03 systemd-journald[254]: Journal stopped

-- Reboot --   All times are correct, this is an actual reboot

May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: microcode: microcode updated early to revision 0x88, date = 2021-03-31
May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: Linux version 5.18.0-rc2-daily-default-20220518-0-g79973093ab8c ([email protected]) (gcc (Ubun>
May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.18.0-rc2-daily-default-20220518-0-g79973093ab8c root=UUID=dc238153->
May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: x86/split lock detection: #AC: crashing the kernel on kernel split_locks and warning on user-space split_loc>
May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
May 19 11:44:49 jf-tglu-sku0a32-sdca-03 kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
   .
   .
   .
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Starting Set console scheme...
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Update UTMP about System Runlevel Changes.
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Set console scheme.
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Created slice system-getty.slice.
May 19 11:45:10 jf-tglu-sku0a32-sdca-03 systemd[1]: Startup finished in 9.989s (firmware) + 3.173s (loader) + 5.076s (kernel) + 21.979s (userspace) = 40.218s.
May 19 11:45:19 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-fsckd.service: Succeeded.
May 19 11:45:20 jf-tglu-sku0a32-sdca-03 systemd-timesyncd[399]: Initial synchronization to time server 10.104.196.177:123 (corp.intel.com).
May 19 11:45:21 jf-tglu-sku0a32-sdca-03 tracker-store[799]: OK
May 19 11:45:21 jf-tglu-sku0a32-sdca-03 systemd[665]: tracker-store.service: Succeeded.
May 19 11:45:22 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-hostnamed.service: Succeeded.
May 19 11:45:22 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-localed.service: Succeeded.

-- Reboot --   Logs of first boot with correct time now polluted by -> Logs of second boot with WRONG time 11:45

May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: microcode: microcode updated early to revision 0x88, date = 2021-03-31
May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: Linux version 5.18.0-rc2-daily-default-20220518-0-g79973093ab8c ([email protected]) (gcc (Ubunt>
May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.18.0-rc2-daily-default-20220518-0-g79973093ab8c root=UUID=dc238153-5>
May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: x86/split lock detection: #AC: crashing the kernel on kernel split_locks and warning on user-space split_locks
May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
May 19 11:45:42 jf-tglu-sku0a32-sdca-03 kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
   .
   .
   .
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Load AppArmor profiles being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Store a System Token in an EFI Variable being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Received SIGRTMIN+20 from PID 334 (plymouthd).
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: plymouth-read-write.service: Succeeded.
May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Tell Plymouth To Write Out Runtime Data.

-- Reboot --  Back to logs of first boot with CORRECT time

May 19 11:45:47 jf-tglu-sku0a32-sdca-03 dbus-daemon[682]: [session uid=1000 pid=682] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tr>
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 systemd[665]: Starting Tracker metadata database store and lookup manager...
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 dbus-daemon[682]: [session uid=1000 pid=682] Successfully activated service 'org.freedesktop.Tracker1'
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 systemd[665]: Started Tracker metadata database store and lookup manager.
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 dbus-daemon[682]: [session uid=1000 pid=682] Activating via systemd: service name='org.freedesktop.Tracker1.Miner.Ext>
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 systemd[665]: Starting Tracker metadata extractor...
May 19 11:45:47 jf-tglu-sku0a32-sdca-03 tracker-extract[1459]: Set scheduler policy to SCHED_IDLE
   .
   .
   .
May 19 12:01:12 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
May 19 12:01:12 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 1
May 19 12:01:12 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x2024001e successful
May 19 12:01:12 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
May 19 12:01:16 jf-tglu-sku0a32-sdca-03 kernel: soundwire sdw-master-0: clock stop prep/de-prep done slave:15

-- Reboot -- first boot with correct time -> second boot with (better but still) WRONG time

May 19 11:45:43 jf-tglu-sku0a32-sdca-03 systemd-timesyncd[404]: System clock time unset or jumped backwards, restoring from recorded timestamp: Thu 2022-05-19 12:01:53 UTC
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 kernel: [drm] Initialized i915 1.6.0 20201103 for 0000:00:02.0 on minor 0
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 systemd[1]: Started Network Time Synchronization.
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 systemd[1]: Reached target System Initialization.
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 systemd[1]: Started ACPI Events Check.
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 systemd[1]: Condition check resulted in Process error reports when automatic reporting is enabled (file watch) being skipped.
May 19 12:01:53 jf-tglu-sku0a32-sdca-03 systemd[1]: Started CUPS Scheduler.
   .
   .
   .
May 19 12:02:14 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Set console scheme.
May 19 12:02:14 jf-tglu-sku0a32-sdca-03 systemd[1]: Created slice system-getty.slice.
May 19 12:02:14 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
May 19 12:02:14 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Update UTMP about System Runlevel Changes.
May 19 12:02:14 jf-tglu-sku0a32-sdca-03 systemd[1]: Startup finished in 9.853s (firmware) + 3.173s (loader) + 5.271s (kernel) + 21.777s (userspace) = 40.075s
.
May 19 12:02:23 jf-tglu-sku0a32-sdca-03 systemd[1]: systemd-fsckd.service: Succeeded.

-- Reboot -- wrong time -> CORRECT time

May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 4 dir 1 cmd 0
May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x20240000 successful
May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 4 dir 1
May 19 12:02:52 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000: GLB_TPLG_MSG: COMP_FREE
   .
   .
   .
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790528
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_hda_dai_trigger: cmd=1 dai iDisp3 Pin direction 0
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc3_hda_dai_trigger: cmd=1 dai iDisp3 Pin direction 0
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 7 dir 0 cmd 1
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
May 19 12:11:59 jf-tglu-sku0a32-sdca-03 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START

       ( CRASH https://github.com/thesofproject/linux/issues/3387 )

-- Reboot --  first boot with correct time -> second boot with finally CORRECT time!

May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd-timesyncd[404]: Initial synchronization to time server A.B.C.D
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd[1]: Started Run anacron jobs.
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 anacron[10774]: Anacron 2.3 started on 2022-05-19
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 anacron[10774]: Normal exit (0 jobs run)
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd[1]: Starting Message of the Day...
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd[1]: anacron.service: Succeeded.
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd[1]: motd-news.service: Succeeded.
May 19 22:08:46 jf-tglu-sku0a32-sdca-03 systemd[1]: Finished Message of the Day.

PS: fun read: https://www.newyorker.com/tech/annals-of-technology/the-thorny-problem-of-keeping-the-internets-time

marc-hb · 2022-05-20T00:05:20Z

marc-hb
May 20, 2022
Maintainer Author

For more complex cases try a look at files in ls -lt /var/log/journal/*/*system* | head and their timestamps.

A single file can normally contain multiple boots but in this case journalctl seems to have started a new file after the crash; you can see that the second file has not reached the maximum size and that his last modification time 11:45 matches the (wrong) time of reboot after the crash.

-rw-r-----+ 1 root systemd-journal   8388608 May 19 23:17 /var/log/journal/221282dcb81e44199e72e66c2a01c359/system.journal
-rw-r-----+ 1 root systemd-journal  83886080 May 19 11:45 /var/log/journal/221282dcb81e44199e72e66c2a01c359/[email protected]~
-rw-r-----+ 1 root systemd-journal 100663296 May 19 11:02 /var/log/journal/221282dcb81e44199e72e66c2a01c359/system@a0a0394860a8412185be0c8c61fea2b3-0000000000029feb-0005df5abb2429d1.journal

You can read a single .journal thanks to the --file option and you can combine --file with either --list-boots or -b 4aafbba1586740878938eb06b0748218. Example:

$ journalctl --file ./[email protected]~ --list-boots

-2 727fb0d118e242a68faa463e44a47208 Thu 2022-05-19 11:02:50 UTC—Thu 2022-05-19 11:30:05 UTC
-1 a41196ed0b5a4ae9810a9c222aa83deb Thu 2022-05-19 11:30:25 UTC—Thu 2022-05-19 11:44:29 UTC
 0 4aafbba1586740878938eb06b0748218 Thu 2022-05-19 11:44:49 UTC—Thu 2022-05-19 12:11:59 UTC  <== end time has been fixed!! Thanks to the lack of pollution from the next boot.

cc: @poettering

0 replies

marc-hb · 2022-10-05T23:08:54Z

marc-hb
Oct 5, 2022
Maintainer Author

`/var/log/syslog*` and `rsyslogd` on Ubuntu 22

When the hardware clock gets stuck in the past, the time catch-up normally happens in two steps. In the first step, systemd notices that the time cannot possibly be earlier than events that already happened and jumps once first. Then NTP provides a second forward jump. See example below.

For some unknown reason Ubuntu 22 still runs rsyslogd which duplicates most journalctl data in more traditional /var/log/syslog* files.

I suspect the order in rsyslogd is "better" when the time correction goes backwards than when using journalctl without -b but I haven't observed it yet.

It looks like rsyslogd is started by systemd after the first time catch-up. However rsyslogd is somehow still receiving log lines that were issued before it was started. So the lines before the first time catch-up have a different timestamp in rsyslogd compared to journalctl.

Interestingly, rsyslogd and journalctl don't show logs in the exact same order because log concurrency. In journalctl Linux version is always at the start of a boot but not in /var/log/syslog*

# catch-up 1/2 in journalctl

Oct 03 23:46:45 sh-tglh-0a5e-sdw-01 systemd-timesyncd[466]: System clock time unset or jumped backwards, restoring from recorded timestamp: Tue 2022-10-04 03:27:41 UTC
Oct 04 03:27:41 sh-tglh-0a5e-sdw-01 systemd[1]: Started Network Time Synchronization.


# catch-up 2/2, finally correct time

Oct 04 03:28:11 sh-tglh-0a5e-sdw-01 systemd[1]: systemd-fsckd.service: Deactivated successfully.
Oct 04 22:29:11 sh-tglh-0a5e-sdw-01 systemd-resolved[454]: Clock change detected. Flushing caches.
Oct 04 22:29:11 sh-tglh-0a5e-sdw-01 systemd-timesyncd[466]: Initial synchronization to time server 1.2.3.4:123

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

HOWTO use journalctl when faced with time warps #908

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments

{{title}}

{{title}}

Select a reply

HOWTO use journalctl when faced with time warps #908

marc-hb May 20, 2022 Maintainer

Replies: 2 comments

marc-hb May 20, 2022 Maintainer Author

marc-hb Oct 5, 2022 Maintainer Author

/var/log/syslog* and rsyslogd on Ubuntu 22

marc-hb
May 20, 2022
Maintainer

marc-hb
May 20, 2022
Maintainer Author

marc-hb
Oct 5, 2022
Maintainer Author

`/var/log/syslog*` and `rsyslogd` on Ubuntu 22