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

[Rainer Gerhards]

> -----Original Message-----
> From: Michael Biebl [mailto:mbiebl at gmail.com]
> Sent: Friday, March 11, 2011 8:04 AM
> To: Andrey Borzenkov
> Cc: Mike Kazantsev; systemd-devel at lists.freedesktop.org; Rainer
> Gerhards
> Subject: Re: [systemd-devel] systemd-logger and external syslog daemon
> 
> 2011/2/26 Andrey Borzenkov <arvidjaar at mail.ru>:
> > On Wed, Feb 23, 2011 at 10:48 AM, Mike Kazantsev
> <mk.fraggod at gmail.com> wrote:
> >>
> >> I've recently deployed systemd on a machine that uses some syslog
> >> monitoring software and the software went nuts because messages from
> >> systemd logger were inconsistent with other logging - they all look
> >> like this:
> >>
> >>  kernel.warning kernel[-]: process[pid]: message contents
> >>
> >
> > I confirm this at least for one special case - redirecting service
> > output to syslog. Here is how it looks like:
> >
> > Mar  1 06:35:53 localhost kernel: crond[847]: Starting crond: [  OK
>  ]^M[  OK  ]
> > Mar  1 06:35:53 localhost kernel: atd[850]: Starting atd: [  OK  ]
> 
> 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.
> 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 occured.
> 
> Rainer, can you share any insight on this matter?

Lennart recommended that to me and I had some code in place to do it.
However, at that time this did not work because the kernel did not record
that timestamp. This was added a while later, but I did not yet revisit that
issue. I was a bit hesitant to dig into this issue as I found no simple
enough method to setup a system with systemd (I know it's important, but
there are many other important things as well...). I'll see that I can at
least see what kernel patch needs to be present. 

Rainer