Systematic journal corruption on clean install of Bookworm Lite 64bit

demukti commented 9 months ago

I've stumbled across this error in the journal after spending weeks building a project on top of this OS:

system.journal corrupted or uncleanly shut down, renaming and replacing

After some investigation I found that this error has been shown every boot from the very first reboot after installing with the Pi Imager. So I tried a fresh install on a brand new SanDisk Extreme Pro and used another Pi 4B 1.5 (4GB). The error starts showing up immediately in every case. There have been no unclean shutdowns.

Switching debug on in cmdline.txt shows

system.journal is from the future, refusing to append new data to it

I've also tried rm /var/log/journal/* but the issue is always there (as expected since it's also there on a clean install).
The only thing that stops it is to turn persistent storage off but I don't want to do that.
I've also installed the Bullseye lite 64 version with the imager and the error is not there
I've tried with and without personal settings in the Imager and that makes no difference
ntp, fake-hw-clock, etc are all running as normal and I can't find other errors related to this
I've used google, chatgpt 4 and Bing co-pilot but there are no reports or fixes to be found anywhere.
Googling the error itself returns thousands of hits but most are about other issues or offer no solution. None are specifically about this exact OS that I can find and chatgpt has no clue.

The action that systemd reports that it will take is never done. The journal is not renamed and only one single journal file exists at all times. It is never renamed or restarted. Renaming and restarting it manually does nothing to stop the errors.

This should be very easy to replicate so I hope that some of the devs are willing to do that and help me fix this.

This should probably be a different post but just for reference; The reason I looked into this is that I get a sporadic reboot loop that seems to be journal or time related. There's no errors in any logs when this happens but the logging stops at the moment the time should start running (just before plymouth starts). So everything is the same time in the log (kernel, .. ) and right at the point where it should start adding seconds the log stops for every boot. Plymouth still shows and systemd is doing stuff but it's no longer logged and I suspect that errors in time functions are the cause. The loop is easily broken just by switching VT or connecting via SSH, otherwise it would continue indefinitely it seems. I'm just adding this now in case anyone says the error is harmless and just to let it be. The reboot issue is surely something in my setup because it wasn't there the first weeks I worked on this but I do believe it might be related to a time issue that is baked in at this point.

This is the debug log:


Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Time spent on flushing to /var/log/journal/48d069bf1c2340a18395b322c7d9419f is 52.788ms for 860 entries.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: System Journal (/var/log/journal/48d069bf1c2340a18395b322c7d9419f) is 56.0M, max 2.8G, 2.8G free.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: varlink: New incoming connection.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: varlink-18: Setting state idle-server
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: varlink-18: New incoming message: {"method":"io.systemd.Journal.FlushToVar","parameters":{}}
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: varlink-18: Changing state idle-server → processing-method
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Received client request to flush runtime journal.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Journal file /var/log/journal/48d069bf1c2340a18395b322c7d9419f/system.journal is from the future, refusing to append new data to it th>
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: File /var/log/journal/48d069bf1c2340a18395b322c7d9419f/system.journal corrupted or uncleanly shut down, renaming and replacing.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Fixed min_use=16.0M max_use=2.8G max_size=128.0M min_size=512.0K keep_free=1.4G n_max_files=100
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Reserving 333 entries in field hash table.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Reserving 233016 entries in data hash table.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Flushing to /var/log/journal/48d069bf1c2340a18395b322c7d9419f...
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Considering root directory '/run/log/journal'.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Root directory /run/log/journal added.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Considering directory '/run/log/journal/48d069bf1c2340a18395b322c7d9419f'.
Feb 28 16:26:11 tzvpi1 systemd-journald[304]: Directory /run/log/journal/48d069bf1c2340a18395b322c7d9419f added.
Feb 28 16:26:11 tzvpi1 systemd-tmpfiles[324]: Entry "/dev/kvm" matches include prefix "/dev".

Any help is greatly appreciated! Thank you.

popcornmix commented 9 months ago

To avoid duplicated answers, this question is also asked on forum.

demukti commented 9 months ago

Below is the output journalctl | grep hwclock. It starts with normal logging and then a few times with debug logging on. This is all since I removed the log file yesterday and started fresh. Specifically note that: Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load has a date from over a month ago but is just listed in the chronologic order ignoring the datetime index.

