Bug 64760

Summary:	journalctl mixes new logs with logs from the previous boot on crash (no RTC)
Product:	systemd	Reporter:	Peter Wu <peter>
Component:	general	Assignee:	systemd-bugs
Status:	RESOLVED MOVED	QA Contact:	systemd-bugs
Severity:	normal
Priority:	medium	CC:	drizzd
Version:	unspecified
Hardware:	Other
OS:	All
Whiteboard:
i915 platform:		i915 features:

Description Peter Wu 2013-05-19 13:00:38 UTC

Originally mentioned at https://bugs.freedesktop.org/show_bug.cgi?id=61411#c9:
--->8--->8--->8--->8--->8--->8--->8--->8--->8--->8--->8---
I have a different issue where the order of messages is interleaved (journalctl is apparently sorting by date?), but that fails horribly because there is no RTC in my device. Therefore, all boots starts on January 1st.

rsyslogd would write log entries to disk and if power is suddenly gone, you can see the new boot log entries appended to the previous one.

rsyslogd example (after reboot, truncated to preserve space):
Jan  1 01:00:16 arpi systemd[1]: Starting OpenNTP Daemon...
Jan  1 01:00:17 arpi systemd[1]: Failed to read PID from file /run/nginx...
Jan  1 01:00:17 arpi systemd[1]: Started A high performance ...
May 19 14:32:10 arpi systemd[1]: Time has been changed
May 19 14:32:10 arpi systemd[1]: Started OpenNTP Daemon.

journalctl (diff on journal before "crash" and after reboot):
+Jan 01 01:00:16 arpi systemd[1]: Starting OpenNTP Daemon...
+-- Reboot --
 (old log entries here)
+-- Reboot --
+Jan 01 01:00:17 arpi systemd[1]: Failed to read PID from file /run/nginx...
+-- Reboot --

 (more old log entries and newer entries interleaved)

+May 19 14:31:10 arpi sshd[358]: pam_unix(sshd:session): ...
+May 19 14:31:10 arpi systemd-logind[115]: New session c2 ...
+-- Reboot --
+May 19 14:32:10 arpi systemd[1]: Time has been changed
+May 19 14:32:10 arpi systemd[1]: Started OpenNTP Daemon.
---8<---8<---8<---8<---8<---8<---8<---8<---8<---8<---8<---

This corruption occurs when the system is uncleanly shut down (pull power). It makes logs hard to read with journalctl.

These logs are taken from a Raspberry Pi, an ARM board with no RTC.

Comment 1 Zbigniew Jedrzejewski-Szmek 2013-06-08 02:20:05 UTC

I guess we could a mode where journalctl orders messages first by boot_id, and then by the monotonic time. Shouldn't be too hard:
  for sd_journal_enumerate_unique("BOOT_ID"):
     sd_journal_add_match("BOOT_ID=...")
     logs_show()

Might even be useful to people who have an rtc but it's not functioning currently.

I wonder how rare such a situation is.

Comment 2 Zbigniew Jedrzejewski-Szmek 2014-06-21 03:06:02 UTC

http://cgit.freedesktop.org/systemd/systemd/commit/?id=ece6e766
and http://cgit.freedesktop.org/systemd/systemd/commit/?id=d636d376
add /var/lib/systemd/clock file, which is timestamped whenever systemd-timesyncd is running and an ntp time is acquired. This should solve your issue partially.

Comment 3 Lennart Poettering 2019-03-19 12:43:17 UTC

A very similar issue exists in github, we should probably continue discussion there.
https://github.com/systemd/systemd/issues/662

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.