printk: Userspace format indexing support

From an abstract point of view, escape_special's counterpart, unescape_special, already handles the unescaping of blackslashed double quote sequences.

As a more practical example, printk indexing is an example case where this is already practically useful. Compare an example with ESCAPE_SPECIAL | ESCAPE_SPACE, with quotes not escaped:

[root@ktst ~]# grep drivers/pci/pci-stub.c:69 /sys/kernel/debug/printk/index/vmlinux <4> drivers/pci/pci-stub.c:69 pci_stub_init "pci-stub: invalid ID string "%s"\n"

...and the same after this patch:

[root@ktst ~]# grep drivers/pci/pci-stub.c:69 /sys/kernel/debug/printk/index/vmlinux <4> drivers/pci/pci-stub.c:69 pci_stub_init "pci-stub: invalid ID string \"%s\"\n"

One can of course, alternatively, use ESCAPE_APPEND with a quote in @only, but without this patch quotes are coerced into hex or octal which can hurt readability quite significantly.

A new ESCAPE_QUOTE/ESCAPE_PRINTK option is also possible, but it seems reasonable to use the simplest strategy first, since this is already decoded properly.

Signed-off-by Chris Down <[email protected]>

Cc Andy Shevchenko <[email protected]>

Cc Rasmus Villemoes <[email protected]>

---
 lib/string_helpers.c      |  4 ++++
 lib/test-string_helpers.c | 14 +++++++-------
 2 files changed, 11 insertions(+), 7 deletions(-)

lib/string_helpers.c +4 -0

index 5a35c7e16e96..3806a52ce697 100644
@@ -361,6 +361,9 @@ static bool escape_special(unsigned char c, char **dst, char *end)
 	case '\e':
 		to = 'e';
 		break;
+	case '"':
+		to = '"';
+		break;
 	default:
 		return false;
 	}

@@ -474,6 +477,7 @@ static bool escape_hex(unsigned char c, char **dst, char *end)
  *		'\t' - horizontal tab
  *		'\v' - vertical tab
  *	%ESCAPE_SPECIAL:
+ *		'\"' - double quote
  *		'\\' - backslash
  *		'\a' - alert (BEL)
  *		'\e' - escape

lib/test-string_helpers.c +7 -7

