kernel logging feature requests
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. 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).
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.
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).
Also, seems quite useful. usertty() was created before templates were used for anything but filenames. I'm right in the middle of pulling the PE related changes into the OSE tree finally, so I'm not sure when I can work on these. The option needs to be added to the grammar (afuser-grammar.ym), then the compiled template stored in the AFUserDestDriver. Then where the current sprintf() code formats the message in afuser_dd_queue(), the template expansion code be called (log_template_format()), and write that to the terminal. The best would be if the current format would be the default value of the template() option, so that no branches would be needed in afuser_dd_queue() for the templetized case. Anyone volunteering? -- Bazsi
Balazs Scheidler <bazsi@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?
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! -- |8]
Sent: Wed Sep 21 2011 09:33:40 GMT-0600 (MST) From: Gergely Nagy <algernon@balabit.hu> To: Syslog-ng users' and developers' mailing list <syslog-ng@lists.balabit.hu> Subject: Re: [syslog-ng] kernel logging feature requests
Balazs Scheidler<bazsi@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?
Well I think you'd have to calculate this on every message received. If you do something just once like what time the system booted, if the system time changes, then values calculated off that will be inaccurate. Also I question if we need a separate flag. If we just use the pre-existing 'kernel' flag, we can assign the calculated time to the S_ macros (S_HOUR, S_DATE, etc), and then have R_ macros be the time it was read off the line.
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! I might have time to do this this weekend. I'm the on-call at work this week, so I'll be chained to my computer anyway. But I dont know. Seems like none of us can figure if we'll have time to do this or not :-). So if I do it, I'll just respond to this thread.
"Patrick H." <syslogng@feystorm.net> writes:
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?
Well I think you'd have to calculate this on every message received. If you do something just once like what time the system booted, if the system time changes, then values calculated off that will be inaccurate.
Hrm, true. I didn't consider moving time.
Also I question if we need a separate flag. If we just use the pre-existing 'kernel' flag, we can assign the calculated time to the S_ macros (S_HOUR, S_DATE, etc), and then have R_ macros be the time it was read off the line.
Oh, we have a kernel flag? O:) Then we can reuse that, yes. I'll see if I can come up with something over the weekend or so.
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! I might have time to do this this weekend. I'm the on-call at work this week, so I'll be chained to my computer anyway. But I dont know. Seems like none of us can figure if we'll have time to do this or not :-). So if I do it, I'll just respond to this thread.
*cheers* -- |8]
On Wed, 2011-09-21 at 17:33 +0200, Gergely Nagy wrote:
Balazs Scheidler <bazsi@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!
-- Bazsi
Sent: Wed Sep 28 2011 03:19:43 GMT-0400 (EDT) From: Balazs Scheidler <bazsi@balabit.hu> To: Syslog-ng users' and developers' mailing list <syslog-ng@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@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. -Patrick
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@balabit.hu> To: Syslog-ng users' and developers' mailing list <syslog-ng@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@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
Sent: Wed Feb 01 2012 05:58:52 GMT-0500 (EST) From: Balazs Scheidler <bazsi@balabit.hu> To: Patrick Hemmer <syslogng@stormcloud9.net> Syslog-ng users' and developers' mailing list <syslog-ng@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@balabit.hu> To: Syslog-ng users' and developers' mailing list <syslog-ng@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@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
participants (4)
-
Balazs Scheidler
-
Gergely Nagy
-
Patrick H.
-
Patrick Hemmer