lkml.org 
[lkml]   [2021]   [May]   [25]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: [PATCH v6 3/4] printk: Userspace format indexing support
    On Tue 2021-05-18 13:00:43, 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.
    >
    > This 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_index section, both in vmlinux and
    > modules. At runtime, this can then be iterated by looking at
    > <debugfs>/printk/index/<module>, which emits the following format, both
    > readable by humans and able to be parsed by machines:
    >
    > diff --git a/include/linux/printk.h b/include/linux/printk.h
    > index f589b8b60806..40b97d538e12 100644
    > --- a/include/linux/printk.h
    > +++ b/include/linux/printk.h
    > +#ifdef CONFIG_PRINTK_INDEX
    > +struct pi_entry {
    > + const char *fmt;
    > + const char *func;
    > + const char *file;
    > + unsigned int line;
    > +
    > + /*
    > + * While printk and pr_* have the level stored in the string at compile
    > + * time, some subsystems dynamically add it at runtime through the
    > + * format string. For these dynamic cases, we allow the subsystem to
    > + * tell us the level at compile time.
    > + *
    > + * NULL indicates that the level, if any, is stored in fmt.
    > + */
    > + const char *level;
    > +
    > + /*
    > + * The format string before and after the fmt, or at least something
    > + * that would match whatever it could be.
    > + */
    > + const char *pre_fmt;
    > + const char *post_fmt;

    Are you aware of any subsystem having some extra post_fmt, please?

    I think about calling this "subsys_fmt" or "subsys_prefix".

    Well, the main question is whether we need to store this
    at all. Does it bring any useful information?

    Note that we do not store the value defined by pr_fmt() which
    is yet another automatically added prefix.

    I would personally omit these prefixes. The most important
    information is:

    + fmt: is the pattern that the system monitors would most likely
    look for.

    + level: says whether the string will appear on console that
    shows only messages below a certain console_loglevel

    + func, file, line: help to find the string in the kernel sources.
    It is useful when investigating what has changed.

    For example, pre_fmt="%s %s:" used by dev_printk (4th patch)
    is not much useful.


    > +} __packed;
    > +
    > +#define __printk_index_emit(_fmt, _level, _pre_fmt, _post_fmt) \
    > + ({ \
    > + if (__builtin_constant_p(_fmt) && __builtin_constant_p(_level)) { \
    > + /*
    > + * The compiler may not be able to eliminate the
    > + * non-constant variants of _fmt and _level, so we need
    > + * to make sure that it doesn't see any hypothetical
    > + * assignment for non-constants even though this is
    > + * already inside the __builtin_constant_p guard.
    > + */ \
    > + static const struct pi_entry _entry \
    > + __used = { \
    > + .fmt = __builtin_constant_p(_fmt) ? (_fmt) : NULL, \
    > + .func = __func__, \
    > + .file = __FILE__, \
    > + .line = __LINE__, \
    > + .level = __builtin_constant_p(_level) ? (_level) : NULL, \
    > + .pre_fmt = _pre_fmt, \

    Should this also be?

    .pre_fmt = __builtin_constant_p(_pre_fmt) ? _pre_fmt : NULL

    > + .post_fmt = _post_fmt, \

    Similar here.

    Well, I would remove .pre_fmt and .post_fmt completely.

    > + }; \
    > + static const struct pi_entry *_entry_ptr \
    > + __used __section(".printk_index") = &_entry; \
    > + } \
    > + })
    > +
    > +#else /* !CONFIG_PRINTK_INDEX */
    > +#define __printk_index_emit(...) do {} while (0)
    > +#endif /* CONFIG_PRINTK_INDEX */
    > +
    > +/*
    > + * Some subsystems have their own custom printk that applies a va_format to a
    > + * generic format, for example, to include a device number or other metadata
    > + * alongside the format supplied by the caller.
    > + *
    > + * In order to store these in the way they would be emitted by the printk
    > + * infrastructure, the subsystem provides us with the start, fixed string, and
    > + * any subsequent text in the format string.
    > + *
    > + * We take a variable argument list as pr_fmt/dev_fmt/etc are sometimes passed
    > + * as multiple arguments (eg: `"%s: ", "blah"`), and we must only take the
    > + * first one.
    > + *
    > + * pre and post must be known at compile time, or compilation will fail (since
    > + * this is a mistake). If fmt or level is not known at compile time, no index
    > + * entry will be made (since this can legitimately happen).

    How is this achieved, please?

    __printk_index_emit() creates the entry when the following check is true:

    if (__builtin_constant_p(_fmt) && __builtin_constant_p(_level))

    It checks neither _pre_fmt nor _post_fmt.


    > + */
    > +#define printk_index_subsys_emit(pre, post, level, fmt, ...) \
    > + __printk_index_emit(fmt, level, pre, post)
    > +
    > +#define printk_index_wrap(_p_func, _fmt, ...) \
    > + ({ \
    > + __printk_index_emit(_fmt, NULL, NULL, NULL); \
    > + _p_func(_fmt, ##__VA_ARGS__); \
    > + })
    > +
    > +
    > --- /dev/null
    > +++ b/kernel/printk/index.c
    > @@ -0,0 +1,198 @@
    > +// SPDX-License-Identifier: GPL-2.0
    > +/*
    > + * printk/index.c - Userspace indexing of printk formats
    > + */
    > +
    > +#include <linux/debugfs.h>
    > +#include <linux/module.h>
    > +#include <linux/printk.h>
    > +#include <linux/slab.h>
    > +#include <linux/string_helpers.h>
    > +
    > +#include "internal.h"
    > +
    > +extern struct pi_entry *__start_printk_index[];
    > +extern struct pi_entry *__stop_printk_index[];
    > +
    > +/* The base dir for module formats, typically debugfs/printk/index/ */
    > +static struct dentry *dfs_index;
    > +
    > +#ifdef CONFIG_MODULES
    > +static const char *pi_get_module_name(struct module *mod)
    > +{
    > + return mod ? mod->name : "vmlinux";
    > +}
    > +
    > +void pi_create_file(struct module *mod);
    > +void pi_remove_file(struct module *mod);
    I would personally move all this module-notify-related code right
    above pi_init() definition and avoid any forward declarations.


    > +
    > +static int pi_module_notify(struct notifier_block *nb, unsigned long op,
    > + void *data)
    > +{
    > + struct module *mod = data;
    > +
    > + switch (op) {
    > + case MODULE_STATE_COMING:
    > + pi_create_file(mod);
    > + break;
    > + case MODULE_STATE_GOING:
    > + pi_remove_file(mod);
    > + break;
    > + }
    > +
    > + return NOTIFY_OK;
    > +}

    [...]

    > +static int pi_show(struct seq_file *s, void *v)
    > +{
    > + const struct pi_entry *entry = v;
    > + int level = LOGLEVEL_DEFAULT;
    > + enum printk_info_flags flags = 0;
    > + u16 prefix_len = 0;
    > +
    > + if (v == SEQ_START_TOKEN) {
    > + seq_puts(s,
    > + "# <level[,flags]> filename:line function \"format\"\n");
    > + return 0;
    > + }
    > +
    > + if (!entry->fmt)
    > + return 0;

    Is this just a paranoid check or is it a valid case?

    Is is possible to update __printk_index_emit() to do not create
    entries with fmt = NULL ?

    We should either remove the above check or add a comment
    explaining why it is necessary.


    > +
    > + if (entry->level)
    > + printk_parse_prefix(entry->level, &level, &flags);
    > + else
    > + prefix_len = printk_parse_prefix(entry->fmt, &level, &flags);

    This is missing:

    if (level == LOGLEVEL_DEFAULT)
    level = default_message_loglevel;
    Without it, it produces lines with loglevel <-1>, for example:

    <-1> init/do_mounts.c:457 mount_block_root "\n"
    <-1> init/do_mounts.c:456 mount_block_root " %s"
    <-1> init/do_mounts.c:454 mount_block_root "No filesystem could mount root, tried: "



    > +
    > + seq_printf(s, "<%d%s> %s:%d %s \"",
    > + level, flags & LOG_CONT ? ",c" : "", entry->file,
    > + entry->line, entry->func);

    It produces the following for continuous lines:

    <-1,c> arch/x86/events/core.c:2101 init_hw_perf_events "%s PMU driver.\n"
    <-1,c> arch/x86/events/core.c:2091 init_hw_perf_events "no PMU driver, software events only.\n"

    But we should print the loglevel only when explicitly defined.
    So I would do it the following way:

    if (flags & LOG_CONT) {
    if (level == LOGLEVEL_DEFAULT)
    seq_printf(s, "<c>");
    else
    seq_printf(s, "<%d,c>", level);
    } else {
    if (level == LOGLEVEL_DEFAULT)
    level = default_message_loglevel;
    seq_printf(s, "<%d>", level);
    }
    seq_printf(s, " %s:%d %s \"", entry->file, entry->line, entry->func);

    > + if (entry->pre_fmt)
    > + seq_escape_printf_format(s, entry->pre_fmt);
    > + seq_escape_printf_format(s, entry->fmt + prefix_len);
    > + if (entry->post_fmt)
    > + seq_escape_printf_format(s, entry->post_fmt);
    > + seq_puts(s, "\"\n");
    > +
    > + return 0;
    > +}
    > +
    > diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
    > index 51615c909b2f..dbeeb2fa74ab 100644
    > --- a/kernel/printk/internal.h
    > +++ b/kernel/printk/internal.h
    > @@ -4,6 +4,8 @@
    > */
    > #include <linux/percpu.h>
    >
    > +#include "printk_ringbuffer.h"
    > +
    > #ifdef CONFIG_PRINTK
    >
    > #define PRINTK_SAFE_CONTEXT_MASK 0x007ffffff
    > @@ -51,6 +53,8 @@ bool printk_percpu_data_ready(void);
    >
    > void defer_console_output(void);
    >
    > +u16 printk_parse_prefix(const char *text, int *level,
    > + enum printk_info_flags *flags);

    It would be nice to do all this parse_prefix() shuffling and
    renaming in another preparatoty patch. I mean to have
    two preparaty patches:

    + patch renaming enum log_flags -> printk_info_flags
    + patch renaming parse_prefix -> printk_parse_prefix

    That said, I do not resit on it. It is just nice to have ;-)

    > #else
    >
    > /*

    I am really happy with the progress. The remaining problems are mostly
    with the support for the subsystem-specific printk() callers that was
    added in this revision.

    Best Regards,
    Petr

    \
     
     \ /
      Last update: 2021-05-25 17:07    [W:4.769 / U:1.196 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site