index 2185d71704f0..437d8e6b7cb1 100644
@@ -140,13 +140,13 @@ static const struct test_string_2 escape0[] __initconst = {{
 },{
 	.in = "\\h\\\"\a\e\\",
 	.s1 = {{
-		.out = "\\\\h\\\\\"\\a\\e\\\\",
+		.out = "\\\\h\\\\\\\"\\a\\e\\\\",
 		.flags = ESCAPE_SPECIAL,
 	},{
-		.out = "\\\\\\150\\\\\\042\\a\\e\\\\",
+		.out = "\\\\\\150\\\\\\\"\\a\\e\\\\",
 		.flags = ESCAPE_SPECIAL | ESCAPE_OCTAL,
 	},{
-		.out = "\\\\\\x68\\\\\\x22\\a\\e\\\\",
+		.out = "\\\\\\x68\\\\\\\"\\a\\e\\\\",
 		.flags = ESCAPE_SPECIAL | ESCAPE_HEX,
 	},{
 		/* terminator */

@@ -157,10 +157,10 @@ static const struct test_string_2 escape0[] __initconst = {{
 		.out = "\eb \\C\007\"\x90\\r]",
 		.flags = ESCAPE_SPACE,
 	},{
-		.out = "\\eb \\\\C\\a\"\x90\r]",
+		.out = "\\eb \\\\C\\a\\\"\x90\r]",
 		.flags = ESCAPE_SPECIAL,
 	},{
-		.out = "\\eb \\\\C\\a\"\x90\\r]",
+		.out = "\\eb \\\\C\\a\\\"\x90\\r]",
 		.flags = ESCAPE_SPACE | ESCAPE_SPECIAL,
 	},{
 		.out = "\\033\\142\\040\\134\\103\\007\\042\\220\\015\\135",

@@ -169,10 +169,10 @@ static const struct test_string_2 escape0[] __initconst = {{
 		.out = "\\033\\142\\040\\134\\103\\007\\042\\220\\r\\135",
 		.flags = ESCAPE_SPACE | ESCAPE_OCTAL,
 	},{
-		.out = "\\e\\142\\040\\\\\\103\\a\\042\\220\\015\\135",
+		.out = "\\e\\142\\040\\\\\\103\\a\\\"\\220\\015\\135",
 		.flags = ESCAPE_SPECIAL | ESCAPE_OCTAL,
 	},{
-		.out = "\\e\\142\\040\\\\\\103\\a\\042\\220\\r\\135",
+		.out = "\\e\\142\\040\\\\\\103\\a\\\"\\220\\r\\135",
 		.flags = ESCAPE_SPACE | ESCAPE_SPECIAL | ESCAPE_OCTAL,
 	},{
 		.out = "\eb \\C\007\"\x90\r]",

Signature · 1 line

2.31.1

We have only one direct user of ESCAPE_SPECIAL and there " is not used.

Indirect ones are %pE, but IIRC most of them are either debug messages or some kind of (non-ABI) messages.

It would be nice if you can confirm this and put a note into commit message.

If the above is confirmed, feel free to add mine Reviewed-by; Andy Shevchenko <[email protected]>

Quoted 1 line

From an abstract point of view, escape_special's counterpart,

unescape_special, already handles the unescaping of blackslashed double quote sequences.

Signed-off-by Chris Down <[email protected]>

Cc Andy Shevchenko <[email protected]>

Cc Rasmus Villemoes <[email protected]>

In the past, enum log_flags was part of struct log, hence the name. struct log has since been reworked and now this struct is stored inside struct printk_info. However, the name was never updated, which is somewhat confusing -- especially since these flags operate at the record level rather than at the level of an abstract log.

printk_info_flags also joins its other metadata struct friends in printk_ringbuffer.h.

Signed-off-by Chris Down <[email protected]>

Cc Petr Mladek <[email protected]>

kernel/printk/printk_ringbuffer.h +0 -0

 /*
  * A descriptor: the complete meta-data for a record.
  *

Signature · 1 line

2.31.1

Quoted 8 lines

kernel/printk/printk_ringbuffer.h +0 -0

index 73cc80e01cef..71918d47ca95 100644
@@ -50,6 +50,12 @@ struct prb_data_blk_lpos {
 	unsigned long	next;
 };
 

kernel/printk/printk_ringbuffer.h struct prb_data_blk_lpos { · line 57

Quoted 5 lines

kernel/printk/printk_ringbuffer.h +5 -0

+/* Flags for a single printk record. */
+enum printk_info_flags {
+	LOG_NEWLINE	= 2,	/* text ended with a newline */
+	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+};

Nit: Could you please move this after "enum desc_state" declaration?

Quoted 8 lines · Petr Mladek

Quoted 8 lines

kernel/printk/printk_ringbuffer.h +0 -0

index 73cc80e01cef..71918d47ca95 100644
@@ -50,6 +50,12 @@ struct prb_data_blk_lpos {
 	unsigned long	next;
 };
 

Quoted 7 lines

kernel/printk/printk_ringbuffer.h struct prb_data_blk_lpos { · line 57

Quoted 5 lines

kernel/printk/printk_ringbuffer.h +5 -0

+/* Flags for a single printk record. */
+enum printk_info_flags {
+	LOG_NEWLINE	= 2,	/* text ended with a newline */
+	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+};

Nit: Could you please move this after "enum desc_state" declaration?

Is there a reason that this enum is moved into printk_ringbuffer.h? The ringbuffer does not use this enum.

Quoted 16 lines

Quoted 15 lines

kernel/printk/printk_ringbuffer.h struct prb_data_blk_lpos { · line 57

Quoted 13 lines

kernel/printk/printk_ringbuffer.h +5 -0

index 73cc80e01cef..71918d47ca95 100644
@@ -50,6 +50,12 @@ struct prb_data_blk_lpos {
 	unsigned long	next;
 };
 
+/* Flags for a single printk record. */
+enum printk_info_flags {
+	LOG_NEWLINE	= 2,	/* text ended with a newline */
+	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+};

Nit: Could you please move this after "enum desc_state" declaration?

Quoted 2 lines

Is there a reason that this enum is moved into printk_ringbuffer.h? The ringbuffer does not use this enum.

We want to use it in two source files: printk.c and index.c Alternative solution would be to move it to kernel/printk/internal.h.

Well, will internal.h still be needed after we remove printk_safe?

Quoted 16 lines · Petr Mladek

Quoted 16 lines

Quoted 15 lines

kernel/printk/printk_ringbuffer.h struct prb_data_blk_lpos { · line 57

Quoted 13 lines

kernel/printk/printk_ringbuffer.h +5 -0

index 73cc80e01cef..71918d47ca95 100644
@@ -50,6 +50,12 @@ struct prb_data_blk_lpos {
 	unsigned long	next;
 };
 
+/* Flags for a single printk record. */
+enum printk_info_flags {
+	LOG_NEWLINE	= 2,	/* text ended with a newline */
+	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+};

Nit: Could you please move this after "enum desc_state" declaration?

Quoted 7 lines

Quoted 2 lines

Is there a reason that this enum is moved into printk_ringbuffer.h? The ringbuffer does not use this enum.

We want to use it in two source files: printk.c and index.c Alternative solution would be to move it to kernel/printk/internal.h.

Well, will internal.h still be needed after we remove printk_safe?

We wouldn't be able to remove internal.h until deferred printing is removed. And that cannot happen until after printing kthreads exist. So it will still hang around for a while.

But even so, I do not like the idea of turning printk_ringbuffer.h into the new internal.h. The ringbuffer is quite complex and IMHO we should try to keep the printk_ringbuffer.* files as isolated as possible.

I would prefer to put this enum declaration in internal.h. Even if eventually it is the only thing left in internal.h.

Fair enough. Chris, please move enum printk_info_flags declaration into kernel/printk/internal.h

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.

While for some kinds of issues we have counters, tracepoints, or metrics with a stable interface which can reliably indicate the issue, in order to react to production issues quickly we need to work with the interface which most kernel developers naturally use when developing: printk.

Most production issues come from unexpected phenomena, and as such usually the code in question doesn't have easily usable tracepoints or other counters available for the specific problem being mitigated. We have a number of lines of monitoring defence against problems in production (host metrics, process metrics, service metrics, etc), and where it's not feasible to reliably monitor at another level, this kind of pragmatic netconsole monitoring is essential.

As one would expect, monitoring using printk is rather brittle for a number of reasons -- most notably that the message might disappear entirely in a new version of the kernel, or that the message may change in some way that the regex or other classification methods start to silently fail.

One factor that makes this even harder is that, under normal operation, many of these messages are never expected to be hit. For example, there may be a rare hardware bug which one wants to detect if it was to ever happen again, but its recurrence is not likely or anticipated. This precludes using something like checking whether the printk in question was printed somewhere fleetwide recently to determine whether the message in question is still present or not, since we don't anticipate that it should be printed anywhere, but still need to monitor for its future presence in the long-term.

This class of issue has happened on a number of occasions, causing unhealthy machines with hardware issues to remain in production for longer than ideal. As a recent example, some monitoring around blk_update_request fell out of date and caused semi-broken machines to remain in production for longer than would be desirable.

Searching through the codebase to find the message is also extremely fragile, because many of the messages are further constructed beyond their callsite (eg. btrfs_printk and other module-specific wrappers, each with their own functionality). Even if they aren't, guessing the format and formulation of the underlying message based on the aesthetics of the message emitted is not a recipe for success at scale, and our previous issues with fleetwide machine health checking demonstrate as much.

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:

    $ head -1 vmlinux; shuf -n 5 vmlinux
    # <level[,flags]> filename:line function "format"
    <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n"
    <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n"
    <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n"
    <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n"
    <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n"

This mitigates the majority of cases where we have a highly-specific printk which we want to match on, as we can now enumerate and check whether the format changed or the printk callsite disappeared entirely in userspace. This allows us to catch changes to printks we monitor earlier and decide what to do about it before it becomes problematic.

There is no additional runtime cost for printk callers or printk itself, and the assembly generated is exactly the same.

include/linux/printk.h +11 -0

+		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, \

(quoted diff) +1 -0

+	})

+/*
+ * printk/index.c - Userspace indexing of printk formats

+ */

+}

(quoted diff) +1 -0

+	}

+static void *pi_start(struct seq_file *s, loff_t *pos);

kernel/printk/index.c new file +21 -0

+static void *pi_next(struct seq_file *s, void *v, loff_t *pos)
+{
+	const struct module *mod = s->file->f_inode->i_private;
+	struct pi_entry *entry = pi_get_entry(mod, *pos);
+
+	(*pos)++;
+
+	return entry;
+}
+
+static void *pi_start(struct seq_file *s, loff_t *pos)
+{
+	/*
+	 * Make show() print the header line. Do not update *pos because
+	 * pi_next() still has to return the entry at index 0 later.
+	 */
+	if (*pos == 0)
+		return SEQ_START_TOKEN;
+
+	return pi_next(s, NULL, pos);
+}

kernel/printk/index.c line 23

Quoted 3 lines

kernel/printk/index.c new file +3 -0

+static const char *pi_get_module_name(struct module *mod)
+{
+	return mod ? mod->name : "vmlinux";

First of all, you have several occurrences of the "vmlinux" literal. Second, can't you get it from somewhere else? Is it even guaranteed that the name is always the same?

kernel/printk/index.c line 114

Quoted 2 lines

kernel/printk/index.c new file +2 -0

+#define seq_escape_printf_format(s, src) \
+	seq_escape_str(s, src, ESCAPE_ANY | ESCAPE_NAP | ESCAPE_APPEND, "\"\\")

Hmm... But after your ESCAPE_SPECIAL update why " is in @only? Not sure about back slash either.

One can of course, alternatively, use ESCAPE_APPEND with a quote in @only, but without this patch quotes are coerced into hex or octal which can hurt readability quite significantly.

Quoted 4 lines

kernel/printk/index.c new file +4 -0

+static int __init pi_init(void)
+{
+	struct dentry *dfs_root = debugfs_create_dir("printk", NULL);
+

kernel/printk/index.c line 195

Quoted 6 lines

kernel/printk/index.c new file +6 -0

+	dfs_index = debugfs_create_dir("index", dfs_root);
+	pi_setup_module_notifier();
+	pi_create_file(NULL);
+
+	return 0;
+}

No __exit? (There is a corresponding call for exit)

Andy Shevchenko writes:

Quoted 5 lines

kernel/printk/index.c line 23

Quoted 1 line

kernel/printk/index.c new file +1 -0

+	return mod ? mod->name : "vmlinux";

First of all, you have several occurrences of the "vmlinux" literal. Second, can't you get it from somewhere else? Is it even guaranteed that the name is always the same?

Hmm, I don't know if it's guaranteed, but we already have similar logic in (as one example) livepatch, which seems to suggest it's not obviously wrong:

    % grep -R '"vmlinux"' kernel/livepatch/
    kernel/livepatch/core.c:                       sympos, name, objname ? objname : "vmlinux");
    kernel/livepatch/core.c:        bool sec_vmlinux = !strcmp(sec_objname, "vmlinux");
    kernel/livepatch/core.c:                sym_vmlinux = !strcmp(sym_objname, "vmlinux");
    kernel/livepatch/core.c:        if (strcmp(objname ? objname : "vmlinux", sec_objname))
    kernel/livepatch/core.c:        name = klp_is_module(obj) ? obj->name : "vmlinux";
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:        if (!strcmp(mod->name, "vmlinux")) {

Is there another name or method you'd prefer? :-)

As for the literals, are you saying that you prefer that it's symbolised as a macro or static char, or do you know of an API where this kind of name can be canonically accessed?

Quoted 5 lines

kernel/printk/index.c line 114

Quoted 2 lines

kernel/printk/index.c new file +2 -0

+#define seq_escape_printf_format(s, src) \
+	seq_escape_str(s, src, ESCAPE_ANY | ESCAPE_NAP | ESCAPE_APPEND, "\"\\")

Hmm... But after your ESCAPE_SPECIAL update why " is in @only? Not sure about back slash either.

Good question! It's because ESCAPE_NAP (used to reduce scope of ESCAPE_OCTAL) will cause double quote and backslash to be ignored for quoting otherwise, even with ESCAPE_SPECIAL from ESCAPE_ANY.

I touched on this briefly in the changelog for the patch adding the quote to ESCAPE_SPECIAL:

From "string_helpers: Escape double quotes in escape_special":

Quoted 3 lines

One can of course, alternatively, use ESCAPE_APPEND with a quote in @only, but without this patch quotes are coerced into hex or octal which can hurt readability quite significantly.

Maybe you know of a more intuitive way to deal with this? :-)

Quoted 3 lines

Quoted 1 line

+static int __init pi_init(void)

No __exit? (There is a corresponding call for exit)

Hmm, can't printk only be built in to the kernel, so it can't be unloaded? At least it looks that way from Kconfig. Maybe I'm missing something and there's some other way that might be invoked?

Quoted 3 lines

As for the literals, are you saying that you prefer that it's symbolised as a macro or static char, or do you know of an API where this kind of name can be canonically accessed?

I have heard that modern GCC (at least) can utilize same constant literals in a single compilation unit, so it won't be duplicated.

But more serious here is the guarantees of the name. Shouldn't it come from KBuild / Makefile into some header like version do?

Quoted 6 lines

Quoted 5 lines

kernel/printk/index.c line 114

Quoted 2 lines

kernel/printk/index.c new file +2 -0

+#define seq_escape_printf_format(s, src) \
+	seq_escape_str(s, src, ESCAPE_ANY | ESCAPE_NAP | ESCAPE_APPEND, "\"\\")

Hmm... But after your ESCAPE_SPECIAL update why " is in @only? Not sure about back slash either.

Quoted 3 lines

Good question! It's because ESCAPE_NAP (used to reduce scope of ESCAPE_OCTAL) will cause double quote and backslash to be ignored for quoting otherwise, even with ESCAPE_SPECIAL from ESCAPE_ANY.

Ah, makes sense. Yep, it's a bit complicated, but okay, perhaps it needs a comment near to the macro.

Quoted 7 lines

Quoted 3 lines

Quoted 1 line

+static int __init pi_init(void)

No __exit? (There is a corresponding call for exit)

Hmm, can't printk only be built in to the kernel, so it can't be unloaded? At least it looks that way from Kconfig. Maybe I'm missing something and there's some other way that might be invoked?

While it's true, it may help in these cases:
1) getting things done in a clean way
2) finding bugs during boot cycle
3) (possibly) making better debugging in virtual environments
4) (also possibly) clean up something which shouldn't be seen by the next (unsecure) kernel, like kexec.

I'm not sure about these, but it what comes to my mind.

Quoted 7 lines · Andy Shevchenko

Quoted 3 lines

As for the literals, are you saying that you prefer that it's symbolised as a macro or static char, or do you know of an API where this kind of name can be canonically accessed?

I have heard that modern GCC (at least) can utilize same constant literals in a single compilation unit, so it won't be duplicated.

Quoted 2 lines

But more serious here is the guarantees of the name. Shouldn't it come from KBuild / Makefile into some header like version do?

I'm not against that, but it seems like something worth doing outside of this patch series, unless you have strong feelings to the contrary?

More than happy to put that on my TODO list for tree-wide cleanups.

Quoted 1 line · Chris Down

Andy Shevchenko writes:

...

Quoted 19 lines

Quoted 5 lines

kernel/printk/index.c line 23

Quoted 1 line

kernel/printk/index.c new file +1 -0

+	return mod ? mod->name : "vmlinux";

First of all, you have several occurrences of the "vmlinux" literal. Second, can't you get it from somewhere else? Is it even guaranteed that the name is always the same?

Hmm, I don't know if it's guaranteed, but we already have similar logic in (as one example) livepatch, which seems to suggest it's not obviously wrong:

    % grep -R '"vmlinux"' kernel/livepatch/
    kernel/livepatch/core.c:                       sympos, name, objname ? objname : "vmlinux");
    kernel/livepatch/core.c:        bool sec_vmlinux = !strcmp(sec_objname, "vmlinux");
    kernel/livepatch/core.c:                sym_vmlinux = !strcmp(sym_objname, "vmlinux");
    kernel/livepatch/core.c:        if (strcmp(objname ? objname : "vmlinux", sec_objname))
    kernel/livepatch/core.c:        name = klp_is_module(obj) ? obj->name : "vmlinux";
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:        if (!strcmp(mod->name, "vmlinux")) {

Quoted 5 lines

Is there another name or method you'd prefer? :-)

As for the literals, are you saying that you prefer that it's symbolised as a macro or static char, or do you know of an API where this kind of name can be canonically accessed?

I have heard that modern GCC (at least) can utilize same constant literals in a single compilation unit, so it won't be duplicated.

Quoted 8 lines

Quoted 4 lines

Quoted 2 lines

+static int __init pi_init(void)

No __exit? (There is a corresponding call for exit)

Hmm, can't printk only be built in to the kernel, so it can't be unloaded? At least it looks that way from Kconfig. Maybe I'm missing something and there's some other way that might be invoked?

While it's true, it may help in these cases:
1) getting things done in a clean way

2) finding bugs during boot cycle

3) (possibly) making better debugging in virtual environments

