Bug 64296

Summary: journalctl --since $DATE contains entries from before $DATE
Product: systemd Reporter: Jonas H. <jonas>
Component: generalAssignee: systemd-bugs
Status: RESOLVED WONTFIX QA Contact: systemd-bugs
Severity: normal    
Priority: medium CC: doak, drizzd, jonas
Version: unspecified   
Hardware: Other   
OS: All   
See Also: https://bugs.freedesktop.org/show_bug.cgi?id=64293
https://bugs.freedesktop.org/show_bug.cgi?id=59856
https://bugs.freedesktop.org/show_bug.cgi?id=64291
Whiteboard:
i915 platform: i915 features:

Description Jonas H. 2013-05-06 21:23:55 UTC
$ date
Mon May  6 23:21:04 CEST 2013
$ journalctl --since "2013-05-06 23:20" | head -n 20
-- Logs begin at Tue 2013-04-09 12:08:24 CEST, end at Sun 2060-02-15 19:22:01 CET. --
May 06 23:20:10 x201 ...
May 06 23:20:10 x201 ...
May 06 23:20:10 x201 ...
May 06 23:20:10 x201 ...
May 06 23:20:16 x201 ...
May 06 23:20:27 x201 ...
May 06 23:20:29 x201 ...
May 06 23:20:29 x201 ...
May 06 23:20:29 x201 ...
May 06 23:20:30 x201 ...
-- Reboot --
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Apr 17 04:05:40 x201 ...
Comment 1 Zbigniew Jedrzejewski-Szmek 2013-06-10 14:50:11 UTC
Can you check if http://cgit.freedesktop.org/systemd/systemd/commit/?id=87011c25d9 fixes things for you? Also,
http://cgit.freedesktop.org/systemd/systemd/commit/?id=cbd671772 should fix one the ways that looped journals are produced, but it won't immediately help if you have such journals currently.
Comment 2 Jonas H. 2013-06-12 07:58:44 UTC
Not fixed.
Comment 3 Zbigniew Jedrzejewski-Szmek 2013-07-03 15:34:16 UTC
OK, could you attach the offending journal files? They compress really well, usually to a few percent of their size. I could then make another attempt at finding out what is wrong.
Comment 4 Clemens Buchacher 2013-07-17 15:32:59 UTC
I appear to suffer from the same problem, or multiple problems. In addition to journalctl showing old messages, the messages are also interleaved with newer messages.

This is with latest master: v205-133-gc72aadd

I see the problem only as root. Even if the journal files are readable to the current user, as a normal user I cannot reproduce this behavior.

FWIW, I had a kernel panic on Jul 17 between 17:26 and 14:33, which is why I am looking at the logs.

I cannot post my raw journal here because it contains sensitive information. Is it possible to decode them to plain-text, such that I can strip out message contents, then re-encode them? Or is there some way to replace the message contents with dummy placeholders?

Do you have any other pointers how to debug this? Is the file format documented?

$ date
Wed Jul 17 16:45:38 CEST 2013
$ journalctl -D /var/log/journal/7077725e2734c7b16dbbe92a00000b89/ --since="2013-07-17 14:33:24" | head -20
-- Logs begin at Sat 2012-10-20 15:23:13 CEST, end at Wed 2013-07-17 17:08:58 CEST. --
Jul 17 14:33:24 [...]
Jul 17 14:33:25 [...]
-- Reboot --
Jun 15 10:28:50 [...]
-- Reboot --
Jul 17 14:33:25 [...]
-- Reboot --
Jun 15 10:28:50 [...]
Comment 6 Clemens Buchacher 2013-07-23 11:17:50 UTC
I have modified journalctl to output file and cursor instead of payload fields (https://github.com/drizzd/systemd), and now it is easy to see that the files user-120.journal and user-1000@0004df35caac7448-f0d0cc1ab7d0a25e.journal~ are inconsistent. They use the same seqnum_id, but their seqnums are not monotonic.

$ sudo ~/src/systemd/journalctl --since 2013-07-17 --until 2013-07-18
[...]
Jul 17 14:33:25 /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-120.journal
[s=1e8bf438a4954ed29f9f9e18d06d2ba8;i=23be3;b=f3bb91d108fe42088d15babff2094f17;m=249cc0d;t=4e1b44cd11eb4;x=a739d43d2e7dd4f0]
-- Reboot --
Jun 15 10:28:50 /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-1000@0004df35caac7448-f0d0cc1ab7d0a25e.journal~
[s=1e8bf438a4954ed29f9f9e18d06d2ba8;i=23be4;b=aba85173ce764cfbb338f9c1ee385293;m=ead55eac0;t=4df2d2726c2c8;x=9d6e45264e28f715]
-- Reboot --
Jul 17 14:33:26 /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-120.journal
[s=1e8bf438a4954ed29f9f9e18d06d2ba8;i=23be4;b=f3bb91d108fe42088d15babff2094f17;m=24f84b7;t=4e1b44cd6d75e;x=4c7b5deba69f0a1f]
-- Reboot --
Jun 15 10:28:50 /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-1000@0004df35caac7448-f0d0cc1ab7d0a25e.journal~
[s=1e8bf438a4954ed29f9f9e18d06d2ba8;i=23be5;b=aba85173ce764cfbb338f9c1ee385293;m=ead55eb4e;t=4df2d2726c356;x=9d6e45264e28f715]
[...]

File Path: /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-1000@0004df35caac7448-f0d0cc1ab7d0a25e.journal~
Sequential Number ID: 1e8bf438a4954ed29f9f9e18d06d2ba8
Head Sequential Number: 109789
Tail Sequential Number: 148676
Head Realtime Timestamp: Wed 2013-05-29 00:57:44 CEST
Tail Realtime Timestamp: Sat 2013-06-15 20:44:25 CEST

File Path: /var/log/journal/7077725e2734c7b16dbbe92a00000b89/user-120.journal
Sequential Number ID: 1e8bf438a4954ed29f9f9e18d06d2ba8
Head Sequential Number: 136044
Tail Sequential Number: 158116
Head Realtime Timestamp: Sun 2013-06-09 14:04:49 CEST
Tail Realtime Timestamp: Mon 2013-07-22 14:05:41 CEST

I have been running systemd 204 from May 20 until now.
Comment 7 Zbigniew Jedrzejewski-Szmek 2014-11-27 06:07:00 UTC
Is this still a problem with systemd >= 217?
Comment 8 Zbigniew Jedrzejewski-Szmek 2018-03-09 08:00:45 UTC
Closing all stale bugs with NEEDINFO. Please open a new bug at https://github.com/systemd/issues if the problem still occurs.

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.