Feb 28 01:13:48 tzvpi1 systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
Feb 28 01:13:48 tzvpi1 systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
Feb 28 01:13:48 tzvpi1 fake-hwclock[301]: Wed 28 Feb 00:13:48 UTC 2024
Feb 28 01:17:00 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 01:17:00 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 01:17:00 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 01:17:00 tzvpi1 systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
Feb 28 01:17:00 tzvpi1 systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
Feb 28 01:17:00 tzvpi1 fake-hwclock[300]: Wed 28 Feb 00:17:00 UTC 2024
Feb 28 01:19:05 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 01:19:05 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 01:19:05 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 01:19:05 tzvpi1 systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
Feb 28 01:19:05 tzvpi1 systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
Feb 28 01:19:05 tzvpi1 fake-hwclock[301]: Wed 28 Feb 00:19:05 UTC 2024
Feb 28 01:31:13 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 01:31:13 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 01:31:13 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 01:31:13 tzvpi1 systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
Feb 28 01:31:13 tzvpi1 systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
Feb 28 01:31:13 tzvpi1 fake-hwclock[299]: Wed 28 Feb 00:31:13 UTC 2024
Feb 28 16:17:22 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 16:17:22 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 16:17:22 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 16:17:22 tzvpi1 systemd[1]: Starting fake-hwclock.service - Restore / save the current clock...
Feb 28 16:17:22 tzvpi1 systemd[1]: Finished fake-hwclock.service - Restore / save the current clock.
Feb 28 16:17:22 tzvpi1 fake-hwclock[298]: Wed 28 Feb 15:17:22 UTC 2024
Feb 28 16:26:11 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 16:26:11 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 16:26:11 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 16:26:11 tzvpi1 systemd-sysv-generator[281]: Native unit for fake-hwclock.service already exists, skipping.
Feb 28 16:26:11 tzvpi1 systemd-sysv-generator[281]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 28 16:26:11 tzvpi1 systemd-sysv-generator[281]: Native unit for hwclock.service already exists, skipping.
Feb 28 16:26:11 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 16:26:11 tzvpi1 fake-hwclock[303]: Wed 28 Feb 15:26:11 UTC 2024
Feb 28 16:26:11 tzvpi1 systemd-udevd[328]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:26:15 tzvpi1 systemd-udevd[328]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:26:18 tzvpi1 systemd-udevd[328]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:54:07 tzvpi1 systemd[1]: fake-hwclock.service: Installed new job fake-hwclock.service/stop as 770
Feb 28 16:54:07 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=774 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 16:54:07 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=775 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 16:54:07 tzvpi1 systemd[1]: fake-hwclock.service: stopping held back, waiting for: sysinit.target
Feb 28 16:54:08 tzvpi1 systemd-udevd[328]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Will spawn child (service_enter_stop): /sbin/fake-hwclock
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: About to execute /sbin/fake-hwclock save
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Forked /sbin/fake-hwclock as 1132
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Changed exited -> stop
Feb 28 16:54:09 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 16:54:09 tzvpi1 (-hwclock)[1132]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Feb 28 16:54:09 tzvpi1 systemd[1]: Received SIGCHLD from PID 1132 (fake-hwclock).
Feb 28 16:54:09 tzvpi1 systemd[1]: Child 1132 (fake-hwclock) died (code=exited, status=0/SUCCESS)
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Child 1132 belongs to fake-hwclock.service.
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Control process exited, code=exited, status=0/SUCCESS (success)
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Got final SIGCHLD for state stop.
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Service restart not allowed.
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Changed stop -> dead
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Job 770 fake-hwclock.service/stop finished, result=done
Feb 28 16:54:09 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Consumed 16ms CPU time.
Feb 28 16:54:09 tzvpi1 systemd[1]: Cannot stat /run/credentials/fake-hwclock.service: No such file or directory
Feb 28 16:54:09 tzvpi1 systemd[1]: fake-hwclock.service: Control group is empty.
Feb 28 16:54:09 tzvpi1 systemd-sysv-generator[281]: Native unit for fake-hwclock.service already exists, skipping.
Feb 28 16:54:09 tzvpi1 systemd-sysv-generator[281]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 28 16:54:09 tzvpi1 systemd-sysv-generator[281]: Native unit for hwclock.service already exists, skipping.
Feb 28 16:54:09 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 16:54:09 tzvpi1 fake-hwclock[301]: Wed 28 Feb 15:54:09 UTC 2024
Feb 28 16:54:10 tzvpi1 systemd-udevd[329]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:54:13 tzvpi1 systemd-udevd[329]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 16:54:16 tzvpi1 systemd-udevd[329]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:19:01 tzvpi1 systemd[1]: fake-hwclock.service: Installed new job fake-hwclock.service/stop as 878
Feb 28 17:19:01 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=793 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:19:01 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=794 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:19:01 tzvpi1 systemd-logind[515]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=793 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:19:01 tzvpi1 systemd-logind[515]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=794 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:19:01 tzvpi1 systemd[1]: fake-hwclock.service: stopping held back, waiting for: sysinit.target
Feb 28 17:19:03 tzvpi1 systemd-udevd[329]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:19:03 tzvpi1 systemd-sysv-generator[278]: Native unit for fake-hwclock.service already exists, skipping.
Feb 28 17:19:03 tzvpi1 systemd-sysv-generator[278]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 28 17:19:03 tzvpi1 systemd-sysv-generator[278]: Native unit for hwclock.service already exists, skipping.
Feb 28 17:19:03 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 17:19:03 tzvpi1 fake-hwclock[301]: Wed 28 Feb 16:19:03 UTC 2024
Feb 28 17:19:04 tzvpi1 systemd-udevd[327]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:19:07 tzvpi1 systemd-udevd[327]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:19:10 tzvpi1 systemd-udevd[327]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:20:19 tzvpi1 systemd[1]: fake-hwclock.service: Installed new job fake-hwclock.service/stop as 845
Feb 28 17:20:19 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=646 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:20:19 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=647 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:20:19 tzvpi1 systemd[1]: fake-hwclock.service: stopping held back, waiting for: sysinit.target
Feb 28 17:20:19 tzvpi1 systemd-logind[524]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=646 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:20:19 tzvpi1 systemd-logind[524]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=647 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 17:20:20 tzvpi1 systemd-udevd[327]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Will spawn child (service_enter_stop): /sbin/fake-hwclock
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: About to execute /sbin/fake-hwclock save
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Forked /sbin/fake-hwclock as 1089
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Changed exited -> stop
Feb 28 17:20:21 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 17:20:21 tzvpi1 (-hwclock)[1089]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Feb 28 17:20:21 tzvpi1 systemd[1]: Child 1089 (fake-hwclock) died (code=exited, status=0/SUCCESS)
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Child 1089 belongs to fake-hwclock.service.
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Control process exited, code=exited, status=0/SUCCESS (success)
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Got final SIGCHLD for state stop.
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Service restart not allowed.
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Changed stop -> dead
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Job 845 fake-hwclock.service/stop finished, result=done
Feb 28 17:20:21 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Consumed 17ms CPU time.
Feb 28 17:20:21 tzvpi1 systemd[1]: Cannot stat /run/credentials/fake-hwclock.service: No such file or directory
Feb 28 17:20:21 tzvpi1 systemd[1]: fake-hwclock.service: Control group is empty.
Feb 28 17:20:21 tzvpi1 systemd-sysv-generator[279]: Native unit for fake-hwclock.service already exists, skipping.
Feb 28 17:20:21 tzvpi1 systemd-sysv-generator[279]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 28 17:20:21 tzvpi1 systemd-sysv-generator[279]: Native unit for hwclock.service already exists, skipping.
Feb 28 17:20:21 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 17:20:21 tzvpi1 fake-hwclock[300]: Wed 28 Feb 16:20:21 UTC 2024
Feb 28 17:20:22 tzvpi1 systemd-udevd[324]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:20:25 tzvpi1 systemd-udevd[324]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 17:20:28 tzvpi1 systemd-udevd[324]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 21:00:27 tzvpi1 systemd[1]: fake-hwclock.service: Installed new job fake-hwclock.service/stop as 951
Feb 28 21:00:27 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=803 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 21:00:27 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=804 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 21:00:27 tzvpi1 systemd-logind[496]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=803 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 21:00:27 tzvpi1 systemd-logind[496]: Got message type=signal sender=:1.2 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=804 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 28 21:00:27 tzvpi1 systemd[1]: fake-hwclock.service: stopping held back, waiting for: sysinit.target
Feb 28 21:00:28 tzvpi1 systemd-udevd[324]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Will spawn child (service_enter_stop): /sbin/fake-hwclock
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: About to execute /sbin/fake-hwclock save
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Forked /sbin/fake-hwclock as 1411
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Changed exited -> stop
Feb 28 21:00:30 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 28 21:00:30 tzvpi1 (-hwclock)[1411]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Feb 28 21:00:30 tzvpi1 systemd[1]: Received SIGCHLD from PID 1411 (fake-hwclock).
Feb 28 21:00:30 tzvpi1 systemd[1]: Child 1411 (fake-hwclock) died (code=exited, status=0/SUCCESS)
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Child 1411 belongs to fake-hwclock.service.
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Control process exited, code=exited, status=0/SUCCESS (success)
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Got final SIGCHLD for state stop.
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Service restart not allowed.
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Changed stop -> dead
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Job 951 fake-hwclock.service/stop finished, result=done
Feb 28 21:00:30 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Consumed 15ms CPU time.
Feb 28 21:00:30 tzvpi1 systemd[1]: Cannot stat /run/credentials/fake-hwclock.service: No such file or directory
Feb 28 21:00:30 tzvpi1 systemd[1]: fake-hwclock.service: Control group is empty.
Feb 28 21:00:30 tzvpi1 systemd-sysv-generator[279]: Native unit for fake-hwclock.service already exists, skipping.
Feb 28 21:00:30 tzvpi1 systemd-sysv-generator[279]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 28 21:00:30 tzvpi1 systemd-sysv-generator[279]: Native unit for hwclock.service already exists, skipping.
Feb 28 21:00:30 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 21:00:30 tzvpi1 fake-hwclock[302]: Wed 28 Feb 20:00:30 UTC 2024
Feb 28 21:00:30 tzvpi1 systemd-udevd[326]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 21:00:34 tzvpi1 systemd-udevd[326]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 28 21:00:37 tzvpi1 systemd-udevd[326]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 29 14:04:24 tzvpi1 systemd[1]: fake-hwclock.service: Installed new job fake-hwclock.service/stop as 1087
Feb 29 14:04:24 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=790 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 29 14:04:24 tzvpi1 systemd[1]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=791 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 29 14:04:24 tzvpi1 systemd-logind[498]: Got message type=signal sender=:1.3 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=790 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 29 14:04:24 tzvpi1 systemd-logind[498]: Got message type=signal sender=:1.3 destination=n/a path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=791 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Feb 29 14:04:24 tzvpi1 systemd[1]: fake-hwclock.service: stopping held back, waiting for: sysinit.target
Feb 29 14:04:25 tzvpi1 systemd-udevd[326]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Will spawn child (service_enter_stop): /sbin/fake-hwclock
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: About to execute /sbin/fake-hwclock save
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Forked /sbin/fake-hwclock as 1270
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Changed exited -> stop
Feb 29 14:04:29 tzvpi1 systemd[1]: Stopping fake-hwclock.service - Restore / save the current clock...
Feb 29 14:04:29 tzvpi1 (-hwclock)[1270]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Feb 29 14:04:29 tzvpi1 systemd[1]: Received SIGCHLD from PID 1270 (fake-hwclock).
Feb 29 14:04:29 tzvpi1 systemd[1]: Child 1270 (fake-hwclock) died (code=exited, status=0/SUCCESS)
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Child 1270 belongs to fake-hwclock.service.
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Control process exited, code=exited, status=0/SUCCESS (success)
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Got final SIGCHLD for state stop.
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Deactivated successfully.
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Service restart not allowed.
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Changed stop -> dead
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Job 1087 fake-hwclock.service/stop finished, result=done
Feb 29 14:04:29 tzvpi1 systemd[1]: Stopped fake-hwclock.service - Restore / save the current clock.
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Consumed 19ms CPU time.
Feb 29 14:04:29 tzvpi1 systemd[1]: Cannot stat /run/credentials/fake-hwclock.service: No such file or directory
Feb 29 14:04:29 tzvpi1 systemd[1]: fake-hwclock.service: Control group is empty.
Feb 29 14:04:29 tzvpi1 systemd-sysv-generator[279]: Native unit for fake-hwclock.service already exists, skipping.
Feb 29 14:04:29 tzvpi1 systemd-sysv-generator[279]: Linked unit file: /lib/systemd/system/hwclock.service → /dev/null
Feb 29 14:04:29 tzvpi1 systemd-sysv-generator[279]: Native unit for hwclock.service already exists, skipping.
Feb 29 14:04:29 tzvpi1 systemd[1]: unit_file_build_name_map: normal unit file: /lib/systemd/system/fake-hwclock.service
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 29 14:04:29 tzvpi1 fake-hwclock[298]: Thu 29 Feb 13:04:29 UTC 2024
Feb 29 14:04:29 tzvpi1 systemd-udevd[325]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 29 14:04:33 tzvpi1 systemd-udevd[325]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 29 14:04:35 tzvpi1 systemd-udevd[325]: Reading rules file: /usr/lib/udev/rules.d/85-hwclock.rules
Feb 29 14:08:05 tzvpi1 systemd[1]: Got message type=method_call sender=:1.18 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/fake_2dhwclock_2eservice interface=org.freedesktop.DBus.Properties member=GetAll cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Feb 29 14:08:05 tzvpi1 systemd[1]: Found unit fake-hwclock.service at /lib/systemd/system/fake-hwclock.service (regular file)
Feb 29 14:08:05 tzvpi1 systemd[1]: Preset files don't specify rule for fake-hwclock.service. Enabling.

