Re: [systemd-devel] journalctl --since today --follow weirdness
'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@marley ~]# date Fri 23 May 09:05:38 BST 2014 [root@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@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@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/ ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] journalctl --since today --follow weirdness
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? Cheers 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/ ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journalctl --since today --follow weirdness
On Wed, Apr 23, 2014 at 6:12 PM, Colin Guthrie gm...@colin.guthr.ie wrote: 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) strace shows that it isn't looking up any data; it's actually waiting for inotify events for the --follow mode. Seems odd. -- Mantas Mikulėnas graw...@gmail.com ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journalctl --since today --follow weirdness
Yeah, I see this with systemd 212. And let me clarify a little bit: this delay after showing first 10 lines is not a result of looking up for something; Following lines appear as soon as there is something new in the log (that is, actually what `-f` does). So, here is what I see: I type `journalctl --since today -f`. First 10 lines from today appear. As soon as something is written to log (e.g. I simulate this by deliberately failing a `sudo` authentication) all the remaining lines from today (including the new ones, of course) appear. That's clearly a bug. -- Кирилл Елагин On Wed, Apr 23, 2014 at 8:05 PM, Mantas Mikulėnas graw...@gmail.com wrote: On Wed, Apr 23, 2014 at 6:12 PM, Colin Guthrie gm...@colin.guthr.ie wrote: 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) strace shows that it isn't looking up any data; it's actually waiting for inotify events for the --follow mode. Seems odd. -- Mantas Mikulėnas graw...@gmail.com ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journalctl --since today --follow weirdness
On Wed, 23.04.14 16:12, Colin Guthrie (gm...@colin.guthr.ie) wrote: 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 actually happens is that the output will show you everything from today, and when it is done with that continue with a live output. To me this appears as the right thing to do, no? To me --follow is kinda the little add-on just says and then continue live... Of course, this definition means that --until and --follow are contradictory when combined, so we should probably just check for that and exit with an error 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!) Hmm, I am actually seeing that I get the full output of today, plus anything that happens afterwards, this looks quite ok to me... This is with a recent version of the 208-stable branch. can you check with git? Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journalctl --since today --follow weirdness
I've checked the code, and the issue is, basically, that `--since` and skipping to the end with `--follow` are in a way “mutually exclusive”, that is, they are handled in a single `if … else if …` statement, so, because `--since` is processed first, we don't skip to head. But since `--follow` sets arg_lines to 10, we still get just 10 lines of output. And then the rest. -- Кирилл Елагин On Wed, Apr 23, 2014 at 9:53 PM, Kirill Elagin kirela...@gmail.com wrote: Yeah, I see this with systemd 212. And let me clarify a little bit: this delay after showing first 10 lines is not a result of looking up for something; Following lines appear as soon as there is something new in the log (that is, actually what `-f` does). So, here is what I see: I type `journalctl --since today -f`. First 10 lines from today appear. As soon as something is written to log (e.g. I simulate this by deliberately failing a `sudo` authentication) all the remaining lines from today (including the new ones, of course) appear. That's clearly a bug. -- Кирилл Елагин On Wed, Apr 23, 2014 at 8:05 PM, Mantas Mikulėnas graw...@gmail.comwrote: On Wed, Apr 23, 2014 at 6:12 PM, Colin Guthrie gm...@colin.guthr.ie wrote: 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) strace shows that it isn't looking up any data; it's actually waiting for inotify events for the --follow mode. Seems odd. -- Mantas Mikulėnas graw...@gmail.com ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journalctl --since today --follow weirdness
On Wed, Apr 23, 2014 at 10:16 PM, Lennart Poettering lenn...@poettering.net wrote: What actually happens is that the output will show you everything from today, and when it is done with that continue with a live output. Not exactly. You don't get _everything_ form to day, you get just arg_lines lines. And you get the rest from today when something new is added to log. This happens because `--follow` sets args_lines to 10 and once n_shown is 10 we pause waiting for more lines to come, and once they come we output everything in bulk. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
