[systemd-devel] journalctl --since today --follow weirdness

[Colin Guthrie]

'Twas brillig, and Colin Guthrie at 23/04/14 16:12 did gyre and gimble:
> Hiya,
> 
> A colleague pointed out an oddity in journalctl --since today --follow
> output.
> 
> It seems the two arguments somewhat contradict each other: one asks for
> all the output for today and the other asks for all future messages, but
> using them together should obviously behave in a somewhat sensible way!
> 
> What I was expecting was basically the same as what journalctl --follow
> would produce, but excluding any output not from today. e.g. if the
> first 5 lines of a standard journalctl -f happened to be from yesterday,
> then I'd expect only the 5 lines from today to be printed and then any
> further output as it happens.
> 
> What appears to happen instead is that you get the first 10 lines from
> the day (i.e. after midnight) and then *all* lines from today following
> that after a small delay (likely not a deliberate delay - just whatever
> overhead it takes to lookup and output the data), thus taking quite some
> time to page through which is definitely not what you expect from
> --follow, but arguably what you would expect from --since today. It's
> only the delay before full output that makes this very much feel like a
> bug rather than intentional (i.e. --since having a higher precedence
> than --follow's 10 line limit!)
> 
> This is with a recent version of the 208-stable branch.
> 
> Can someone confirm is this is still a problem in more recent versions?

Just to follow up on this while I notice the bug (so I can recheck on
more recent versions when I pull my finger out), but I noticed more
strange behaviour today.

My home server has been a little unstable of late and there have been a
couple random reboots... this morning I thought I'd try and look at the
logs to see if there was anything interesting before the reboot:


[root at marley ~]# date
Fri 23 May 09:05:38 BST 2014

[root at marley ~]# journalctl --since '2014-05-22 00:00:00' | tail -n1
May 23 07:42:01 marley.rasta.guthr.ie CROND[15012]: (root) CMD
(/root/lcc/update)

Hmm, the last line in the log is from more than an hour ago... seems
unlikely...


[root at marley ~]# journalctl --since '2014-05-23 00:00:00' | head -n2
-- Logs begin at Tue 2014-05-13 20:45:11 BST, end at Fri 2014-05-23
09:05:45 BST. --
May 23 07:43:08 marley.rasta.guthr.ie systemd-journal[553]: Runtime
journal is using 8.0M (max allowed 196.0M, trying to leave 294.0M free
of 1.9G available → current limit 196.0M).

Hmmm, strange, I change the --since argument to today's date and
suddenly the *first* line is from *after* the previous command's last
line... doesn't seem right!


[root at marley ~]# journalctl --since '2014-05-23 00:00:00' | tail -n1
May 23 09:05:45 marley.rasta.guthr.ie postfix/smtpd[3729]: disconnect
from unknown[117.213.206.10]

And just to confirm, a tail -n1 of the journal with a day newer --since
argument and it gets different results.


Something is wrong here. I suspect it's some kind of bug due to
improperly closed journals (i.e. my unexpected reboot).



FWIW, This is on a semi-recent 208-stable build, so no idea if this has
actually been fixed subsequently, but incorrect querying of data is
pretty bad.

I'll try and see if updated versions behave better (I've kept a backup
of my journal files to play with).

Col


-- 

Colin Guthrie
gmane(at)colin.guthr.ie
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited http://www.tribalogic.net/
Open Source:
  Mageia Contributor http://www.mageia.org/
  PulseAudio Hacker http://www.pulseaudio.org/
  Trac Hacker http://trac.edgewall.org/