$ journalctl | grep 'Executing: /sbin/fake-hwclock' 
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 16:54:09 tzvpi1 (-hwclock)[1132]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 17:20:21 tzvpi1 (-hwclock)[1089]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 21:00:30 tzvpi1 (-hwclock)[1411]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 29 14:04:29 tzvpi1 (-hwclock)[1270]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load

demukti commented 9 months ago

This rogue date does not exist in the journal with using time arguments; the journal starts at Feb 28 but when using grep there's this:

$ journalctl | grep 'Jan 26'
Jan 26 22:48:37 tzvpi1 (mount)[284]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[285]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (mount)[286]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (kmod)[290]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (modprobe)[292]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (setup.sh)[289]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (modprobe)[294]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[297]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[299]: modprobe@fuse.service: Executing: /sbin/modprobe -abq fuse
Jan 26 22:48:37 tzvpi1 (modprobe)[300]: modprobe@loop.service: Executing: /sbin/modprobe -abq loop
Jan 26 22:48:37 tzvpi1 (mount)[284]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[285]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[287]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (mount)[286]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (setup.sh)[289]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (kmod)[290]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (modprobe)[292]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (modprobe)[293]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[297]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[298]: modprobe@fuse.service: Executing: /sbin/modprobe -abq fuse
Jan 26 22:48:37 tzvpi1 (modprobe)[299]: modprobe@loop.service: Executing: /sbin/modprobe -abq loop
Jan 26 22:48:37 tzvpi1 (mount)[282]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[283]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[284]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (kmod)[288]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (setup.sh)[286]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (modprobe)[290]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (modprobe)[291]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[293]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[298]: modprobe@loop.service: Executing: /sbin/modprobe -abq loop
Jan 26 22:48:37 tzvpi1 (mount)[282]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[283]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (mount)[284]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (setup.sh)[287]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (modprobe)[290]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (kmod)[288]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (modprobe)[293]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[294]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[297]: modprobe@fuse.service: Executing: /sbin/modprobe -abq fuse
Jan 26 22:48:37 tzvpi1 (mount)[282]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[283]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[284]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (setup.sh)[286]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (kmod)[288]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (modprobe)[290]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (modprobe)[292]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[291]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[296]: modprobe@fuse.service: Executing: /sbin/modprobe -abq fuse
Jan 26 22:48:37 tzvpi1 (modprobe)[297]: modprobe@loop.service: Executing: /sbin/modprobe -abq loop
Jan 26 22:48:37 tzvpi1 (les-load)[301]: systemd-modules-load.service: Executing: /lib/systemd/systemd-modules-load
Jan 26 22:48:37 tzvpi1 (mount)[282]: dev-mqueue.mount: Executing: /bin/mount mqueue /dev/mqueue -t mqueue -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[283]: sys-kernel-debug.mount: Executing: /bin/mount debugfs /sys/kernel/debug -t debugfs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (mount)[284]: sys-kernel-tracing.mount: Executing: /bin/mount tracefs /sys/kernel/tracing -t tracefs -o nosuid,nodev,noexec
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Jan 26 22:48:37 tzvpi1 (setup.sh)[286]: keyboard-setup.service: Executing: /lib/console-setup/keyboard-setup.sh
Jan 26 22:48:37 tzvpi1 (kmod)[288]: kmod-static-nodes.service: Executing: /bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/static-nodes.conf
Jan 26 22:48:37 tzvpi1 (modprobe)[291]: modprobe@dm_mod.service: Executing: /sbin/modprobe -abq dm_mod
Jan 26 22:48:37 tzvpi1 (modprobe)[289]: modprobe@configfs.service: Executing: /sbin/modprobe -abq configfs
Jan 26 22:48:37 tzvpi1 (modprobe)[294]: modprobe@drm.service: Executing: /sbin/modprobe -abq drm
Jan 26 22:48:37 tzvpi1 (modprobe)[295]: modprobe@efi_pstore.service: Executing: /sbin/modprobe -abq efi_pstore
Jan 26 22:48:37 tzvpi1 (modprobe)[296]: modprobe@fuse.service: Executing: /sbin/modprobe -abq fuse