4) (also possibly) clean up something which shouldn't be seen by the next (unsecure) kernel, like kexec.

Quoted 2 lines · Andy Shevchenko

Quoted 1 line · Chris Down

Andy Shevchenko writes:

Quoted 19 lines

Quoted 19 lines

Quoted 5 lines

kernel/printk/index.c line 23

Quoted 1 line

kernel/printk/index.c new file +1 -0

+	return mod ? mod->name : "vmlinux";

First of all, you have several occurrences of the "vmlinux" literal. Second, can't you get it from somewhere else? Is it even guaranteed that the name is always the same?

Hmm, I don't know if it's guaranteed, but we already have similar logic in (as one example) livepatch, which seems to suggest it's not obviously wrong:

    % grep -R '"vmlinux"' kernel/livepatch/
    kernel/livepatch/core.c:                       sympos, name, objname ? objname : "vmlinux");
    kernel/livepatch/core.c:        bool sec_vmlinux = !strcmp(sec_objname, "vmlinux");
    kernel/livepatch/core.c:                sym_vmlinux = !strcmp(sym_objname, "vmlinux");
    kernel/livepatch/core.c:        if (strcmp(objname ? objname : "vmlinux", sec_objname))
    kernel/livepatch/core.c:        name = klp_is_module(obj) ? obj->name : "vmlinux";
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:                                klp_is_module(obj) ? obj->name : "vmlinux");
    kernel/livepatch/core.c:        if (!strcmp(mod->name, "vmlinux")) {

Quoted 8 lines

Quoted 5 lines

Is there another name or method you'd prefer? :-)

As for the literals, are you saying that you prefer that it's symbolised as a macro or static char, or do you know of an API where this kind of name can be canonically accessed?

I have heard that modern GCC (at least) can utilize same constant literals in a single compilation unit, so it won't be duplicated.

Yes, except it's not gcc but ld, string deduplication happens across compilation units, and "modern" isn't required, SHF_STRINGS and SHF_MERGE have been part of the ELF spec for decades, with support in binutils landing around 2001-04-13 AFAICT.

IOW, don't uglify the code by introducing macros or const char[] objects. Using string literals is just fine.

Quoted 10 lines

Quoted 7 lines

Quoted 3 lines

Quoted 1 line

+static int __init pi_init(void)

No __exit? (There is a corresponding call for exit)

Hmm, can't printk only be built in to the kernel, so it can't be unloaded? At least it looks that way from Kconfig. Maybe I'm missing something and there's some other way that might be invoked?

While it's true, it may help in these cases:
1) getting things done in a clean way

