[RFC][PATCH] printk: add console_msg_format command line option
0day and kernelCI automatically parse kernel log - basically some sort of grepping using the pre-defined text patterns - in order to detect and report regressions/errors. There are several sources they get the kernel logs from: a) dmesg or /proc/ksmg This is the preferred way. Because `dmesg --raw' and /proc/kmsg output contains facility and log level, which greatly simplifies grepping for EMERG/ALERT/CRIT/ERR messages. b) serial consoles This option is harder to maintain, because serial console messages don't contain facility and log level. This patch introduces a `console_msg_format=' command line option, to switch between different message formatting on serial consoles. For the time being we have just one option - syslog. This option makes serial console messages to appear in syslog format, matching the `dmesg --raw' and `cat /proc/kmsg' output formats: - facility and log level - time stamp (depends on printk_time/PRINTK_TIME) - message <%u>[time stamp] text\n Per Kevin Hilman: : Right now we can get this info from a "dmesg --raw" after bootup, : but it would be really nice in certain automation frameworks to : have a kernel command-line option to enable printing of loglevels : in default boot log. : : This is especially useful when ingesting kernel logs into advanced : search/analytics frameworks (I'm playing with and ELK stack: Elastic : Search, Logstash, Kibana). : : The other important reason for having this on the command line is that : for testing linux-next (and other bleeding edge developer branches), : it's common that we never make it to userspace, so can't even run : "dmesg --raw" (or equivalent.) So we really want this on the primary : boot (serial) console. Per Fengguang Wu, 0day scripts should quickly benefit from that feature, because they will be able to switch to a more reliable parsing, based on messages' facility and log levels [1]: `#{grep} -a -E -e '^<[0123]>' -e '^kern :(err |crit |alert |emerg )' instead of doing text pattern matching `#{grep} -a -F -f /lkp/printk-error-messages #{kmsg_file} | grep -a -v -E -f #{LKP_SRC}/etc/oops-pattern | grep -a -v -F -f #{LKP_SRC}/etc/kmsg-blacklist` [1] https://github.com/fengguang/lkp-tests/blob/master/lib/dmesg.rb Signed-off-by: Sergey Senozhatsky Reviewed-by: Fengguang Wu Reviewed-by: Kevin Hilman Tested-by: Kevin Hilman --- Documentation/admin-guide/kernel-parameters.txt | 10 ++ kernel/printk/printk.c | 21 - 2 files changed, 30 insertions(+), 1 deletion(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 28467638488d..2dd91c5073f9 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -643,6 +643,16 @@ console=brl,ttyS0 For now, only VisioBraille is supported. + console_msg_format= + [KNL] Control message format + By default we print messages in "[time stamp] text\n" + format (time stamp may not be printed, depending on + CONFIG_PRINTK_TIME or `printk_time' param). + syslog + Switch to syslog format (similar to "dmesg --raw" or + reading from /proc/kmsg): "<%u>[time stamp] text\n" + IOW, each message has a facility and loglevel prefix. + consoleblank= [KNL] The console blank (screen saver) timeout in seconds. A value of 0 disables the blank timer. Defaults to 0. diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 5d81206a572d..012a6b4991a6 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -277,6 +277,13 @@ EXPORT_SYMBOL(console_set_on_cmdline); /* Flag: console code may call schedule() */ static int console_may_schedule; +enum con_msg_format { + MSG_FORMAT_DEFAULT = 0, + MSG_FORMAT_SYSLOG = (1 << 0), +}; + +static int console_msg_format = MSG_FORMAT_DEFAULT; + /* * The printk log buffer consists of a chain of concatenated variable * length records. Every record starts with a record header, containing @@ -1913,6 +1920,15 @@ static int __add_preferred_console(char *name, int idx, char *options, c->index = idx; return 0; } + +static int __init console_msg_format_setup(char *str) +{ + if (!strncmp(str, "syslog", 6)) + console_msg_format = MSG_FORMAT_SYSLOG; + return 1; +} +__setup("console_msg_format=", console_msg_format_setup); + /* * Set up a console. Called via do_early_param() in init/main.c * for each "console=" parameter in the boot command line. @@ -2215,7 +2231,10 @@ void console_unlock(void) goto skip; } - len += msg_print_text(msg, false, text + len, siz
Re: [RFC][PATCH] printk: add console_msg_format command line option
On Fri 2017-12-01 19:44:04, Sergey Senozhatsky wrote: > 0day and kernelCI automatically parse kernel log - basically some sort > of grepping using the pre-defined text patterns - in order to detect > and report regressions/errors. There are several sources they get the > kernel logs from: > > a) dmesg or /proc/ksmg > >This is the preferred way. Because `dmesg --raw' and /proc/kmsg >output contains facility and log level, which greatly simplifies >grepping for EMERG/ALERT/CRIT/ERR messages. > > b) serial consoles > >This option is harder to maintain, because serial console messages >don't contain facility and log level. > > This patch introduces a `console_msg_format=' command line option, > to switch between different message formatting on serial consoles. > For the time being we have just one option - syslog. This option > makes serial console messages to appear in syslog format, matching > the `dmesg --raw' and `cat /proc/kmsg' output formats: I have realized that 'cat /proc/kmsg' did not work. It can be done using: dd if=/dev/kmsg iflag=nonblock Also the format is more comlicated here, see printk.c: * /dev/kmsg exports the structured data in the following line format: * ",,,[,additional_values, ... ];\n" > diff --git a/Documentation/admin-guide/kernel-parameters.txt > b/Documentation/admin-guide/kernel-parameters.txt > index 28467638488d..2dd91c5073f9 100644 > --- a/Documentation/admin-guide/kernel-parameters.txt > +++ b/Documentation/admin-guide/kernel-parameters.txt > @@ -643,6 +643,16 @@ > console=brl,ttyS0 > For now, only VisioBraille is supported. > > + console_msg_format= > + [KNL] Control message format > + By default we print messages in "[time stamp] text\n" > + format (time stamp may not be printed, depending on > + CONFIG_PRINTK_TIME or `printk_time' param). > + syslog > + Switch to syslog format (similar to "dmesg --raw" or > + reading from /proc/kmsg): "<%u>[time stamp] text\n" To be precise, it exactly the same as "dmesg -S --raw". Also it is the format used by SYSLOG_ACTION_READ* actions of the syslog syscall. Note that it is affected by CONFIG_PRINTK_TIME or "printk_time" command-line option the same way as the default format. > + IOW, each message has a facility and loglevel prefix. > + > consoleblank= [KNL] The console blank (screen saver) timeout in > seconds. A value of 0 disables the blank timer. > Defaults to 0. > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 5d81206a572d..012a6b4991a6 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -277,6 +277,13 @@ EXPORT_SYMBOL(console_set_on_cmdline); > /* Flag: console code may call schedule() */ > static int console_may_schedule; > > +enum con_msg_format { > + MSG_FORMAT_DEFAULT = 0, > + MSG_FORMAT_SYSLOG = (1 << 0), > +}; > + > +static int console_msg_format = MSG_FORMAT_DEFAULT; > + > /* > * The printk log buffer consists of a chain of concatenated variable > * length records. Every record starts with a record header, containing > @@ -1913,6 +1920,15 @@ static int __add_preferred_console(char *name, int > idx, char *options, > c->index = idx; > return 0; > } > + > +static int __init console_msg_format_setup(char *str) > +{ > + if (!strncmp(str, "syslog", 6)) > + console_msg_format = MSG_FORMAT_SYSLOG; It might make sense to accept also the "default" format. > + return 1; > +} > +__setup("console_msg_format=", console_msg_format_setup); I would use early_param() so that it takes effect as soon as possible. Otherwise, it looks fine. The patch is nicely minimalistic. Best Regards, Petr
Re: [RFC][PATCH] printk: add console_msg_format command line option
Hi, On (12/07/17 14:48), Petr Mladek wrote: [..] > > This patch introduces a `console_msg_format=' command line option, > > to switch between different message formatting on serial consoles. > > For the time being we have just one option - syslog. This option > > makes serial console messages to appear in syslog format, matching > > the `dmesg --raw' and `cat /proc/kmsg' output formats: > > I have realized that 'cat /proc/kmsg' did not work. It can be done using: hm, it does work on my system. what do you mean by 'did not work'? > Also the format is more comlicated here, see printk.c: > > * /dev/kmsg exports the structured data in the following line format: > * ",,,[,additional_values, ... > ];\n" that's /dev/kmsg. /dev/kmsg != /proc/kmsg. I never mentioned /dev/kmsg in my commit. /dev/kmsg prints the extended stuff, /proc/kmsg does not. > > diff --git a/Documentation/admin-guide/kernel-parameters.txt > > b/Documentation/admin-guide/kernel-parameters.txt > > index 28467638488d..2dd91c5073f9 100644 > > --- a/Documentation/admin-guide/kernel-parameters.txt > > +++ b/Documentation/admin-guide/kernel-parameters.txt > > @@ -643,6 +643,16 @@ > > console=brl,ttyS0 > > For now, only VisioBraille is supported. > > > > + console_msg_format= > > + [KNL] Control message format > > + By default we print messages in "[time stamp] text\n" > > + format (time stamp may not be printed, depending on > > + CONFIG_PRINTK_TIME or `printk_time' param). > > + syslog > > + Switch to syslog format (similar to "dmesg --raw" or > > + reading from /proc/kmsg): "<%u>[time stamp] text\n" > > To be precise, it exactly the same as "dmesg -S --raw". Also it is the > format used by SYSLOG_ACTION_READ* actions of the syslog syscall. hmm... `dmesg -S --raw' doesn't show anything on my system. `dmesg --raw' matches the console_msg_format=syslog. > > +static int __init console_msg_format_setup(char *str) > > +{ > > + if (!strncmp(str, "syslog", 6)) > > + console_msg_format = MSG_FORMAT_SYSLOG; > > It might make sense to accept also the "default" format. > > > + return 1; > > +} > > +__setup("console_msg_format=", console_msg_format_setup); > > I would use early_param() so that it takes effect as soon as possible. ok. can take a look. -ss
Re: [RFC][PATCH] printk: add console_msg_format command line option
On Thu 2017-12-07 23:01:04, Sergey Senozhatsky wrote: > Hi, > > On (12/07/17 14:48), Petr Mladek wrote: > [..] > > > This patch introduces a `console_msg_format=' command line option, > > > to switch between different message formatting on serial consoles. > > > For the time being we have just one option - syslog. This option > > > makes serial console messages to appear in syslog format, matching > > > the `dmesg --raw' and `cat /proc/kmsg' output formats: > > > > I have realized that 'cat /proc/kmsg' did not work. It can be done using: > > hm, it does work on my system. what do you mean by 'did not work'? > > > > Also the format is more comlicated here, see printk.c: > > > > * /dev/kmsg exports the structured data in the following line format: > > * ",,,[,additional_values, ... > > ];\n" > > that's /dev/kmsg. /dev/kmsg != /proc/kmsg. I never mentioned /dev/kmsg > in my commit. /dev/kmsg prints the extended stuff, /proc/kmsg does not. Ah, I have messed /dev/kmsg and /proc/kmsg. > > > > diff --git a/Documentation/admin-guide/kernel-parameters.txt > > > b/Documentation/admin-guide/kernel-parameters.txt > > > index 28467638488d..2dd91c5073f9 100644 > > > --- a/Documentation/admin-guide/kernel-parameters.txt > > > +++ b/Documentation/admin-guide/kernel-parameters.txt > > > @@ -643,6 +643,16 @@ > > > console=brl,ttyS0 > > > For now, only VisioBraille is supported. > > > > > > + console_msg_format= > > > + [KNL] Control message format > > > + By default we print messages in "[time stamp] text\n" > > > + format (time stamp may not be printed, depending on > > > + CONFIG_PRINTK_TIME or `printk_time' param). > > > + syslog > > > + Switch to syslog format (similar to "dmesg --raw" or > > > + reading from /proc/kmsg): "<%u>[time stamp] text\n" > > > > To be precise, it exactly the same as "dmesg -S --raw". Also it is the > > format used by SYSLOG_ACTION_READ* actions of the syslog syscall. > > hmm... `dmesg -S --raw' doesn't show anything on my system. `dmesg --raw' > matches the console_msg_format=syslog. Huh, I am confused now. I thought that I saw the extended, /dev/kmsg - like, output with "dmesg --raw" but I do not see it now. Anyway, I can see a difference related to /sys/module/printk/parameters/time. The command "dmesg --raw" always shows the timestamp help because it reads the messages via /dev/kmsg. But "dmesg -S --raw" shows the timestamp only when the "time" parameter is enabled: $> echo 0 >/sys/module/printk/parameters/time $> dmesg -S --raw | head -n 3 <5>Linux version 4.15.0-rc2-5-default+ (pmladek@pathway) (gcc version 4.8.5 (SUSE Linux)) #4180 SMP Thu Dec 7 16:06:42 CET 2017 <6>Command line: BOOT_IMAGE=/boot/vmlinuz-4.15.0-rc2-5-default+ root=UUID=9ba368bb-c323-4131-ad94-c29cf3add76f resume=/dev/sda2 earlyprintk=ttyS0,115200 console=tty0 console=ttyS0,115200 console_msg_format=syslog ignore_loglevel nosplash showopts crashkernel=256M,high crashkernel=128M,low <6>x86/fpu: x87 FPU will use FXSAVE $> echo 1 >/sys/module/printk/parameters/time $> dmesg -S --raw | head -n 3 <5>[0.00] Linux version 4.15.0-rc2-5-default+ (pmladek@pathway) (gcc version 4.8.5 (SUSE Linux)) #4180 SMP Thu Dec 7 16:06:42 CET 2017 <6>[0.00] Command line: BOOT_IMAGE=/boot/vmlinuz-4.15.0-rc2-5-default+ root=UUID=9ba368bb-c323-4131-ad94-c29cf3add76f resume=/dev/sda2 earlyprintk=ttyS0,115200 console=tty0 console=ttyS0,115200 console_msg_format=syslog ignore_loglevel nosplash showopts crashkernel=256M,high crashkernel=128M,low <6>[0.00] x86/fpu: x87 FPU will use FXSAVE Note that the -S option has been added in util-linux, v2.22 by the commit https://git.kernel.org/pub/scm/utils/util-linux/util-linux.git/commit/?id=ed61acc2542ebb0d9b8f5600c38fbe0d77933345 I guess that dmesg fallbacks to the classic syslog mode when /dev/kmsg is not available. To be honest, I am somehow confused by the terminology. We should make it clear that the "syslog" console format is the same as the format used by the syslog syscall. dmesg --raw might show something different when it gets the data from /dev/kmsg as shown above. Best Regards, Petr
Re: [RFC][PATCH] printk: add console_msg_format command line option
On (12/07/17 16:45), Petr Mladek wrote: [.,] > > hmm... `dmesg -S --raw' doesn't show anything on my system. `dmesg --raw' > > matches the console_msg_format=syslog. > > Huh, I am confused now. I thought that I saw the extended, /dev/kmsg - like, > output with "dmesg --raw" but I do not see it now. > > Anyway, I can see a difference related to > /sys/module/printk/parameters/time. The command "dmesg --raw" always > shows the timestamp help because it reads the messages via /dev/kmsg. > But "dmesg -S --raw" shows the timestamp only when the "time" > parameter is enabled: aha, I see your point. -S forces dmesg to use syslog() syscall. so it doesn't access the kmsg. otherwise it attempts to read from kmsg first. you are right. > $> echo 0 >/sys/module/printk/parameters/time > $> dmesg -S --raw | head -n 3 > <5>Linux version 4.15.0-rc2-5-default+ (pmladek@pathway) (gcc version 4.8.5 > (SUSE Linux)) #4180 SMP Thu Dec 7 16:06:42 CET 2017 > <6>Command line: BOOT_IMAGE=/boot/vmlinuz-4.15.0-rc2-5-default+ > root=UUID=9ba368bb-c323-4131-ad94-c29cf3add76f resume=/dev/sda2 > earlyprintk=ttyS0,115200 console=tty0 console=ttyS0,115200 > console_msg_format=syslog ignore_loglevel nosplash showopts > crashkernel=256M,high crashkernel=128M,low > <6>x86/fpu: x87 FPU will use FXSAVE > $> echo 1 >/sys/module/printk/parameters/time > $> dmesg -S --raw | head -n 3 > <5>[0.00] Linux version 4.15.0-rc2-5-default+ (pmladek@pathway) (gcc > version 4.8.5 (SUSE Linux)) #4180 SMP Thu Dec 7 16:06:42 CET 2017 > <6>[0.00] Command line: > BOOT_IMAGE=/boot/vmlinuz-4.15.0-rc2-5-default+ > root=UUID=9ba368bb-c323-4131-ad94-c29cf3add76f resume=/dev/sda2 > earlyprintk=ttyS0,115200 console=tty0 console=ttyS0,115200 > console_msg_format=syslog ignore_loglevel nosplash showopts > crashkernel=256M,high crashkernel=128M,low > <6>[0.00] x86/fpu: x87 FPU will use FXSAVE I see. > To be honest, I am somehow confused by the terminology. > We should make it clear that the "syslog" console format > is the same as the format used by the syslog syscall. yeah. that was exactly my point. syslog format means that : we do what reading from /proc/kmsg does -- do_syslog(). which "is" : the same for some dmesg modes. I thought that `dmesg --raw' always uses do_syslog(), apparently this is not the case, and that "is" was not correct. -ss