Message-Id: <20171201104404.1885-1-sergey.senozhatsky@gmail.com>
Date:   Fri,  1 Dec 2017 19:44:04 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky@...il.com>
To:     Steven Rostedt <rostedt@...dmis.org>,
        Petr Mladek <pmladek@...e.com>
Cc:     Linus Torvalds <torvalds@...ux-foundation.org>,
        Fengguang Wu <fengguang.wu@...el.com>,
        Kevin Hilman <khilman@...libre.com>,
        Mark Brown <broonie@...nel.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        LKML <linux-kernel@...r.kernel.org>,
        Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>
Subject: [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 <sergey.senozhatsky@...il.com>
Reviewed-by: Fengguang Wu <fengguang.wu@...el.com>
Reviewed-by: Kevin Hilman <khilman@...libre.com>
Tested-by: Kevin Hilman <khilman@...libre.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

Powered by blists - more mailing lists