lkml.org 
[lkml]   [2021]   [Feb]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
Subjectoutput: was: Re: [PATCH v4] printk: Userspace format enumeration support
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
\
 
 \ /
  Last update: 2021-02-17 11:38    [W:0.145 / U:0.068 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site