Re: [gentoo-amd64] Systemd migration: opinion and questions

[Marc Joliet]

Am Tue, 24 Feb 2015 21:15:45 +0100
schrieb Marc Joliet <marcec@×××.de>:

> However, I did find something unexpected.  I haven't looked deeply yet, but I
> noticed some dmesg entries not ending up in the journal (i.e., a bunch of "-"
> lines in-between the "+" lines in the diff output). Did I do something wrong, or
> is this known behaviour when running the journal and syslog-ng simultaneously?
> I'll look more closely tomorrow, but wondered if anybody here noticed anything
> similar.

OK, I looked at the logs.  It turns out that it was simply that various log
entries (mostly dmesg logs) were positioned differently or given different time
stamps.  For example, this pinentry segfault:

    Feb 15 01:11:03 arthur lightdm[1445]: ** (lightdm:1445): WARNING **: Could not create user data directory /var/lib/lightdm-data/marcec: Error creating directory: No such file or directory
   -Feb 15 01:12:13 arthur kernel: [  159.526696] pinentry[2323]: segfault at 18 ip 00007fe8e025965c sp 00007fffa2ba4678 error 4 in libncursesw.so.5.9[7fe8e023e000+5d000]
   +Feb 15 01:11:03 arthur lightdm[1891]: pam_unix(lightdm:session): session opened for user marcec by (uid=0)
   [...]
   +Feb 15 01:12:13 arthur kernel: pinentry[2323]: segfault at 18 ip 00007fe8e025965c sp 00007fffa2ba4678 error 4 in libncursesw.so.5.9[7fe8e023e000+5d000]

Notice that the journal entry is missing the dmesg time stamp.  The reason for
that (whatever it is) is probably also the reason why some entries have slightly
different time stamps (e.g., 01:09:54 vs. 01:09:40).

I didn't look at every single difference, but it looks like no messages was
missed.

Ah, no, there is one class of messages that only went to syslog-ng:

    -Feb 18 19:48:27 arthur kernel:    6.803784] systemd-journald[132]: Received request to flush runtime journal from PID 1
    -Feb 18 19:52:14 arthur kernel:  245.293713] systemd-journald[132]: Failed to read ACL on /var/log/journal/b3a495d35e890b80816684a4521fc1cc/user-1000.journal, ignoring: Operation not supported

(Note that the ACL thing is fixed, I simply did't have btrfs POSIX ACL support
activated before the migration.)

That's... interesting.  Why does the journal not contain these entries
relating to itself? All I can find in the journal related to flushing are lots
of "Time spent on flushing" entries:

    % journalctl|grep flush
    Feb 15 00:19:45 arthur systemd-journal[131]: Time spent on flushing to /var is 20.220ms for 798 entries.
    Feb 15 00:25:20 arthur kernel: nr_pdflush_threads exported in /proc is scheduled for removal
    Feb 15 00:32:36 arthur systemd-journal[131]: Time spent on flushing to /var is 570.566ms for 775 entries.
    [...]

Grepping for ACL also turns up empty.  What gives?

-- 
Marc Joliet
--
"People who think they know everything really annoy those of us who know we
don't" - Bjarne Stroustrup