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

[Petr Mladek]

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: