Hi there! (this is my first post to this forum :D )
I noticed that some log files (matching the pattern of /var/log/*/current) have out-of-order timestamps.
My hunch is that if I were to set the timestamp format to include the timezone or if the timezone was always in GMT, then this issue would be resolved. I suspect it's usually logging in my local time, and sometimes it's logging in GMT.
The exact timestamp on these logs matter - since I've been debugging some other issues around hibernation crashes and the like.
Do my suspicions make sense? Do you have any recommendations? Is there something I haven't checked? Has anyone else noticed this behavior?
By default, the timestamp format we use is the ISO 8601 timestamp which is indeed local time. It is the T directive which is described on the s6-log page (https://skarnet.org/software/s6/s6-log.html). Now as for out-of-order timestamps, I can't say I've ever witnessed that on my system. This sounds like the time on your machine is going back/forth for some reason and not always increasing.
Did some more digging to find an example. Just skimmed through all files in /var/log to see if I can find one. Here's the first I found.
It's possible s6 isn't to blame, here's the (censored) content of /var/log/messages.log:
Feb 5 09:07:56 xxxxxxxxx root: ACPI group/action undefined: jack/videoout / VIDEOOUT
Feb 5 09:07:56 xxxxxxxxx NetworkManager[729]: <info> [xxxxxxxxxx.xxxx] agent-manager: agent[xxxxxxxxxxxxxxxx,:1.24/org.kde.plasma.networkmanagement/1000]: agent registered
Feb 5 09:07:57 xxxxxxxxx kernel: warning: `kded5' uses wireless extensions which will stop working for Wi-Fi 7 hardware; use nl80211
Feb 5 16:07:57 xxxxxxxxx rtkit-daemon[1803]: Successfully made thread 2041 of process 2041 owned by '1000' high priority at nice level -11.
Feb 5 16:07:57 xxxxxxxxx rtkit-daemon[1803]: Successfully made thread 2061 of process 2041 owned by '1000' RT at priority 20.
Feb 5 16:07:57 xxxxxxxxx rtkit-daemon[1803]: Successfully made thread 2065 of process 2039 owned by '1000' RT at priority 20.
Feb 5 16:07:57 xxxxxxxxx rtkit-daemon[1803]: Successfully made thread 2039 of process 2039 owned by '1000' high priority at nice level -11.
Feb 5 09:07:57 xxxxxxxxx dbus-daemon[584]: [system] Activating service name='org.kde.powerdevil.discretegpuhelper' requested by ':1.29' (uid=1000 pid=2008 comm="/usr/lib/org_kde_powerdevil") (using servicehelper)
Feb 5 09:07:57 xxxxxxxxx kernel: EXT4-fs (dm-3): mounted filesystem xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx r/w with ordered data mode. Quota mode: none.
Feb 5 09:07:57 xxxxxxxxx dbus-daemon[584]: [system] Activating service name='org.kde.kded.smart' requested by ':1.24' (uid=1000 pid=1938 comm="/usr/bin/kded5") (using servicehelper)
I also found the same (exact) logs in /var/log/everything.log
Here's some from /var/log/daemon.log:
Feb 4 15:44:50 xxxxxxxxx NetworkManager[739]: <info> [1707086690.5553] dhcp6 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Feb 4 15:44:50 xxxxxxxxx NetworkManager[739]: <info> [1707086690.5554] dhcp6 (wlan0): state changed no lease
Feb 4 22:44:50 xxxxxxxxx rtkit-daemon[1832]: Supervising 1 threads of 1 processes of 1 users.
Feb 4 22:44:50 xxxxxxxxx rtkit-daemon[1832]: Supervising 1 threads of 1 processes of 1 users.
Feb 4 22:44:50 xxxxxxxxx rtkit-daemon[1832]: Supervising 1 threads of 1 processes of 1 users.
Feb 4 21:12:52 xxxxxxxxx NetworkManager[732]: <info> [1707106373.0019] manager: startup complete
Feb 4 21:12:52 xxxxxxxxx NetworkManager[732]: <info> [1707106373.0026] device (lo): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
It looks like all related out-of-order logs are rtkit-daemon.
I looked through all s6 logs and found nothing. I must have been mistaken.