Bug 80858

Summary: journalctl misbehaves when wall clock is changed
Product: systemd Reporter: Marius Vollmer <marius.vollmer>
Component: generalAssignee: systemd-bugs
Status: NEW --- QA Contact: systemd-bugs
Severity: normal    
Priority: medium CC: radek
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: test program.

Description Marius Vollmer 2014-07-03 14:49:15 UTC
Created attachment 102202 [details]
test program.

With a specific set of journal files, we are seeing some odd behavior.  The journal files cover multiple boots and have walltime discontinuities in them.

I'll send the journal files on request.

$ journalctl -D XXX/var/log/journal/ --cursor 's=de164a5e12e64f03b334128e4542ec9a;i=edb36;b=88b9ffdd4d2c40c1836f4a4d11c7d2bc;m=145f5aa0ae;t=4fc1b3c1b82f7;x=cf69db9bc053ff06' -u NetworkManager --show-cursor | tail -1
-- cursor: s=a6243fe62e0d45939c17eb9cb76f8812;i=11c34e;b=3e5244c588534eb4b4f3645d56b011c1;m=260accecf9;t=4fd38316fe7ed;x=38925d7bd704ad1d
$ journalctl -D XXX/var/log/journal/ --cursor 's=a6243fe62e0d45939c17eb9cb76f8812;i=11c34e;b=3e5244c588534eb4b4f3645d56b011c1;m=260accecf9;t=4fd38316fe7ed;x=38925d7bd704ad1d' -u NetworkManager --show-cursor | tail -1
-- cursor: s=de164a5e12e64f03b334128e4542ec9a;i=edb36;b=88b9ffdd4d2c40c1836f4a4d11c7d2bc;m=145f5aa0ae;t=4fc1b3c1b82f7;x=cf69db9bc053ff06

Thus, there are two cursors, and starting from one ends up at the other.

Also, doing sd_journal_seek_tail(), sd_journal_skip_previous(10) and then looping over sd_journal_next until it returns 0 will happily loop over thousands of entries, instead of the expected 10.

I attach a small program that combines these effects to get into an endless loop, although it works correctly for most journal files.
Comment 1 Philip Donlon 2014-07-03 15:12:36 UTC
Here are the journal files that produce the loop:

https://drive.google.com/file/d/0B_MyU2g8XYMrR2RQSndTTVlMNzA/edit?usp=sharing
Comment 2 Marius Vollmer 2014-07-04 06:40:11 UTC
Forgot to mention: This only fails with a match.  Without the '-u' option, this happens:

$ journalctl -D XXX/var/log/journal/ --cursor 's=a6243fe62e0d45939c17eb9cb76f8812;i=11c34e;b=3e5244c588534eb4b4f3645d56b011c1;m=260accecf9;t=4fd38316fe7ed;x=38925d7bd704ad1d' --show-cursor | tail -1
-- cursor: s=a6243fe62e0d45939c17eb9cb76f8812;i=11c363;b=3e5244c588534eb4b4f3645d56b011c1;m=261ef68e3f;t=4fd3845998933;x=84b1b3c1b922ad2e
$ journalctl -D XXX/var/log/journal/ --cursor 's=a6243fe62e0d45939c17eb9cb76f8812;i=11c363;b=3e5244c588534eb4b4f3645d56b011c1;m=261ef68e3f;t=4fd3845998933;x=84b1b3c1b922ad2e' --show-cursor | tail -1
-- cursor: s=a6243fe62e0d45939c17eb9cb76f8812;i=11c363;b=3e5244c588534eb4b4f3645d56b011c1;m=261ef68e3f;t=4fd3845998933;x=84b1b3c1b922ad2e

Thus, no looping between cursors.
Comment 3 George McCollister 2014-09-23 19:56:04 UTC
Has anyone looked into this problem?

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.