Huh?

Quoted 1 line

2) finding bugs during boot cycle

What bugs would code that doesn't get executed find?

Quoted 1 line

3) (possibly) making better debugging in virtual environments

How?

Quoted 2 lines

4) (also possibly) clean up something which shouldn't be seen by the next (unsecure) kernel, like kexec.

Tearing down a few debugfs files wouldn't touch a lot of memory, the printk format strings are very unlikely to be sensitive, and I highly doubt __exit code is kept around and run at kexec time anyway.

IOW, please do not bloat the kernel image with __exit code in things which cannot be built modular.

Quoted 21 lines · Rasmus Villemoes

Quoted 11 lines · Andy Shevchenko

Quoted 7 lines · Chris Down

Quoted 3 lines

Quoted 1 line

+static int __init pi_init(void)

No __exit? (There is a corresponding call for exit)

Hmm, can't printk only be built in to the kernel, so it can't be unloaded? At least it looks that way from Kconfig. Maybe I'm missing something and there's some other way that might be invoked?

While it's true, it may help in these cases:
1) getting things done in a clean way

Huh?

Quoted 1 line

2) finding bugs during boot cycle

What bugs would code that doesn't get executed find?

Quoted 1 line

3) (possibly) making better debugging in virtual environments

Quoted 8 lines

