Re: [systemd-devel] Monotonic time went backwards, rotating log
Pekka Paalanen writes: > have you checked your boot ID, maybe it's often the same as the previous > boot? Good thought, but it doesn't look like it: IDX BOOT ID FIRST ENTRY LAST ENTRY -20 c2a5e3af1f044d79805c4fbdd120beec Wed 2023-05-10 11:17:40 EDT Wed 2023-05-17 08:59:48 EDT -19 3f20878d92714d09a7928b1d1260074c Wed 2023-05-17 09:30:55 EDT Wed 2023-05-17 09:33:36 EDT -18 22944fc66fc949048c14a3e9e559824e Wed 2023-05-17 09:34:13 EDT Mon 2023-05-22 15:41:05 EDT -17 28c59dbf8d13407c8aa89ef2d3b3024c Tue 2023-05-23 08:34:38 EDT Fri 2023-05-26 14:46:36 EDT -16 e6804a377e984bc499fbc44dd9a14f40 Tue 2023-05-30 08:53:41 EDT Tue 2023-05-30 09:35:00 EDT -15 d3f4946a0f4e4951961ce62ae88d390c Tue 2023-05-30 09:35:36 EDT Thu 2023-06-01 13:00:15 EDT -14 9bd458cbf57d458e869d5405c534d549 Thu 2023-06-01 13:01:06 EDT Thu 2023-06-01 13:01:35 EDT -13 df67fe939f4a434f9beadfe81101e10e Thu 2023-06-01 13:40:22 EDT Tue 2023-06-06 10:56:06 EDT -12 b860691a4da841e6bd223a4035536ef6 Tue 2023-06-06 10:57:13 EDT Wed 2023-06-21 11:16:51 EDT -11 1f72e13c3d2542e69abfd5c38d8050fe Fri 2023-06-23 11:41:45 EDT Mon 2023-06-26 15:48:31 EDT -10 50821dde5780459bbf05d5dffc52ac37 Fri 2023-07-28 15:08:56 EDT Mon 2023-07-31 16:15:21 EDT -9 444f76e5a93b422583e2a8089816aafe Mon 2023-07-31 16:16:13 EDT Fri 2023-08-04 13:26:22 EDT -8 3ff965b69adb4c51b058cba5dcaa4c09 Tue 2023-08-08 12:50:10 EDT Tue 2023-08-08 12:50:19 EDT -7 448ca4a0ef024be0a0dd7ec2b58b1015 Tue 2023-08-08 12:54:43 EDT Thu 2023-08-10 10:17:08 EDT -6 68f66c75cf674dd48b6216cb05c9278c Thu 2023-08-24 10:00:56 EDT Thu 2023-08-24 15:09:49 EDT -5 184ac41dd9164e1786edc74d19e4cef9 Fri 2023-09-01 09:34:58 EDT Tue 2023-09-12 15:28:40 EDT -4 0f7b2c0b1d244769bff218e2933ba46d Mon 2023-09-25 12:04:21 EDT Tue 2023-09-26 10:58:30 EDT -3 f1369263334a4c6db183fa7fa61074c6 Tue 2023-09-26 10:59:10 EDT Thu 2023-10-05 13:02:18 EDT -2 dea7a07fe6d24ad49ce1841e0260b42e Thu 2023-10-05 13:03:49 EDT Thu 2023-10-05 13:11:00 EDT -1 b2d29b9e947942a79303ad6944d7ad31 Thu 2023-10-05 13:11:45 EDT Thu 2023-10-05 13:22:45 EDT 0 4539fd6a1ddf471e8795345cc3965f44 Thu 2023-10-05 13:23:22 EDT Fri 2023-10-06 13:38:45 EDT
Re: [systemd-devel] Monotonic time went backwards, rotating log
On Thu, 05 Oct 2023 13:32:37 -0400 Phillip Susi wrote: > Phillip Susi writes: > > > Lennart Poettering writes: > > > >> It actually checks that first: > >> > >> https://github.com/systemd/systemd/blob/main/src/libsystemd/sd-journal/journal-file.c#L2201 > >> > > > > That's what I'm saying: it should have noticed that FIRST and not gotten > > to the monotonic time check, but it didn't. > > I decided to try looking into this again. It seems it's also my system > log that is rotated on each boot with this message about the monotonic > clock, despite the fact that it should be rotated first just because > it's a new boot. Hi, have you checked your boot ID, maybe it's often the same as the previous boot? IIRC I had that problem on a device that had no RTC and when no software (kernel, etc.?) had been updated at all. The said device had problems keeping its logs in order, too, with some old systemd version. Thanks, pq > There are some debug prints that might shed light on what is happening, > but I can't seem to get them to enable. I tried setting > Environment=SYSTEMD_DEBUG_LEVEL=debug on systemd-journald.service, but I > still don't get them. > pgpt3diZjWPGL.pgp Description: OpenPGP digital signature
Re: [systemd-devel] Monotonic time went backwards, rotating log
Phillip Susi writes: > Lennart Poettering writes: > >> It actually checks that first: >> >> https://github.com/systemd/systemd/blob/main/src/libsystemd/sd-journal/journal-file.c#L2201 > > That's what I'm saying: it should have noticed that FIRST and not gotten > to the monotonic time check, but it didn't. I decided to try looking into this again. It seems it's also my system log that is rotated on each boot with this message about the monotonic clock, despite the fact that it should be rotated first just because it's a new boot. There are some debug prints that might shed light on what is happening, but I can't seem to get them to enable. I tried setting Environment=SYSTEMD_DEBUG_LEVEL=debug on systemd-journald.service, but I still don't get them.
Re: [systemd-devel] Monotonic time went backwards, rotating log
Lennart Poettering writes: > It actually checks that first: > > https://github.com/systemd/systemd/blob/main/src/libsystemd/sd-journal/journal-file.c#L2201 That's what I'm saying: it should have noticed that FIRST and not gotten to the monotonic time check, but it didn't.
Re: [systemd-devel] Monotonic time went backwards, rotating log
On Do, 25.05.23 14:32, Phillip Susi (ph...@thesusis.net) wrote: > > Lennart Poettering writes: > > > We want that within each file all records are strictly ordered by all > > clocks, so that we can find specific entries via bisection. > > Why *all* clocks? Even if you want to search on the monotonic time, you > first have to specify a boot ID within which that monotonic time is > valid, don't you? So the first step in your search would be to find the > boot records, then bisect from there. We didn't use to do this, but it makes things a lot easier to say "one boot id per file", since we nowadays have a concept for dealing with systems that lack a battery-buffered RTC and which hence of a CLOCK_REALTIME that initially starts at zero. We will nowadays use the monotonic timestamp of log records for them and adjust them by the most recent delta between CLOCK_REALTIME and CLOCK_MONOTONIC for the specific boot id. If we can look this up directly in the journal file header is relatively cheap and easy. But once we store more than one boot id in a file this becomes harder, because we now have to search for the boot ID inside the file. > > The message is debug level, no? > > log_ratelimit_info(), which appears to be printed by default when I log > in, and I presume my session systemd instance is started. I guess > that's the problem: it should be debug. File a bug, or better file a PR. > Also though, why doesn't it first note that the boot ID changed? It actually checks that first: https://github.com/systemd/systemd/blob/main/src/libsystemd/sd-journal/journal-file.c#L2201 Lennart -- Lennart Poettering, Berlin
Re: [systemd-devel] Monotonic time went backwards, rotating log
Lennart Poettering writes: > We want that within each file all records are strictly ordered by all > clocks, so that we can find specific entries via bisection. Why *all* clocks? Even if you want to search on the monotonic time, you first have to specify a boot ID within which that monotonic time is valid, don't you? So the first step in your search would be to find the boot records, then bisect from there. > The message is debug level, no? log_ratelimit_info(), which appears to be printed by default when I log in, and I presume my session systemd instance is started. I guess that's the problem: it should be debug. Also though, why doesn't it first note that the boot ID changed?
Re: [systemd-devel] Monotonic time went backwards, rotating log
On Di, 23.05.23 11:04, Phillip Susi (ph...@thesusis.net) wrote: > Every time I reboot, when I first log in, journald ( 253.3-r1 ) > complains that the monotonic time went backwards, rotating log file. > This appears to happen because journal_file_append_entry_internal() > wishes to enforce strict time ordering within the log file. I'm not > sure why it cares about the *monotonic* time being in strict order > though, since that will always go backwards when you reboot. I'm also > not sure why the previous check that the boot ID has changed did not > trigger. We want that within each file all records are strictly ordered by all clocks, so that we can find specific entries via bisection. Rotation doesn't mean systemd doesn't look at the records anymore. journalctl will look at all journal files it discoveres and display them in a single unified "interleaved" stream, so that you can't see that they are stored in separate journal files. > If it is intentional that journals be rotated after a reboot, could it > at least be done without complaining about it? The message is debug level, no? Lennart -- Lennart Poettering, Berlin
[systemd-devel] Monotonic time went backwards, rotating log
Every time I reboot, when I first log in, journald ( 253.3-r1 ) complains that the monotonic time went backwards, rotating log file. This appears to happen because journal_file_append_entry_internal() wishes to enforce strict time ordering within the log file. I'm not sure why it cares about the *monotonic* time being in strict order though, since that will always go backwards when you reboot. I'm also not sure why the previous check that the boot ID has changed did not trigger. If it is intentional that journals be rotated after a reboot, could it at least be done without complaining about it?
