* [RFC][PATCH] printk: add console_msg_format command line option
@ 2017-12-01 10:44 Sergey Senozhatsky
2017-12-07 13:48 ` Petr Mladek
0 siblings, 1 reply; 5+ messages in thread
From: Sergey Senozhatsky @ 2017-12-01 10:44 UTC (permalink / raw)
To: Steven Rostedt, Petr Mladek
Cc: Linus Torvalds, Fengguang Wu, Kevin Hilman, Mark Brown,
Greg Kroah-Hartman, Andrew Morton, LKML, Sergey Senozhatsky,
Sergey Senozhatsky
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 <sergey.senozhatsky@gmail.com>
Reviewed-by: Fengguang Wu <fengguang.wu@intel.com>
Reviewed-by: Kevin Hilman <khilman@baylibre.com>
Tested-by: Kevin Hilman <khilman@baylibre.com>
---
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, sizeof(text) - len);
+ len += msg_print_text(msg,
+ console_msg_format & MSG_FORMAT_SYSLOG,
+ text + len,
+ sizeof(text) - len);
if (nr_ext_console_drivers) {
ext_len = msg_print_ext_header(ext_text,
sizeof(ext_text),
--
2.15.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [RFC][PATCH] printk: add console_msg_format command line option
2017-12-01 10:44 [RFC][PATCH] printk: add console_msg_format command line option Sergey Senozhatsky
@ 2017-12-07 13:48 ` Petr Mladek
2017-12-07 14:01 ` Sergey Senozhatsky
0 siblings, 1 reply; 5+ messages in thread
From: Petr Mladek @ 2017-12-07 13:48 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: Steven Rostedt, Linus Torvalds, Fengguang Wu, Kevin Hilman,
Mark Brown, Greg Kroah-Hartman, Andrew Morton, LKML,
Sergey Senozhatsky
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:
* "<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [RFC][PATCH] printk: add console_msg_format command line option
2017-12-07 13:48 ` Petr Mladek
@ 2017-12-07 14:01 ` Sergey Senozhatsky
2017-12-07 15:45 ` Petr Mladek
0 siblings, 1 reply; 5+ messages in thread
From: Sergey Senozhatsky @ 2017-12-07 14:01 UTC (permalink / raw)
To: Petr Mladek
Cc: Sergey Senozhatsky, Steven Rostedt, Linus Torvalds, Fengguang Wu,
Kevin Hilman, Mark Brown, Greg Kroah-Hartman, Andrew Morton,
LKML, Sergey Senozhatsky
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:
> * "<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [RFC][PATCH] printk: add console_msg_format command line option
2017-12-07 14:01 ` Sergey Senozhatsky
@ 2017-12-07 15:45 ` Petr Mladek
2017-12-07 16:03 ` Sergey Senozhatsky
0 siblings, 1 reply; 5+ messages in thread
From: Petr Mladek @ 2017-12-07 15:45 UTC (permalink / raw)
To: Sergey Senozhatsky
Cc: Steven Rostedt, Linus Torvalds, Fengguang Wu, Kevin Hilman,
Mark Brown, Greg Kroah-Hartman, Andrew Morton, LKML,
Sergey Senozhatsky
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:
> > * "<level>,<sequnum>,<timestamp>,<contflag>[,additional_values, ... ];<message text>\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.000000] 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.000000] 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.000000] 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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [RFC][PATCH] printk: add console_msg_format command line option
2017-12-07 15:45 ` Petr Mladek
@ 2017-12-07 16:03 ` Sergey Senozhatsky
0 siblings, 0 replies; 5+ messages in thread
From: Sergey Senozhatsky @ 2017-12-07 16:03 UTC (permalink / raw)
To: Petr Mladek
Cc: Sergey Senozhatsky, Steven Rostedt, Linus Torvalds, Fengguang Wu,
Kevin Hilman, Mark Brown, Greg Kroah-Hartman, Andrew Morton,
LKML, Sergey Senozhatsky
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.000000] 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.000000] 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.000000] 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
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2017-12-07 16:04 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-12-01 10:44 [RFC][PATCH] printk: add console_msg_format command line option Sergey Senozhatsky
2017-12-07 13:48 ` Petr Mladek
2017-12-07 14:01 ` Sergey Senozhatsky
2017-12-07 15:45 ` Petr Mladek
2017-12-07 16:03 ` Sergey Senozhatsky
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).