gitbls commented 9 months ago

I see this on every one of my Pi systems: Pi4s, Pi5s, and even one Pi02W running 32-bit...on every boot.

The funny thing is that the logs from all old boots of the system are still available, so it's not like log information from prior reboots is lost forever.

Nonetheless, it is a bit perturbing.

demukti commented 9 months ago

I see this on every one of my Pi systems: Pi4s, Pi5s, and even one Pi02W running 32-bit...on every boot.

The funny thing is that the logs from all old boots of the system are still available, so it's not like log information from prior reboots is lost forever.

Nonetheless, it is a bit perturbing.

Do you also get that same rogue date or is it a different one? I'm still pretty new at Linux and it's kernel but just wondering if that day could come out of the kernel or if it is set by the system. I just can't figure out where that Jan 26 comes from in my case. My kernel was built on Jan 25 so that may be too close to be a coincidence?

$ uname -v
#1 SMP PREEMPT Debian 1:6.1.73-1+rpt1 (2024-01-25)

Also, are all your pi's running bookworm? Because I don't get this on Bullseye Lite.

gitbls commented 9 months ago

I see this on every one of my Pi systems: Pi4s, Pi5s, and even one Pi02W running 32-bit...on every boot. The funny thing is that the logs from all old boots of the system are still available, so it's not like log information from prior reboots is lost forever. Nonetheless, it is a bit perturbing.