How?

Quoted 2 lines

4) (also possibly) clean up something which shouldn't be seen by the next (unsecure) kernel, like kexec.

Tearing down a few debugfs files wouldn't touch a lot of memory, the printk format strings are very unlikely to be sensitive, and I highly doubt __exit code is kept around and run at kexec time anyway.

I admit that I'm on a learning curve in this area, and perhaps it was unclear from the above that the list I gave is what I think may or might be relevant.

Quoted 2 lines

IOW, please do not bloat the kernel image with __exit code in things which cannot be built modular.

Why we have exitcall in the code which can't be modular? Is somebody going to clean that up? (Ex. git grep -w __exitcall)

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:

include/linux/printk.h +13 -0

index f589b8b60806..40b97d538e12 100644
+#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.
+	 *

include/linux/printk.h +10 -0

+} __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

include/linux/printk.h +16 -0

+			};						       \
+			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

+ */

include/linux/printk.h +10 -0

+#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__);				       \
+	})
+
+

kernel/printk/index.c new file +17 -0

@@ -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/ */

kernel/printk/index.c new file +17 -0

+
+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;
+}

kernel/printk/index.c new file +5 -0

+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;

kernel/printk/index.c new file +10 -0

+	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;
+}
+

kernel/printk/internal.h +2 -0

