[syslog-ng] kernel logging feature requests

[Patrick Hemmer]

Sent: Wed Feb 01 2012 05:58:52 GMT-0500 (EST)
From: Balazs Scheidler <bazsi at balabit.hu>
To: Patrick Hemmer <syslogng at stormcloud9.net> Syslog-ng users' and 
developers' mailing list <syslog-ng at lists.balabit.hu>
Subject: Re: [syslog-ng] kernel logging feature requests
> 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?
I thought of that, but everywhere says that while CLOCK_MONOTONIC will 
increase at the same rate as jiffies, theres nothing that guarantees it 
was initialized at the same time jiffies start being counted. So while 
it might work, I was hesitant to use something that could change in the 
future.

-Patrick