Do you also get that same rogue date or is it a different one? I'm still pretty new at Linux and it's kernel but just wondering if that day could come out of the kernel or if it is set by the system. I just can't figure out where that Jan 26 comes from in my case. My kernel was built on Jan 25 so that may be too close to be a coincidence?
$ uname -v
#1 SMP PREEMPT Debian 1:6.1.73-1+rpt1 (2024-01-25)
Also, are all your pi's running bookworm? Because I don't get this on Bullseye Lite.

No, I don't see the rogue dates.

And, apologies, I neglected to mention that all the Pi systems I mentioned are running Bookworm. No bullseye on my network except for a WSL instance or two.

demukti commented 9 months ago

Thank you for sharing your results! Just to make sure if you run: journalctl | grep 'Executing: /sbin/fake-hwclock' you just get a chronological output instead of this? :

Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 17:20:21 tzvpi1 (-hwclock)[1089]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 28 21:00:30 tzvpi1 (-hwclock)[1411]: fake-hwclock.service: Executing: /sbin/fake-hwclock save
Jan 26 22:48:37 tzvpi1 (-hwclock)[285]: fake-hwclock.service: Executing: /sbin/fake-hwclock load
Feb 29 14:04:29 tzvpi1 (-hwclock)[1270]: fake-hwclock.service: Executing: /sbin/fake-hwclock save

