output: was: Re: [PATCH v4] printk: Userspace format enumeration support

[Petr Mladek <pmladek@suse.com>]

On Fri 2021-02-12 15:30:16, Chris Down wrote:
> We have a number of systems industry-wide that have a subset of their
> functionality that works as follows:
> 
> 1. Receive a message from local kmsg, serial console, or netconsole;
> 2. Apply a set of rules to classify the message;
> 3. Do something based on this classification (like scheduling a
>    remediation for the machine), rinse, and repeat.
> 
> As a couple of examples of places we have this implemented just inside
> Facebook, although this isn't a Facebook-specific problem, we have this
> inside our netconsole processing (for alarm classification), and as part
> of our machine health checking. We use these messages to determine
> fairly important metrics around production health, and it's important
> that we get them right.
> 
> This patch provides a solution to the issue of silently changed or
> deleted printks: we record pointers to all printk format strings known
> at compile time into a new .printk_fmts section, both in vmlinux and
> modules. At runtime, this can then be iterated by looking at
> <debugfs>/printk/formats/<module>, which emits the same format as
> `printk` itself, which we already export elsewhere (for example, in
> netconsole).
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 5a95c688621f..adf545ba9eb9 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> +static int debugfs_pf_show(struct seq_file *s, void *v)
> +{
> +	struct module *mod = s->file->f_inode->i_private;
> +	struct printk_fmt_sec *ps = NULL;
> +	const char **fptr = NULL;
> +	int ret = 0;
> +
> +	mutex_lock(&printk_fmts_mutex);
> +
> +	/*
> +	 * The entry might have been invalidated in the hlist between _open and
> +	 * _show, so we need to eyeball the entries under printk_fmts_mutex
> +	 * again.
> +	 */
> +	ps = find_printk_fmt_sec(mod);
> +	if (unlikely(!ps)) {
> +		ret = -ENOENT;
> +		goto out_unlock;
> +	}
> +
> +	for (fptr = ps->start; fptr < ps->end; fptr++) {
> +		/* For callsites without KERN_SOH + level preamble. */
> +		if (unlikely(*fptr[0] != KERN_SOH_ASCII))
> +			seq_printf(s, "%c%d", KERN_SOH_ASCII,
> +				   MESSAGE_LOGLEVEL_DEFAULT);
> +		seq_printf(s, "%s%c", *fptr, '\0');
> +	}

This produces something like:

3Warning: unable to open an initial console.
3Failed to execute %s (error %d)
6Kernel memory protection disabled.
3Starting init: %s exists but couldn't execute it (error %d)
6Run %s as init process
7initcall %pS returned %d after %lld usecs
7calling  %pS @ %i
2initrd overwritten (0x%08lx < 0x%08lx) - disabling it.

The loglevel is not well separated. It is neither human readable
nor safe for a machine processing . It works only for single digit.

Also it includes the KERN_SOH and other non-printable blobs.
It looks in less like:

^A3Warning: unable to open an initial console.
^@^A3Failed to execute %s (error %d)
^@^A6Kernel memory protection disabled.
^@^A3Starting init: %s exists but couldn't execute it (error %d)
^@^A6Run %s as init process
^@^A7initcall %pS returned %d after %lld usecs
^@^A7calling  %pS @ %i
^@^A2initrd overwritten (0x%08lx < 0x%08lx) - disabling it.
^@^A5Kernel command line: %s
^@^A5%s^@^A6mem auto-init: clearing system memory may take some time...

I would like to use something already existing. We add only loglevel,
so the syslog format would be the best

<3> Warning: unable to open an initial console.
<3> Failed to execute %s (error %d)
<6> Kernel memory protection disabled.
<3> Starting init: %s exists but couldn't execute it (error %d)
<6> Run %s as init process
<7> initcall %pS returned %d after %lld usecs
<7> calling  %pS @ %i
<2> initrd overwritten (0x%08lx < 0x%08lx) - disabling it.

Regarding the non-printable characters, I would either use the same
escape sequences as in /sys/kernel/debug/dynamic_debug/control

But even better might be to preserve to origianal text
as much as possible. It have to the following text
with the patch below:

<3> Warning: unable to open an initial console.\n
<3> Failed to execute %s (error %d)\n
<6> Kernel memory protection disabled.\n
<3> Starting init: %s exists but couldn't execute it (error %d)\n
<6> Run %s as init process\n
<7> initcall %pS returned %d after %lld usecs\n
<7> calling  %pS @ %i\n
<2> initrd overwritten (0x%08lx < 0x%08lx) - disabling it.\n
<5> Kernel command line: %s\n


Well, it still might be non-trivial to find the string in the code
and see what exactly has changed. It might be pretty useful
to mention even the source_file:line, for example:

<3> init/main.c:1489: Warning: unable to open an initial console.\n
<3> init/main.c:1446: Failed to execute %s (error %d)\n
<6> init/main.c:1398: Kernel memory protection disabled.\n
<3> init/main.c:1366: Starting init: %s exists but couldn't execute it (error %d)\n

The way how to store the filename and line number might be found
in the dynamic_debug code.

> +
> +out_unlock:
> +	mutex_unlock(&printk_fmts_mutex);
> +	return ret;
> +}