index 51615c909b2f..dbeeb2fa74ab 100644
@@ -4,6 +4,8 @@
  */
 #include <linux/percpu.h>
 
+#include "printk_ringbuffer.h"
+
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK	0x007ffffff

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

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.

Quoted 11 lines

include/linux/printk.h +10 -0

+} __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

include/linux/printk.h extern int kptr_restrict; · line 353

Quoted 10 lines

include/linux/printk.h +10 -0

+			 * 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

Quoted 3 lines

+ * 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.

Review

Quoted 2 lines

(quoted diff) +2 -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.

kernel/printk/index.c line 135

Quoted 7 lines

kernel/printk/index.c new file +5 -0

+
+	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: "

kernel/printk/index.c line 139

Quoted 4 lines

kernel/printk/index.c new file +4 -0

+
+	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);

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.

Hey Petr,

Thanks for the feedback -- apologies for the delay in getting back.

Quoted 2 lines · Petr Mladek

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

Hmm, we do actually store pr_fmt, since it's known at compile time (or we wouldn't store it at all if it was dynamic due to the __builtin_constant_p check). Or are you seeing something different?

Quoted 1 line

I would personally omit these prefixes. The most important

Having this information means that system monitors know that they can anchor the matching at both ends when linking a printk format with some output, rather than having to look for a substring (in which case things become more difficult to determine).