gitbls commented 9 months ago

Unfortunately my customized Bookworm doesn't use fake-hwclock load and save, so nothing to show you from that.

But, back on Bullseye (before I stopped using fake-hwclock) I have vague recollection of seeing date confusion like you're seeing and wondering WTF was going on.

demukti commented 9 months ago

Unfortunately my customized Bookworm doesn't use fake-hwclock load and save, so nothing to show you from that.

But, back on Bullseye (before I stopped using fake-hwclock) I have vague recollection of seeing date confusion like you're seeing and wondering WTF was going on.

I didn't know that was an option. I'll have to look into that. If you're not using fake-hwclock that unfortunately suggests that these are two unrelated issues.

May I ask if you you're seeing the 'journal corrupted' only or also the 'journal is from the future, refusing to append new data to it' message (with debug mode active)?

gitbls commented 9 months ago

May I ask if you you're seeing the 'journal corrupted' only or also the 'journal is from the future, refusing to append new data to it' message (with debug mode active)?

Only seeing the 'journal corrupted' message.

by commented 8 months ago

XECDesign commented 7 months ago

I think this is a wontfix. It's correctly determining that the journal file is from the future, since there's no RTC on pre-pi5 models. The message is a bit misleading, but harmless. So to the extent there is an issue, it's upstream in systemd rather than us doing something wrong on our end.

raspberrypi / bookworm-feedback

Systematic journal corruption on clean install of Bookworm Lite 64bit #221