[systemd-devel] systemd-logger and external syslog daemon

[Andrey Borzenkov]

On Fri, Mar 11, 2011 at 11:55 AM, Rainer Gerhards
<rgerhards at hq.adiscon.com> wrote:
>> -----Original Message-----
>> From: Andrey Borzenkov [mailto:arvidjaar at mail.ru]
>> Sent: Friday, March 11, 2011 8:38 AM
>> To: Michael Biebl
>> Cc: Mike Kazantsev; systemd-devel at lists.freedesktop.org; Rainer
>> Gerhards
>> Subject: Re: [systemd-devel] systemd-logger and external syslog daemon
>>
>> On Fri, Mar 11, 2011 at 10:03 AM, Michael Biebl <mbiebl at gmail.com>
>> wrote:
>> > For me the log messages actually look slightly different, as I also
>> > get the kernel timestamp and I also noticed a different problem:
>> >
>> > Mar 11 07:56:27 pluto kernel: imklog 5.7.8, log source = /proc/kmsg
>> started.
>> > Mar 11 07:56:27 pluto rsyslogd: [origin software="rsyslogd"
>> > swVersion="5.7.8" x-pid="25093" x-info="http://www.rsyslog.com"]
>> start
>> > Mar 11 07:56:27 pluto kernel: [ 5913.491848] michael[24089]: foo
>> > Mar 11 07:56:27 pluto kernel: [ 5918.029738] michael[24911]: bar
>> > Mar 11 07:56:27 pluto kernel: [ 5921.140864] michael[25078]: baz
>> >
>> > As you can see, when rsyslog starts up and flushes the kmsg queue,
>> the
>> > log messages all have the same timestamp (Mar 11 07:56:27) and they
>> > come after the rsyslog startup message, although they were logged
>> > before the  rsyslog start.
>>
>> But that was the case for as long as I remember. It is not systemd
>> specific in any way.
>>
>> > Lennart argues, that this should be handles within the syslogd (in
>> > this case rsyslog 5.7.8), which should use the kernel time stamp to
>> > compute the correct time when the log message occurred.
>> >
>>
>> Sounds quite reasonable :)
>>
>> What would be also really nice - some systemd specific marker so
>> rsyslog could extract syslogd messages from kmsg. Not sure if it is
>> really doable without some gross kernel hack though.
>>
>> Special severity level may be ... PRINTK_SYSTEMD? :)
>
> There is also a subtle issue with the current systemd implementation, and
> that could potentially solved by such a setting.
>
> Systemd shuffles the system log socket to the kernel log. That is nice,
> because we have logging available right from the system start. However, in
> rsyslog users can configure different rules based on the log source. The
> issue now is that what used to be the local log socket source now becomes the
> kernel log source. I don't think this causes many problems in almost all
> environments, and I guess it would require some non-trivial "magic" in
> rsyslog to handle the situation (and I am not sure it is worth that). But I
> wanted to mention this point ;)
>

Actually looking at kernel printk implementation, it is pretty robust
and will just pass unknown severity through. Which means that
prefixing them with e.g. <s> will mark lines as belonging to systemd
and allow further filtering and post-processing.