[systemd-devel] Moving to systemd39: early kernel msg missed in rsylog logs

[Lennart Poettering]

On Fri, 27.01.12 12:46, Warpme (warpme at o2.pl) wrote:

> Hi *
>
> I just moved my ArchLinux based server from systemd37 to 39.
> Basically all went well.
> For successful logging via rsyslog I do following:
> 1.symlink /lib/systemd/system/rsyslog.service to
> /etc/systemd/system/rsyslog.service
> 2.added in rsyslog.conf entry $SystemLogSocketName
> /run/systemd/journal/syslog
> 3.run systemctl enable rsyslog.service
>
> System boots OK.
> Issue which I have is related to logging messages by rsyslog. I
> don't have first 5-6 sec of booting in rsyslog logs.
> i.e. first entry in rsylog's generated log files is from 10:42:22,
> while systemd-journal show very early boot messages from 10:42:17
> onward.
> rsyslog logging start seems to be correlated with start of imklog as
> by rsyslog files imklog also starts at 10:42:22.
>
> All this is little strange for me as before moving production server
> to systemd39 I make sure all is working OK with systemd39. I do this
> by mirroring my whole server to VM and do tests.
> Starting my server under VM gives me rsyslog files with all messages
> as expected (according to logs imklog starts at very beginning).
> Only difference between real server and VM is virtualization (CPU
> speed, RAM and virtualized HW) so maybe may issue is result of some
> king of races ?
>
> May somebody hint me how to resolve this issue ?

So, I forgot to mention this, I probably should have in the annoucnement
of 38 wiht the journal:

There can only be one reader of /proc/kmsg. By default journald upstream
is configured to do that, but this will collide with a syslog
implementation doing the same. If both a syslog implementation and
journald read from /proc/kmsg then it's undefined which of the two will
get the data, sometimes one, sometimes the other, it's basically a
race. To make this more confusing journald forwards all kernel messages
it reads to the real syslog, but the real syslog doesn't send its
back. So the syslog will see the full thing, the journal won't, but to
syslog some of the kernel messages actually come in via the kernel
interface (i.e. /proc/kmsg), while others come in via the userspace
interface (i.e. the AF_UNIX/SOCK_DGRAM syslog socket), possibly causing
some misattribution.

Now, there are two choices here:

a) Tell the syslog implementation to stop reading from /proc/kmsg, so
that only journald will. You'll have all data in syslog and in the
journal, but in syslog they might possibly be misattributed to userspace
although they come from kernelspace.

b) Tell journald to stop reading from /proc/kmsg (ImportKernel=no in
/etc/systemd/systemd-journald.conf). You'll have the complete, correctly
attributed data in syslog, but not in the journal.

(There's actually a third option: uninstall syslog and only use the journal)

We ship with ImportKernel=yes by default from upstream in systemd. In
Fedora I will however set that to ImportKernel=no by default
(i.e. option b), since we install a syslog implementation by default,
and I'd like to avoid the kernel/userspace misattribution problem.

No I figure the early boot stuff is missing for you because the journald
is written so that i can start as one of the fist processes around,
i.e. without /var being around and so on. Syslog implementations are
generally not like that. That means their socket is traditionally
created much later and hence they lose the early boot messages.

Lennart

--
Lennart Poettering - Red Hat, Inc.