I agree that in this particular case with dev_printk it's not incredibly useful, but there are certainly others we may want to have in future (like the btrfs case) where it would certainly help disambiguate. :-)

Quoted 23 lines

Quoted 10 lines

include/linux/printk.h +10 -0

+} __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

include/linux/printk.h extern int kptr_restrict; · line 353

Quoted 10 lines

include/linux/printk.h +10 -0

+			 * 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?

Quoted 2 lines

	.pre_fmt = __builtin_constant_p(_pre_fmt) ? _pre_fmt : NULL

Hmm, if pre_fmt for a subsystem isn't known at compile time, it's an error on the developer's end -- otherwise things can't be stored anyway and there's no point.

Quoted 6 lines

Quoted 3 lines

+ * 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?

Quoted 5 lines

__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.

Maybe my phrasing wasn't clear, but compilation would fail in that case because .pre_fmt = _pre_fmt will be a non-constant static initialiser, no?

Quoted 4 lines

Review

Quoted 2 lines

(quoted diff) +2 -0

+	if (!entry->fmt)
+		return 0;

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

It happens only for the following printk:

arch/x86/mm/fault.c:534 show_fault_oops "BUG: kernel NULL pointer dereference, address: %px\n"

Quoted 5 lines

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.

The trick is unfortunately necessary for the reason described in the comment above the double check:

/*
* 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. */

Happy to add another comment if it helps.

Quoted 8 lines

kernel/printk/index.c line 135

Quoted 5 lines

kernel/printk/index.c new file +5 -0

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

This is missing:

Quoted 8 lines

	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: "