I have achieved the last but one output with the following patch
on top of the original one:

From d21d1c6d45fc66beb90de8d3309f925ecb501f1a Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Fri, 12 Feb 2021 18:43:54 +0100
Subject: [PATCH] better output

---
 fs/seq_file.c            | 21 +++++++++++++++++++++
 include/linux/seq_file.h |  1 +
 kernel/printk/printk.c   | 20 ++++++++++++++------
 3 files changed, 36 insertions(+), 6 deletions(-)

diff --git a/fs/seq_file.c b/fs/seq_file.c
index 03a369ccd28c..364587eff9d2 100644
--- a/fs/seq_file.c
+++ b/fs/seq_file.c
@@ -376,6 +376,27 @@ void seq_escape(struct seq_file *m, const char *s, const char *esc)
 }
 EXPORT_SYMBOL(seq_escape);
 
+/**
+ *	seq_escape+printf_format - print string into buffer, escaping
+ *		characters that are escaped in printf format,
+ *	@m:	target buffer
+ *	@s:	string
+ *
+ *	Puts string into buffer and escape characters that are
+ *	escaped in printf format.
+ *	Use seq_has_overflowed() to check for errors.
+ */
+void seq_escape_printf_format(struct seq_file *m, const char *s)
+{
+	char *buf;
+	size_t size = seq_get_buf(m, &buf);
+	int ret;
+
+	ret = string_escape_str(s, buf, size, ESCAPE_SPACE | ESCAPE_SPECIAL, NULL);
+	seq_commit(m, ret < size ? ret : -1);
+}
+EXPORT_SYMBOL(seq_escape_printf_format);
+
 void seq_escape_mem_ascii(struct seq_file *m, const char *src, size_t isz)
 {
 	char *buf;
diff --git a/include/linux/seq_file.h b/include/linux/seq_file.h
index b83b3ae3c877..cfc504a30429 100644
--- a/include/linux/seq_file.h
+++ b/include/linux/seq_file.h
@@ -127,6 +127,7 @@ void seq_put_hex_ll(struct seq_file *m, const char *delimiter,
 		    unsigned long long v, unsigned int width);
 
 void seq_escape(struct seq_file *m, const char *s, const char *esc);
+void seq_escape_printf_format(struct seq_file *m, const char *s);
 void seq_escape_mem_ascii(struct seq_file *m, const char *src, size_t isz);
 
 void seq_hex_dump(struct seq_file *m, const char *prefix_str, int prefix_type,
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index adf545ba9eb9..77a43b483b7b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -783,6 +783,8 @@ static const char *ps_get_module_name(const struct printk_fmt_sec *ps)
 }
 #endif /* CONFIG_MODULES */
 
+static u16 parse_prefix(const char *text, int *level, enum log_flags *lflags);
+
 static int debugfs_pf_show(struct seq_file *s, void *v)
 {
 	struct module *mod = s->file->f_inode->i_private;
@@ -804,11 +806,17 @@ static int debugfs_pf_show(struct seq_file *s, void *v)
 	}
 
 	for (fptr = ps->start; fptr < ps->end; fptr++) {
-		/* For callsites without KERN_SOH + level preamble. */
-		if (unlikely(*fptr[0] != KERN_SOH_ASCII))
-			seq_printf(s, "%c%d", KERN_SOH_ASCII,
-				   MESSAGE_LOGLEVEL_DEFAULT);
-		seq_printf(s, "%s%c", *fptr, '\0');
+		int level;
+		u16 prefix_len;
+		const char *fmt;
+
+		level = LOGLEVEL_DEFAULT;
+		prefix_len = parse_prefix(fptr[0], &level, NULL);
+		fmt = fptr[0] + prefix_len;
+
+		seq_printf(s, "<%d> ", level);
+		seq_escape_printf_format(s, fmt);
+		seq_printf(s, "\n");
 	}
 
 out_unlock:
@@ -2113,7 +2121,7 @@ static inline u32 printk_caller_id(void)
  *
  * Return: The length of the parsed level and control flags.
  */
-static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
+static u16 parse_prefix(const char *text, int *level, enum log_flags *lflags)
 {
 	u16 prefix_len = 0;
 	int kern_level;
-- 
2.26.2