Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Thursday, March 17, 2011 10:38 PM To: Rainer Gerhards Cc: Michael Biebl; Andrey Borzenkov; systemd- de...@lists.freedesktop.org Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Thu, 17.03.11 08:38, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: You mean a new udev/dracut/systemd on an old kernel? The messages they print would look a bit weird if they are used together with log msg timestamping the way the kernel does it, since the kernel doesn't recognize the prefix. (See Kay's post about this). But besides these cosmetic issues nothing should really go wrong. (I wonder if we can find a nice way to detect whether the kernel is new enough for this, so that we could strip the facility automatically for older ones. Explcitily checking for kernel versions at runtime is evil though... I can't think of a good way though...) Wouldn't it work to check if there is a PRI right at the start of the message? I think that it is actual user data would be extremely improbable, so this should be a good enough indication. That way, we could pull the PRI even without the kernel patch (but, granted, it is kind of an interface change...). Hmm? The question is how we can detect whether it is safe to write messages to kmsg with PRI values with more than 3 bits. 2.6.39 and above will be able to handle that properly, even if you enable per-line printk kernel timestamping. On 2.6.38 only 3-bit-PRI values will look good if you use printk kernel timestamping. Probably I misunderstood the answer to what happens on a kernel without that patch if a full PRI is written?. I understood the answer was the PRI is moved into the message. So 123msg would actually become 1 [TS] 123Msg From your answer I deduce this understanding is incorrect. So what will then happen on kernels without that patch if printk is provided a message 123MSg? Rainer ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, Mar 18, 2011 at 08:19, Rainer Gerhards rgerha...@hq.adiscon.com wrote: -Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Thursday, March 17, 2011 10:38 PM To: Rainer Gerhards Cc: Michael Biebl; Andrey Borzenkov; systemd- de...@lists.freedesktop.org Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Thu, 17.03.11 08:38, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: You mean a new udev/dracut/systemd on an old kernel? The messages they print would look a bit weird if they are used together with log msg timestamping the way the kernel does it, since the kernel doesn't recognize the prefix. (See Kay's post about this). But besides these cosmetic issues nothing should really go wrong. (I wonder if we can find a nice way to detect whether the kernel is new enough for this, so that we could strip the facility automatically for older ones. Explcitily checking for kernel versions at runtime is evil though... I can't think of a good way though...) Wouldn't it work to check if there is a PRI right at the start of the message? I think that it is actual user data would be extremely improbable, so this should be a good enough indication. That way, we could pull the PRI even without the kernel patch (but, granted, it is kind of an interface change...). Hmm? The question is how we can detect whether it is safe to write messages to kmsg with PRI values with more than 3 bits. 2.6.39 and above will be able to handle that properly, even if you enable per-line printk kernel timestamping. On 2.6.38 only 3-bit-PRI values will look good if you use printk kernel timestamping. Probably I misunderstood the answer to what happens on a kernel without that patch if a full PRI is written?. I understood the answer was the PRI is moved into the message. So 123msg would actually become 1 [TS] 123Msg From your answer I deduce this understanding is incorrect. So what will then happen on kernels without that patch if printk is provided a message 123MSg? http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=9d90c8d9cde929cbc575098e825d7c29d9f45054 Kay ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, Mar 18, 2011 at 14:30, Rainer Gerhards rgerha...@hq.adiscon.com wrote: On 03/18/2011 01:53 PM, Kay Sievers wrote: http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=9d90c8d9cde929cbc575098e825d7c29d9f45054 That's what I understood and what I based my proposal on. In that case, rsyslog can simply check if there is an additional priority. I just did some quick PoC: http://git.adiscon.com/?p=rsyslog.git;a=commitdiff;h=bb67fd7fbf99ce0ec01b347fad5d1d9d101bfa5d Looks like it works pretty well. So systemd could simply always write the full priority and the syslogd would just need to check for the extra header. If the syslogd is not capable of doing that, the message will look a bit strange. But in that case, the priority is wrong in any case, and so chances it will be properly routed are slim... Sounds all good to me. Thanks a lot for your help and cooperation, Kay ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Thursday, March 17, 2011 12:31 AM To: Michael Biebl Cc: Andrey Borzenkov; systemd-devel@lists.freedesktop.org; Rainer Gerhards Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Wed, 16.03.11 07:18, Michael Biebl (mbi...@gmail.com) wrote: 2011/3/16 Lennart Poettering lenn...@poettering.net: On Sat, 12.03.11 16:31, Andrey Borzenkov (arvidj...@mail.ru) wrote: Attached patch preserves full syslog facility marker and simply emits it back. So userspace is free to feed any facility it deems appropriate, not only LOG_USER. This is a good approach. Kay has independently prepped a patch for this now and it is already on its way into the kernel. It is hence very likely that pretty soon there's no reason anymore to strip the facility from the log messages before echoing them into /proc/kmsg. As soon as that patch is in the standard kernel I'll fix systemd to no longer strip the facility. Kay will do the same for udev. And Harald hopefully for Dracut too. And then all messages should contain the same amount of information regardless which way the took to the syslog daemon: directly via the /dev/log socket, or indirectly via the kmsg queue. What happens if you run udev/dracut/systemd on a kernel without this patch? You mean a new udev/dracut/systemd on an old kernel? The messages they print would look a bit weird if they are used together with log msg timestamping the way the kernel does it, since the kernel doesn't recognize the prefix. (See Kay's post about this). But besides these cosmetic issues nothing should really go wrong. (I wonder if we can find a nice way to detect whether the kernel is new enough for this, so that we could strip the facility automatically for older ones. Explcitily checking for kernel versions at runtime is evil though... I can't think of a good way though...) Wouldn't it work to check if there is a PRI right at the start of the message? I think that it is actual user data would be extremely improbable, so this should be a good enough indication. That way, we could pull the PRI even without the kernel patch (but, granted, it is kind of an interface change...). Rainer ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Thu, 17.03.11 08:38, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: You mean a new udev/dracut/systemd on an old kernel? The messages they print would look a bit weird if they are used together with log msg timestamping the way the kernel does it, since the kernel doesn't recognize the prefix. (See Kay's post about this). But besides these cosmetic issues nothing should really go wrong. (I wonder if we can find a nice way to detect whether the kernel is new enough for this, so that we could strip the facility automatically for older ones. Explcitily checking for kernel versions at runtime is evil though... I can't think of a good way though...) Wouldn't it work to check if there is a PRI right at the start of the message? I think that it is actual user data would be extremely improbable, so this should be a good enough indication. That way, we could pull the PRI even without the kernel patch (but, granted, it is kind of an interface change...). Hmm? The question is how we can detect whether it is safe to write messages to kmsg with PRI values with more than 3 bits. 2.6.39 and above will be able to handle that properly, even if you enable per-line printk kernel timestamping. On 2.6.38 only 3-bit-PRI values will look good if you use printk kernel timestamping. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Wed, Mar 16, 2011 at 07:18, Michael Biebl mbi...@gmail.com wrote: 2011/3/16 Lennart Poettering lenn...@poettering.net: On Sat, 12.03.11 16:31, Andrey Borzenkov (arvidj...@mail.ru) wrote: Attached patch preserves full syslog facility marker and simply emits it back. So userspace is free to feed any facility it deems appropriate, not only LOG_USER. This is a good approach. Kay has independently prepped a patch for this now and it is already on its way into the kernel. It is hence very likely that pretty soon there's no reason anymore to strip the facility from the log messages before echoing them into /proc/kmsg. As soon as that patch is in the standard kernel I'll fix systemd to no longer strip the facility. Kay will do the same for udev. And Harald hopefully for Dracut too. And then all messages should contain the same amount of information regardless which way the took to the syslog daemon: directly via the /dev/log socket, or indirectly via the kmsg queue. What happens if you run udev/dracut/systemd on a kernel without this patch? The kernel will not recognize the prefix, add the default one and keep the old prefix in the message: Before: $ echo '14text' /dev/kmsg $ dmesg -r 4[135159.594810] 14text After: $ echo '14text' /dev/kmsg $ dmesg -r 14[ 50.750654] text Kay ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Wed, 16.03.11 07:18, Michael Biebl (mbi...@gmail.com) wrote: 2011/3/16 Lennart Poettering lenn...@poettering.net: On Sat, 12.03.11 16:31, Andrey Borzenkov (arvidj...@mail.ru) wrote: Attached patch preserves full syslog facility marker and simply emits it back. So userspace is free to feed any facility it deems appropriate, not only LOG_USER. This is a good approach. Kay has independently prepped a patch for this now and it is already on its way into the kernel. It is hence very likely that pretty soon there's no reason anymore to strip the facility from the log messages before echoing them into /proc/kmsg. As soon as that patch is in the standard kernel I'll fix systemd to no longer strip the facility. Kay will do the same for udev. And Harald hopefully for Dracut too. And then all messages should contain the same amount of information regardless which way the took to the syslog daemon: directly via the /dev/log socket, or indirectly via the kmsg queue. What happens if you run udev/dracut/systemd on a kernel without this patch? You mean a new udev/dracut/systemd on an old kernel? The messages they print would look a bit weird if they are used together with log msg timestamping the way the kernel does it, since the kernel doesn't recognize the prefix. (See Kay's post about this). But besides these cosmetic issues nothing should really go wrong. (I wonder if we can find a nice way to detect whether the kernel is new enough for this, so that we could strip the facility automatically for older ones. Explcitily checking for kernel versions at runtime is evil though... I can't think of a good way though...) Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, Mar 11, 2011 at 8:35 PM, Lennart Poettering
lenn...@poettering.net wrote:
On Fri, 11.03.11 19:41, Andrey Borzenkov (arvidj...@mail.ru) wrote:
Well ... the problem really is that format is supposed to be single
printable character, which does not really support bit operations and
such. What about attached (completely untested) path - which adds u
marker to anything written into /dev/kmsg?
Please don't do this. Let's not invent new interfaces here. Let's just
stick to traditional syslog which is perfectly capable of handling this,
because it allows for a full 8bit number between and which is 3 bits
priority plus 5 bits facility.
Then, let's fix the kernel side of kmsg to implicitly add in LOG_USER as
facility for everything coming in from /dev/kmsg that has has facility=0
set.
Basically what Kay suggested.
Facilities might not be the most powerful idea ever invented, but they
are useful to distuingish kernel from userspace messages, as there is
LOG_KERNEL for the former and all other facilities for the latter.
Attached patch preserves full syslog facility marker and simply emits
it back. So userspace is free to feed any facility it deems
appropriate, not only LOG_USER.
Compile tested only.
read_priority shamelessly borrowed from systemd :)
From: Andrey Borzenkov arvidj...@gmail.com
Subject: [PATCH] support full syslog facility+priority in printk
Add support for parsing full syslog facility+priority marker.
This allows early boot userspace to inject log messages with
correct facility so that these can be later processed by syslog
according to real source, and not misinterpreted as originated in kernel.
---
kernel/printk.c | 106 +--
1 files changed, 79 insertions(+), 27 deletions(-)
diff --git a/kernel/printk.c b/kernel/printk.c
index 3623152..7534158 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -515,6 +515,54 @@ static void _call_console_drivers(unsigned start,
}
/*
+ * Parse full syslog prefix and extract priority. Returns length of prefix
+ * or 0 if prefix is invalid
+ */
+static int read_priority(const char *buf, int *priority) {
+ const char *p = buf;
+ int a = 0, b = 0, c = 0;
+ int r, len;
+
+ if (*p++ != '')
+ return 0;
+
+ if ((*p == 'd' || *p == 'c') p[1] == '') {
+ r = *p;
+ len = 3;
+ goto out;
+ }
+
+ if (*p = '0' *p = '9')
+ c = *p++ - '0';
+ else
+ return 0;
+
+ if (*p = '0' *p = '9') {
+ b = c;
+ c = *p++ - '0';
+ } else
+ return 0;
+
+ if (*p = '0' *p = '9') {
+ a = b;
+ b = c;
+ c = *p++ - '0';
+ } else
+ return 0;
+
+ if (*p++ != '')
+ return 0;
+
+ r = '0' + ((100*a + 10*b + c) 7);
+ len = p - buf;
+
+out:
+ if (priority)
+ *priority = r;
+ return len;
+}
+
+/*
* Call the console drivers, asking them to write out
* log_buf[start] to log_buf[end - 1].
* The console_lock must be held.
@@ -529,13 +577,12 @@ static void call_console_drivers(unsigned start, unsigned end)
cur_index = start;
start_print = start;
while (cur_index != end) {
- if (msg_level 0 ((end - cur_index) 2)
-LOG_BUF(cur_index + 0) == ''
-LOG_BUF(cur_index + 1) = '0'
-LOG_BUF(cur_index + 1) = '7'
-LOG_BUF(cur_index + 2) == '') {
- msg_level = LOG_BUF(cur_index + 1) - '0';
- cur_index += 3;
+ int plen, prio;
+
+ plen = read_priority(LOG_BUF(cur_index), prio);
+ if (plen prio != 'd' prio != 'c') {
+ msg_level = prio - '0';
+ cur_index += plen;
start_print = cur_index;
}
while (cur_index != end) {
@@ -733,6 +780,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
unsigned long flags;
int this_cpu;
char *p;
+ int plen, prio;
boot_delay_msec();
printk_delay();
@@ -777,24 +825,21 @@ asmlinkage int vprintk(const char *fmt, va_list args)
p = printk_buf;
/* Do we have a loglevel in the string? */
- if (p[0] == '') {
- unsigned char c = p[1];
- if (c p[2] == '') {
- switch (c) {
- case '0' ... '7': /* loglevel */
-current_log_level = c - '0';
- /* Fallthrough - make sure we're on a new line */
- case 'd': /* KERN_DEFAULT */
-if (!new_text_line) {
- emit_log_char('\n');
- new_text_line = 1;
-}
- /* Fallthrough - skip the loglevel */
- case 'c': /* KERN_CONT */
-p += 3;
-break;
+ if ((plen = read_priority(p, prio))) {
+ switch (prio) {
+ case '0' ... '7': /* loglevel */
+ current_log_level = prio - '0';
+ /* Fallthrough - make sure we're on a new line */
+ case 'd': /* KERN_DEFAULT */
+ if (!new_text_line) {
+emit_log_char('\n');
+new_text_line = 1;
}
+ /* Fallthrough - skip the loglevel */
+ case 'c': /* KERN_CONT */
+ break;
}
+ p += plen;
}
/*
@@ -804,10 +849,17 @@ asmlinkage int vprintk(const char *fmt, va_list args)
for ( ; *p; p++) {
if (new_text_line) {
/* Always output the token */
- emit_log_char('');
- emit_log_char(current_log_level + '0');
- emit_log_char('');
- printed_len += 3;
+ if (plen prio != 'd' prio != 'c') {
+
Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Andrey Borzenkov [mailto:arvidj...@mail.ru] Sent: Friday, March 11, 2011 8:38 AM To: Michael Biebl Cc: Mike Kazantsev; systemd-devel@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 mbi...@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 ;) Rainer ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 08:49, Mike Kazantsev (mk.frag...@gmail.com) wrote: Hmm, that is borked. We do provider proper error levels when we write things to kmsg. This must get lost later on. But we do strip the facility, so that it gets replaced by kernel, that is true. The only reason we strip the facility however is because the dmesg tool chokes on it. The kernel is completely fine with it. I think if we'd fix dmesg we should have no trouble with making the kernel log buffer a full featured syslog queue like any other. And the kernel[-]: syntax must be from your log implementation, too. What syslog implementation is that? The same rsyslog. Format is facility.priority cmd[pid]: , but in case of kmsg looks like rsyslog doesn't try to interpret process[pid]: prefix, at least, so my guess is that it doesn't try to get any syslog metadata from this messages, just passing them as-is from kernel.warning kernel[-]. Hmm, the log messages look different for us. Probably different default configuration on Fedora and your distro... Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 08:03, Michael Biebl (mbi...@gmail.com) wrote: 2011/2/26 Andrey Borzenkov arvidj...@mail.ru: On Wed, Feb 23, 2011 at 10:48 AM, Mike Kazantsev mk.frag...@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. Yeah, it would be very good if rsyslog was able to parse the [ 5921.140864] style kernel timestamps if they are set and translate them via CLOCK_MONOTONIC/uptime back to normal wallclock timestamps which would then be used as message timestamps like any other. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 08:09, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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. Nah, these are actually two different things. The SO_TIMESTAMP stuff does not matter in this context. What I'd like to see that SO_TIMESTAMP is used when messages come in via /dev/log. And for messages coming in from /proc/kmsg it would be cool to parse the kernel timestamps that (optionally) are in the message prefix in the [] part. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Friday, March 11, 2011 5:06 PM To: Rainer Gerhards Cc: Michael Biebl; Andrey Borzenkov; Mike Kazantsev; systemd- de...@lists.freedesktop.org Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Fri, 11.03.11 08:09, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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. Nah, these are actually two different things. The SO_TIMESTAMP stuff does not matter in this context. What I'd like to see that SO_TIMESTAMP is used when messages come in via /dev/log. And for messages coming in from /proc/kmsg it would be cool to parse the kernel timestamps that (optionally) are in the message prefix in the [] part. Got it -- but optionally does not sound too good. What if systemd's minimal syslog implementation would guarantee that a timestamp is written for forwarded logs? Rainer ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 08:45, Michael Biebl (mbi...@gmail.com) wrote: 2011/3/11 Rainer Gerhards rgerha...@hq.adiscon.com: So isn't that already a solution? The problem with PRINTK_TIME afaics is that it needs to be turned on explicitly whereas I'd expect SO_TIMESTAMP will be available always (if the kernel is recent enough)? PRINTK_TIME applies to /proc/kmsg data. SO_TIMESTAMP applies to /dev/log sockets. In any case you'd need to interpret that data on the rsyslog side, to compute a correct time stamp and then (optionally) strip off the [ 5913.491848] markers. Yupp, that's what I'd like to see. But there's actually something else I'd like to see, as well: Parse the x priority field read from /proc/kmsg like it is normally done for /dev/log messages. i.e. traditionally, since only the kernel wrote to dmesg all lines where prefixed with prios from the range 0..7 only. And some tools can just parse that: a prefix of plus one number from 0..7 plus . It would be cool to beef that up and parse the full 8bit priority field there too, i.e. not just the 3 bit for the priority, but also the 5 bit for the facility. Since facility=0 refers to kernel messages the kernel messages would be identified as facility=kernel, but in case user code logs something there it can pass the correct facility and the userspace syslog daemon should then not override that facility with kernel anymore. The result of this all put together would be that userspace can log via /dev/kmsg or via /dev/log and not metadata would be lost anymore. Not the prio, not the facility, and not the timestamp. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 10:37, Andrey Borzenkov (arvidj...@mail.ru) wrote: On Fri, Mar 11, 2011 at 10:03 AM, Michael Biebl mbi...@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? :) I see no need for anything systemd specific, and systemd is not actually the only usespace system that logs to to kmsg, at least dracut and udev do that too. To recognize userspace messages proper support for the facility bits in the xxx prefix of kmsg messages would probably be best. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 09:55, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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 ;) I think rules like this should look for the facility field, and we should allow facility bits in the kmsg messages, so that userspace messages can clearly mark themselves as such. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Friday, March 11, 2011 5:17 PM To: Rainer Gerhards Cc: Andrey Borzenkov; Michael Biebl; Mike Kazantsev; systemd- de...@lists.freedesktop.org Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Fri, 11.03.11 09:55, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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 ;) I think rules like this should look for the facility field, and we should allow facility bits in the kmsg messages, so that userspace messages can clearly mark themselves as such. There are too few facilities for this to work. Also, the engine can bind to different rulesets depending on the message origin. It is not trivial to re-route messages in this context. Granted, that's not a problem for a typical system, but it can be one in high-end environments. For rsyslog, it would mean I need to find some kind of an inter-module interface, where imklog shuffles some of the messages to imuxsock. Maybe it would make more sense if imklog in such cases simply forwards the messages to the system log socket (which in that scenario should be bound to rsyslog). But I don't think this is a really pressing problem -- we better see at least one instance of it in reality before trying to fix it... Rainer ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
-Original Message- From: Lennart Poettering [mailto:lenn...@poettering.net] Sent: Friday, March 11, 2011 5:22 PM To: Rainer Gerhards Cc: Michael Biebl; Andrey Borzenkov; Mike Kazantsev; systemd- de...@lists.freedesktop.org Subject: Re: [systemd-devel] systemd-logger and external syslog daemon On Fri, 11.03.11 17:08, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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. Nah, these are actually two different things. The SO_TIMESTAMP stuff does not matter in this context. What I'd like to see that SO_TIMESTAMP is used when messages come in via /dev/log. And for messages coming in from /proc/kmsg it would be cool to parse the kernel timestamps that (optionally) are in the message prefix in the [] part. Got it -- but optionally does not sound too good. What if systemd's minimal syslog implementation would guarantee that a timestamp is written for forwarded logs? Well, if the kernel adds timestamps anyway, then there's little point to add another set of timestamps from userspace, snce then we might end up with two timestamps in each message. And it is difficult to figure out whether kernel-side timestamping is on. Well, I could check a special cookie for the systemd timestamp. I am *not* concerned so much about regular kernel messages. What concerns me are messages that are originally destined to the system log socket. Also note that it may be dangerous to change the output format of syslogd. Various processes seem to die in that case (at least that's why almost all distros still have the silly old-style timestamp set as default, because a variety of tools abort if RFC3339 timestamps are being used...). All big distros enable printk timestamping by default. That means this is an opt-out and not an opt-in feature nowadays. That probably means we shouldn't try to ignore the user configuration and add in timestamps when the kernel doesn't genreate them anyway. Also, note that systemd is not the only one logging to /dev/kmsg. The kernel timestamping covers all those sources equally. As I said, I am concerned about the forwarded messages, for which I think systemd ist he only source. Rainer Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 17:22, Rainer Gerhards (rgerha...@hq.adiscon.com) wrote: 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 ;) I think rules like this should look for the facility field, and we should allow facility bits in the kmsg messages, so that userspace messages can clearly mark themselves as such. There are too few facilities for this to work. Also, the engine can bind to different rulesets depending on the message origin. It is not trivial to re-route messages in this context. Granted, that's not a problem for a typical system, but it can be one in high-end environments. Nah, the facility 0 is kernel, and that's all we need. So, if you find a message in kmsg with facility=0 then you know it is the kernel which logged into the kernel log buffer. However, if facility is != 0, then it is userspace which logged into the kernel log buffer. I think we shouldn't confuse the transport with the origin of messages. Since time began it was possible to log to /dev/kmsg from userspace. Not much code did so, but already then /proc/kmsg was a transport for both kernel and userspace messages. Traditionally userspace didn't add valid facility values to the messages it logged to /dev/kmsg when it did so. What I am suggesting is to add that, so that we can correct the current implicit assumption transport is /proc/kmsg → origin is kernel into facility is 0 → origin is kernel. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, Mar 11, 2011 at 17:47, Rainer Gerhards rgerha...@hq.adiscon.com wrote: From: Andrey Borzenkov [mailto:arvidj...@mail.ru] Well ... the problem really is that format is supposed to be single printable character, which does not really support bit operations and such. What about attached (completely untested) path - which adds u marker to anything written into /dev/kmsg? If it is just a single character, I need to obtain the real facility/severity somewhere. Could that be written to some fixed place, e.g. immediately after u? That way, I'd know exactly what is going on and can remove the extra formatting on the syslogd side. Let's just check if we can fix the kernel to support the full 8 bit, and fill-in the LOG_USER when /dev/kmsg is used, if no other facility is passed-in. That way the both messages are easily distinguished without any breakage of the format. Kay ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11.03.11 19:41, Andrey Borzenkov (arvidj...@mail.ru) wrote: Well ... the problem really is that format is supposed to be single printable character, which does not really support bit operations and such. What about attached (completely untested) path - which adds u marker to anything written into /dev/kmsg? Please don't do this. Let's not invent new interfaces here. Let's just stick to traditional syslog which is perfectly capable of handling this, because it allows for a full 8bit number between and which is 3 bits priority plus 5 bits facility. Then, let's fix the kernel side of kmsg to implicitly add in LOG_USER as facility for everything coming in from /dev/kmsg that has has facility=0 set. Basically what Kay suggested. Facilities might not be the most powerful idea ever invented, but they are useful to distuingish kernel from userspace messages, as there is LOG_KERNEL for the former and all other facilities for the latter. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, 11 Mar 2011 17:01:46 +0100 Lennart Poettering lenn...@poettering.net wrote: On Fri, 11.03.11 08:49, Mike Kazantsev (mk.frag...@gmail.com) wrote: Hmm, that is borked. We do provider proper error levels when we write things to kmsg. This must get lost later on. But we do strip the facility, so that it gets replaced by kernel, that is true. The only reason we strip the facility however is because the dmesg tool chokes on it. The kernel is completely fine with it. I think if we'd fix dmesg we should have no trouble with making the kernel log buffer a full featured syslog queue like any other. And the kernel[-]: syntax must be from your log implementation, too. What syslog implementation is that? The same rsyslog. Format is facility.priority cmd[pid]: , but in case of kmsg looks like rsyslog doesn't try to interpret process[pid]: prefix, at least, so my guess is that it doesn't try to get any syslog metadata from this messages, just passing them as-is from kernel.warning kernel[-]. Hmm, the log messages look different for us. Probably different default configuration on Fedora and your distro... Probably my changes entirely, I have the aforementioned format defined in the configuration. My apologies, should've mentioned that to avoid confusion. Lennart -- Mike Kazantsev // fraggod.net signature.asc Description: PGP signature ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Wed, Feb 23, 2011 at 10:48 AM, Mike Kazantsev mk.frag...@gmail.com wrote: How the kmsg-syslogd-rsyslog migration (for systemd output) is supposed to work? As I just went through all of it ... you absolutely need rsyslog that supports passing sockets from systemd. Otherwise it is race condition - rsyslog will remove and recreate /dev/log on activation so you end up with a) some processes still connected to removed /dev/log and passing messages to /dev/kmsg this way b) losing some messages for as long as /dev/log does not exist Unless you have rsyslog that really supports it - do not stop systemd-kmsg-syslogd! It will result in process blocking on accessing it creating all sorts of interesting deadlocks. I managed to completely lock out any user this way ... :) ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Thu, 10.03.11 23:08, Mike Kazantsev (mk.frag...@gmail.com) wrote: On Thu, 10 Mar 2011 19:14:29 +0300 Andrey Borzenkov arvidj...@mail.ru wrote: On Wed, Feb 23, 2011 at 10:48 AM, Mike Kazantsev mk.frag...@gmail.com wrote: How the kmsg-syslogd-rsyslog migration (for systemd output) is supposed to work? As I just went through all of it ... you absolutely need rsyslog that supports passing sockets from systemd. Otherwise it is race condition - rsyslog will remove and recreate /dev/log on activation so you end up with The behaviour I've described is what actually happened to me with git version of rsyslog from the master branch (that's what I meant by latest scm version) - it's 6-git version. If that doesn't support passsing sockets from systemd, I don't think any other version does ;) rsyslog 5.7.7 contains all the necessary glue code. Lennart -- Lennart Poettering - Red Hat, Inc. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Thu, 10 Mar 2011 22:01:39 +0100 Lennart Poettering lenn...@poettering.net wrote: On Wed, 23.02.11 12:48, Mike Kazantsev (mk.frag...@gmail.com) wrote: Good day, 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 Thus, regardless of what systemd.exec(5) states, SyslogFacility= and SyslogLevel= is irrelevant - to a syslog daemon they will be passed as kernel.warning. Hmm, that is borked. We do provider proper error levels when we write things to kmsg. This must get lost later on. But we do strip the facility, so that it gets replaced by kernel, that is true. The only reason we strip the facility however is because the dmesg tool chokes on it. The kernel is completely fine with it. I think if we'd fix dmesg we should have no trouble with making the kernel log buffer a full featured syslog queue like any other. And the kernel[-]: syntax must be from your log implementation, too. What syslog implementation is that? The same rsyslog. Format is facility.priority cmd[pid]: , but in case of kmsg looks like rsyslog doesn't try to interpret process[pid]: prefix, at least, so my guess is that it doesn't try to get any syslog metadata from this messages, just passing them as-is from kernel.warning kernel[-]. Naturally, the reason is systemd-kmsg-syslogd daemon, which spawns early on boot from syslog.socket and creates /dev/log, which is accessed by systemd-logger long before external syslog daemon starts. Syslog daemon (rsyslog in my case) just grabs these from kmsg. After that, substituting /dev/log for another socket (like rsyslog.socket seem to do) or just removing it doesn't seem to matter - systemd-logger will keep feeding messages to dmesg via kmsg-syslogd. Well, not anymore if you use a socket activatable syslog daemon. In that case the original socket is just handed over and rsyslog continues dispatching syslog messages where the bridge left of. I read Kay Sievers's earlier post in this list on the subject, which states Syslog services have been patched to be able to seemlessly take over an already opened /dev/log. rsyslog is upstream already Yet I've tried latest scm version of rsyslog and it doesn't seem to take over an already opened /dev/log if started via upstream-shipped rsyslog.socket unit (which just uses ListenDatagram=/dev/log) line. it does now, since a couple of days, see my headsup message i posted a few days ago. Thanks, will test it asap. Lennart -- Mike Kazantsev // fraggod.net signature.asc Description: PGP signature ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
2011/3/11 Rainer Gerhards rgerha...@hq.adiscon.com: -Original Message- From: Michael Biebl [mailto:mbi...@gmail.com] Sent: Friday, March 11, 2011 8:04 AM 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. afaik it is not so much a kernel version issue, but a kernel config that needs to be turned on: http://cateee.net/lkddb/web-lkddb/PRINTK_TIME.html says it's available ins 2.6.12 Debian kernels have CONFIG_PRINTK_TIME=y Ubuntu 10.10 and F14 as it seems, too. Cheers, Michael -- Why is it that all of the instruments seeking intelligent life in the universe are pointed away from Earth? ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Fri, Mar 11, 2011 at 10:03 AM, Michael Biebl mbi...@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? :) ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] systemd-logger and external syslog daemon
On Wed, Feb 23, 2011 at 10:48 AM, Mike Kazantsev mk.frag...@gmail.com wrote: Good day, 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 ] Syslog output from other programs is OK, so it looks like internal systemd issue. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