Hmm, from the perspective of someone building this printk-checking infrastructure, I want -1 here instead of dynamically changing the output to default_message_loglevel, because default_message_loglevel may not be the same across systems. For example, having "-1" allows people to know these will come out at whatever the default message loglevel is, rather than necessarily being always at (say) level 4 or whatever it happens to be set at on the running system.

Without that, it's also not possible to compare entries across systems or across time, because the default loglevel may dynamically change at runtime, and it's not possible to disambiguate "will always be KERN_X" from "happens to be KERN_X" on this system.

And if someone really does want to know what value it will be right now, they can just look at /proc/sys/kernel/printk and change it out as desired.

Quoted 7 lines

Quoted 2 lines · Petr Mladek

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

Hmm, we do actually store pr_fmt, since it's known at compile time (or we wouldn't store it at all if it was dynamic due to the __builtin_constant_p check). Or are you seeing something different?

I see. Well, the prefix defined by pr_fmt() becomes part of entry.fmt. It is _not_ stored in entry.pre_fmt which confused me.

As I mentioned in the previous mail. I think about using "subsys_fmt" or "subsys_prefix" instead of "pre_fmt".

Anyway, we should improve the comment. For example, something like:

	/*
	 * The format string used by various subsystem specific printk()
	 * wrappers to prefix the message.
	 *
	 * Note that the static prefix defined by pr_fmt() macro is handled
	 * another way. It is stored directly in the message format (@fmt).
	 */
	const char *subsys_fmt;

Quoted 17 lines

Quoted 5 lines

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.

The trick is unfortunately necessary for the reason described in the comment above the double check:

/*
* 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. */

Quoted 1 line

Happy to add another comment if it helps.

I re-read the discussion about this,
namely https://lore.kernel.org/r/3Kf896Zt9O+/[email protected]

Frankly, the comment above ftrace_vprintk() is easier to understand for me. I mean:

/*
* The double __builtin_constant_p is because gcc will give us an error
* if we try to allocate the static variable to fmt if it is not a
* constant. Even with the outer if statement.
*/

While for most kinds of issues we have counters, tracepoints, or metrics with a stable interface which can reliably be used to indicate issues, in order to react to production issues quickly we sometimes need to work with the interface which most kernel developers naturally use when
developing: printk, and printk-esques like dev_printk.

dev_printk is by far the most likely custom subsystem printk to benefit from the printk indexing infrastructure, since niche device issues brought about by production changes, firmware upgrades, and the like are one of the most common things that we need printk infrastructure's assistance to monitor.

Often these errors were never expected to practically manifest in reality, and exhibit in code without extensive (or any) metrics present. As such, there are typically very few options for issue detection available to those with large fleets at the time the incident happens, and we thus benefit strongly from monitoring netconsole in these instances.

As such, add the infrastructure for dev_printk to be indexed in the printk index. Even on a minimal kernel config, the coverage of the base kernel's printk index is significantly improved:

Before:

[root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux 4497 /sys/kernel/debug/printk/index/vmlinux

After:

[root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux 5573 /sys/kernel/debug/printk/index/vmlinux

In terms of implementation, in order to trivially disambiguate them, dev_printk is now a macro which wraps _dev_printk. If preferred, it's also possible to have the macro and function have the same name.

include/linux/dev_printk.h +0 -0

index 6f009559ee54..202c6a9ea7eb 100644
@@ -97,25 +97,54 @@ void _dev_info(const struct device *dev, const char *fmt, ...)
 
 #endif

include/linux/dev_printk.h +8 -14

+	_dev_printk(level, dev, fmt, ##__VA_ARGS__);		\
+})
+
 /*
  * #defines for all the dev_<level> macros to prefix with whatever
  * possible use of #define dev_fmt(fmt) ...
  */
 
-#define dev_emerg(dev, fmt, ...)					\
-	_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_crit(dev, fmt, ...)						\
-	_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_alert(dev, fmt, ...)					\
-	_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_err(dev, fmt, ...)						\
-	_dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_warn(dev, fmt, ...)						\
-	_dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_notice(dev, fmt, ...)					\
-	_dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__)
-#define dev_info(dev, fmt, ...)						\
-	_dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__)
+#define dev_printk_index_emit(level, fmt)				\
+	printk_index_subsys_emit("%s %s: ", "", level, fmt)
+
+#define dev_emerg(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_EMERG, dev_fmt(fmt));		\