[syslog-ng] kernel logging feature requests

[Balazs Scheidler]

On Mon, 2012-01-30 at 23:59 -0500, Patrick Hemmer wrote:
> Sent: Wed Sep 28 2011 03:19:43 GMT-0400 (EDT)
> From: Balazs Scheidler <bazsi at balabit.hu>
> To: Syslog-ng users' and developers' mailing list 
> <syslog-ng at lists.balabit.hu>
> Subject: Re: [syslog-ng] kernel logging feature requests
> > On Wed, 2011-09-21 at 17:33 +0200, Gergely Nagy wrote:
> >> Balazs Scheidler<bazsi at balabit.hu>  writes:
> >>
> >>> On Fri, 2011-09-16 at 21:16 -0600, Patrick H. wrote:
> >>>> While setting up a new server at home I've come across 2 feature
> >>>> requests that would be fairly nice to have (and not that hard to
> >>>> implement I would think).
> >>>>
> >>>> 1) When the 'kernel' flag is set on a file() source (like for
> >>>> reading /proc/kmsg), look for the printk time (eg "[ 1234.567890]")
> >>>> and calculate when the message would have occurred instead of just
> >>>> using when the line was read off the file. Basically check to see the
> >>>> number of seconds the system has been up, subtract the printk time,
> >>>> and then subtract that from current time.
> >>> this would be useful, I agree.
> >> +1.
> >>
> >> I was pondering about how to do this properly. On one hand, extracting
> >> the timestamp from the message is easy with patterndb. But converting it
> >> to a proper date is a harder task that way (off the top of my head, that
> >> would require a way to figure out the bootup time, preferably once only;
> >> and a way to format an arbitrary timestamp to a date).
> >>
> >> Another solution would be to add a flag(parse-kernel-uptime) flag or
> >> similar, and implement support for it directly in syslog-ng. This would
> >> override the $DATE macros.
> >>
> >> There's probably other ways to do this, perhaps even easier and more
> >> convenient ways. Any other ideas?
> > The kernel flag currently changes the default facility/severity to
> > kern.info instead of user.info.
> >
> > The only issue I see with using the kernel flag is that syslog-ng may
> > run on non-Linux systems, where the kernel message format is different,
> > but that's probably not a problem.
> >
> > Implementation wise this should probably go to the syslogformat plugin,
> > which already contains a wealth of heuristics wrt message format. One
> > more wouldn't hurt, especially if the kernel flag guards it.
> >
> > Something along the lines of:
> >
> > index 640092b..0a36003 100644
> > --- a/modules/syslogformat/syslog-format.c
> > +++ b/modules/syslogformat/syslog-format.c
> > @@ -262,6 +262,15 @@ log_msg_parse_date(LogMessage *self, const guchar **data, gint *length, guint pa
> >       }
> >     else if ((parse_flags&  LP_SYSLOG_PROTOCOL) == 0)
> >       {
> > +
> > +#ifdef __linux__
> > +      if ((parse_options->flags&  LP_KERNEL)&&  left>  2&&  src[0] == '['&&  (src[1] == ' ' || isdigit(src[1])))
> > +        {
> > +          /* get out the number of the string and put a UTC time into self->timestamps[LM_TS_STAMP] */
> > +        }
> > +      else
> > +#endif
> > +
> >         if (left>= 21&&  src[3] == ' '&&  src[6] == ' '&&  src[11] == ' '&&  src[14] == ':'&&  src[17] == ':'&&  (src[20] == ':' || src[20] == ' ')&&
> >             (isdigit(src[7])&&  isdigit(src[8])&&  isdigit(src[9])&&  isdigit(src[10])))
> >           {
> >
> > This would only be enabled when running on Linux and the "kernel" option was set. Different
> > platforms could then implement their own similar processing tied to the kernel flag, if they
> > have kernel specific message formatting.
> >
> >>>> 2) I grab all kernel messages with priority of crit or higher and send
> >>>> it to the usertty() destination, but this destination doesnt support
> >>>> templates. It'd be nice to be able to define the template. I mostly
> >>>> just want to change the time format and remove the hostname (since
> >>>> these will only come from localhost on my setup).
> >> [...]
> >>
> >>> Anyone volunteering?
> >> Unless someone beats me to it, I'll do it, when time permits. But it
> >> would be better if someone else stepped up, it's an easy task, and I'll
> >> gladly give pointers. You don't even have to know much C!
> >>
> 
> So, I was going to take a crack at this, but it does not appear 
> possible. The time shown in printk times is calculated from the number 
> of jiffies since boot. However userspace is not allowed access to the 
> jiffies. Posts on the web say you can use /proc/uptime to get this 
> instead, however this appears incorrect as /proc/uptime does not match 
> printk time on my laptop. On my main server at home, they do indeed 
> match. I'm guessing my laptop doesnt because my laptop suspends a lot. 
> It would appear that /proc/uptime includes time that the system was 
> suspended, so it gets ahead of printk time.
> So unless there's some way to get jiffies (whether direct jiffies, or 
> some way of calculating what jiffies would be from a different 
> variable), there's no way to do this.

Hmm... bad news. clock_gettime(CLOCK_MONOTONIC) may be the same though,
as by the reading of the man page it should be equal to the jiffies,
converted to human time.

so the base of the offset here should be the boot time, which can be
deduced from CLOCK_MONOTONIC, can't it?

-- 
Bazsi