All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH v6 0/4] printk: Userspace format indexing support
@ 2021-05-18 12:00 Chris Down
  2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
                   ` (3 more replies)
  0 siblings, 4 replies; 27+ messages in thread
From: Chris Down @ 2021-05-18 12:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Petr Mladek, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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.

---

v2:

- Use seq_printf instead of step by step accumulation
- Scope fptr closer to its use
- Prevent seq_file from needing to alloc a new buffer
- Always provide KERN_SOH + level, even if caller omitted it
- Provide one file per module
- Update changelog to show ease of parsing
- Provide printk -> _printk for ARCH=um (thanks, LKP robot)
- Move to debugfs (thanks, Steven)

---

v3:

- Reduce locking during open by moving size lifetime to the inode
- Don't explicitly check for debugfs errors (thanks, gregkh)

---

v4:

- Fix a missed `extern int printk` fixup in ia64 (thanks, lkp)

---

v5:

Thanks Petr for the extensive feedback.

- Move all module handling from module notifier to module.[ch] directly
- Change to readable output format
  - Handled by new string_escape(ESCAPE_PRINTF)
- Add file/line/function information
- Mass rename everything to printk_index/CONFIG_PRINTK_INDEX/pi_*
  - As a result, this version does away with the mutex/hashtable
- Use seq_file iteration API instead of simple_open
- Remove debugfs file first to avoid ENOENT
- Tear down backing datastructure if debugfs file creation fails
- Move code under ifdef guard to kernel/printk/index.c
- Add pi_sec (formerly printk_fmt_sec) documentation
- Handle coexisting LOG_CONT + level
- Add header to debugfs output
- ...and probably some other stuff I forgot. :-)

---

v6:

- Rebase on next-20210518
- Remove pi_sec, do on demand lookups instead
- Lookup debugfs file on demand
- pi_sec_{store,remove} now only changes debugfs, so renamed
- Don't check for debugfs failure (again)
- Extract lookup logic into pi_get_entry
- Make the stored struct `const __used`
- Use _p_func directly, which allows including void-returning functions
- Move more stuff outside PRINTK_INDEX #ifdef using __printk_index_emit
- Scope __{start,stop}_printk_index more tightly
- Move parse_prefix to printk_parse_prefix in internal.h
- Put PRINTK_INDEX definition below TRACEDATA
- Use a module notifier again
- pi_object -> pi_entry, with clearer vars
- Reword Kconfig
- Split out printk_info_flags/string_helpers stuff into patches
- Use seq_escape_str directly now that ESCAPE_APPEND exists
- Add dev_printk indexing support

Chris Down (4):
  string_helpers: Escape double quotes in escape_special
  printk: Straighten out log_flags into printk_info_flags
  printk: Userspace format indexing support
  printk: index: Add indexing support to dev_printk

 MAINTAINERS                          |   5 +
 arch/arm/kernel/entry-v7m.S          |   2 +-
 arch/arm/lib/backtrace-clang.S       |   2 +-
 arch/arm/lib/backtrace.S             |   2 +-
 arch/arm/mach-rpc/io-acorn.S         |   2 +-
 arch/arm/vfp/vfphw.S                 |   6 +-
 arch/ia64/include/uapi/asm/cmpxchg.h |   4 +-
 arch/openrisc/kernel/entry.S         |   6 +-
 arch/powerpc/kernel/head_fsl_booke.S |   2 +-
 arch/um/include/shared/user.h        |   3 +-
 arch/x86/kernel/head_32.S            |   2 +-
 drivers/base/core.c                  |   6 +-
 include/asm-generic/vmlinux.lds.h    |  13 ++
 include/linux/dev_printk.h           |  63 ++++++---
 include/linux/module.h               |   5 +
 include/linux/printk.h               |  95 ++++++++++++-
 init/Kconfig                         |  14 ++
 kernel/module.c                      |   5 +
 kernel/printk/Makefile               |   1 +
 kernel/printk/index.c                | 198 +++++++++++++++++++++++++++
 kernel/printk/internal.h             |   4 +
 kernel/printk/printk.c               |  60 ++++----
 kernel/printk/printk_ringbuffer.h    |   6 +
 lib/string_helpers.c                 |   4 +
 lib/test-string_helpers.c            |  14 +-
 25 files changed, 448 insertions(+), 76 deletions(-)
 create mode 100644 kernel/printk/index.c

-- 
2.31.1


^ permalink raw reply	[flat|nested] 27+ messages in thread

* [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special
  2021-05-18 12:00 [PATCH v6 0/4] printk: Userspace format indexing support Chris Down
@ 2021-05-18 12:00 ` Chris Down
  2021-05-18 13:10   ` Andy Shevchenko
  2021-05-25 10:17   ` Petr Mladek
  2021-05-18 12:00 ` [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags Chris Down
                   ` (2 subsequent siblings)
  3 siblings, 2 replies; 27+ messages in thread
From: Chris Down @ 2021-05-18 12:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Petr Mladek, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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 <chris@chrisdown.name>
Cc: Andy Shevchenko <andriy.shevchenko@linux.intel.com>
Cc: Rasmus Villemoes <linux@rasmusvillemoes.dk>
---
 lib/string_helpers.c      |  4 ++++
 lib/test-string_helpers.c | 14 +++++++-------
 2 files changed, 11 insertions(+), 7 deletions(-)

diff --git a/lib/string_helpers.c b/lib/string_helpers.c
index 5a35c7e16e96..3806a52ce697 100644
--- a/lib/string_helpers.c
+++ b/lib/string_helpers.c
@@ -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
diff --git a/lib/test-string_helpers.c b/lib/test-string_helpers.c
index 2185d71704f0..437d8e6b7cb1 100644
--- a/lib/test-string_helpers.c
+++ b/lib/test-string_helpers.c
@@ -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]",
-- 
2.31.1


^ permalink raw reply related	[flat|nested] 27+ messages in thread

* [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-18 12:00 [PATCH v6 0/4] printk: Userspace format indexing support Chris Down
  2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
@ 2021-05-18 12:00 ` Chris Down
  2021-05-25 10:33   ` Petr Mladek
  2021-05-18 12:00 ` [PATCH v6 3/4] printk: Userspace format indexing support Chris Down
  2021-05-18 12:00 ` [PATCH v6 4/4] printk: index: Add indexing support to dev_printk Chris Down
  3 siblings, 1 reply; 27+ messages in thread
From: Chris Down @ 2021-05-18 12:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Petr Mladek, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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 <chris@chrisdown.name>
Cc: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c            | 43 ++++++++++++++-----------------
 kernel/printk/printk_ringbuffer.h |  6 +++++
 2 files changed, 26 insertions(+), 23 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 114e9963f903..3201bb0c269c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -350,11 +350,6 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
  * non-prinatable characters are escaped in the "\xff" notation.
  */
 
-enum log_flags {
-	LOG_NEWLINE	= 2,	/* text ended with a newline */
-	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
-};
-
 /* syslog_lock protects syslog_* variables and write access to clear_seq. */
 static DEFINE_RAW_SPINLOCK(syslog_lock);
 
@@ -1966,19 +1961,20 @@ static inline u32 printk_caller_id(void)
  *
  * @text:     The terminated text message.
  * @level:    A pointer to the current level value, will be updated.
- * @lflags:   A pointer to the current log flags, will be updated.
+ * @flags:    A pointer to the current printk_info flags, will be updated.
  *
  * @level may be NULL if the caller is not interested in the parsed value.
  * Otherwise the variable pointed to by @level must be set to
  * LOGLEVEL_DEFAULT in order to be updated with the parsed value.
  *
- * @lflags may be NULL if the caller is not interested in the parsed value.
- * Otherwise the variable pointed to by @lflags will be OR'd with the parsed
+ * @flags may be NULL if the caller is not interested in the parsed value.
+ * Otherwise the variable pointed to by @flags will be OR'd with the parsed
  * value.
  *
  * 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(char *text, int *level,
+			enum printk_info_flags *flags)
 {
 	u16 prefix_len = 0;
 	int kern_level;
@@ -1994,8 +1990,8 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
 				*level = kern_level - '0';
 			break;
 		case 'c':	/* KERN_CONT */
-			if (lflags)
-				*lflags |= LOG_CONT;
+			if (flags)
+				*flags |= LOG_CONT;
 		}
 
 		prefix_len += 2;
@@ -2005,8 +2001,9 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
 	return prefix_len;
 }
 
-static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags,
-			 const char *fmt, va_list args)
+static u16 printk_sprint(char *text, u16 size, int facility,
+			 enum printk_info_flags *flags, const char *fmt,
+			 va_list args)
 {
 	u16 text_len;
 
@@ -2015,7 +2012,7 @@ static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lfl
 	/* Mark and strip a trailing newline. */
 	if (text_len && text[text_len - 1] == '\n') {
 		text_len--;
-		*lflags |= LOG_NEWLINE;
+		*flags |= LOG_NEWLINE;
 	}
 
 	/* Strip log level and control flags. */
@@ -2039,7 +2036,7 @@ int vprintk_store(int facility, int level,
 {
 	const u32 caller_id = printk_caller_id();
 	struct prb_reserved_entry e;
-	enum log_flags lflags = 0;
+	enum printk_info_flags flags = 0;
 	struct printk_record r;
 	u16 trunc_msg_len = 0;
 	char prefix_buf[8];
@@ -2071,22 +2068,22 @@ int vprintk_store(int facility, int level,
 
 	/* Extract log level or control flags. */
 	if (facility == 0)
-		parse_prefix(&prefix_buf[0], &level, &lflags);
+		parse_prefix(&prefix_buf[0], &level, &flags);
 
 	if (level == LOGLEVEL_DEFAULT)
 		level = default_message_loglevel;
 
 	if (dev_info)
-		lflags |= LOG_NEWLINE;
+		flags |= LOG_NEWLINE;
 
-	if (lflags & LOG_CONT) {
+	if (flags & LOG_CONT) {
 		prb_rec_init_wr(&r, reserve_size);
 		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
 			text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size,
-						 facility, &lflags, fmt, args);
+						 facility, &flags, fmt, args);
 			r.info->text_len += text_len;
 
-			if (lflags & LOG_NEWLINE) {
+			if (flags & LOG_NEWLINE) {
 				r.info->flags |= LOG_NEWLINE;
 				prb_final_commit(&e);
 			} else {
@@ -2113,20 +2110,20 @@ int vprintk_store(int facility, int level,
 	}
 
 	/* fill message */
-	text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &lflags, fmt, args);
+	text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &flags, fmt, args);
 	if (trunc_msg_len)
 		memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
 	r.info->text_len = text_len + trunc_msg_len;
 	r.info->facility = facility;
 	r.info->level = level & 7;
-	r.info->flags = lflags & 0x1f;
+	r.info->flags = flags & 0x1f;
 	r.info->ts_nsec = ts_nsec;
 	r.info->caller_id = caller_id;
 	if (dev_info)
 		memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
 
 	/* A message without a trailing newline can be continued. */
-	if (!(lflags & LOG_NEWLINE))
+	if (!(flags & LOG_NEWLINE))
 		prb_commit(&e);
 	else
 		prb_final_commit(&e);
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..71918d47ca95 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -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 */
+};
+
 /*
  * A descriptor: the complete meta-data for a record.
  *
-- 
2.31.1


^ permalink raw reply related	[flat|nested] 27+ messages in thread

* [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 12:00 [PATCH v6 0/4] printk: Userspace format indexing support Chris Down
  2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
  2021-05-18 12:00 ` [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags Chris Down
@ 2021-05-18 12:00 ` Chris Down
  2021-05-18 13:30   ` Andy Shevchenko
  2021-05-25 15:06   ` Petr Mladek
  2021-05-18 12:00 ` [PATCH v6 4/4] printk: index: Add indexing support to dev_printk Chris Down
  3 siblings, 2 replies; 27+ messages in thread
From: Chris Down @ 2021-05-18 12:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Petr Mladek, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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.

Signed-off-by: Chris Down <chris@chrisdown.name>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Jessica Yu <jeyu@kernel.org>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: John Ogness <john.ogness@linutronix.de>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Johannes Weiner <hannes@cmpxchg.org>
Cc: Kees Cook <keescook@chromium.org>
---
 MAINTAINERS                          |   5 +
 arch/arm/kernel/entry-v7m.S          |   2 +-
 arch/arm/lib/backtrace-clang.S       |   2 +-
 arch/arm/lib/backtrace.S             |   2 +-
 arch/arm/mach-rpc/io-acorn.S         |   2 +-
 arch/arm/vfp/vfphw.S                 |   6 +-
 arch/ia64/include/uapi/asm/cmpxchg.h |   4 +-
 arch/openrisc/kernel/entry.S         |   6 +-
 arch/powerpc/kernel/head_fsl_booke.S |   2 +-
 arch/um/include/shared/user.h        |   3 +-
 arch/x86/kernel/head_32.S            |   2 +-
 include/asm-generic/vmlinux.lds.h    |  13 ++
 include/linux/module.h               |   5 +
 include/linux/printk.h               |  95 ++++++++++++-
 init/Kconfig                         |  14 ++
 kernel/module.c                      |   5 +
 kernel/printk/Makefile               |   1 +
 kernel/printk/index.c                | 198 +++++++++++++++++++++++++++
 kernel/printk/internal.h             |   4 +
 kernel/printk/printk.c               |  21 +--
 20 files changed, 364 insertions(+), 28 deletions(-)
 create mode 100644 kernel/printk/index.c

diff --git a/MAINTAINERS b/MAINTAINERS
index c59e8d6a3862..cd3da42d3452 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -14765,6 +14765,11 @@ S:	Maintained
 F:	include/linux/printk.h
 F:	kernel/printk/
 
+PRINTK INDEXING
+R:	Chris Down <chris@chrisdown.name>
+S:	Maintained
+F:	kernel/printk/index.c
+
 PRISM54 WIRELESS DRIVER
 M:	Luis Chamberlain <mcgrof@kernel.org>
 L:	linux-wireless@vger.kernel.org
diff --git a/arch/arm/kernel/entry-v7m.S b/arch/arm/kernel/entry-v7m.S
index d0e898608d30..7bde93c10962 100644
--- a/arch/arm/kernel/entry-v7m.S
+++ b/arch/arm/kernel/entry-v7m.S
@@ -23,7 +23,7 @@ __invalid_entry:
 	adr	r0, strerr
 	mrs	r1, ipsr
 	mov	r2, lr
-	bl	printk
+	bl	_printk
 #endif
 	mov	r0, sp
 	bl	show_regs
diff --git a/arch/arm/lib/backtrace-clang.S b/arch/arm/lib/backtrace-clang.S
index 6174c45f53a5..5b2cdb1003e3 100644
--- a/arch/arm/lib/backtrace-clang.S
+++ b/arch/arm/lib/backtrace-clang.S
@@ -202,7 +202,7 @@ finished_setup:
 1006:		adr	r0, .Lbad
 		mov	r1, loglvl
 		mov	r2, frame
-		bl	printk
+		bl	_printk
 no_frame:	ldmfd	sp!, {r4 - r9, fp, pc}
 ENDPROC(c_backtrace)
 		.pushsection __ex_table,"a"
diff --git a/arch/arm/lib/backtrace.S b/arch/arm/lib/backtrace.S
index 872f658638d9..e8408f22d4dc 100644
--- a/arch/arm/lib/backtrace.S
+++ b/arch/arm/lib/backtrace.S
@@ -103,7 +103,7 @@ for_each_frame:	tst	frame, mask		@ Check for address exceptions
 1006:		adr	r0, .Lbad
 		mov	r1, loglvl
 		mov	r2, frame
-		bl	printk
+		bl	_printk
 no_frame:	ldmfd	sp!, {r4 - r9, pc}
 ENDPROC(c_backtrace)
 		
diff --git a/arch/arm/mach-rpc/io-acorn.S b/arch/arm/mach-rpc/io-acorn.S
index b9082a2a2a01..aa9bf0d771c0 100644
--- a/arch/arm/mach-rpc/io-acorn.S
+++ b/arch/arm/mach-rpc/io-acorn.S
@@ -25,4 +25,4 @@ ENTRY(insl)
 ENTRY(outsl)
 		adr	r0, .Liosl_warning
 		mov	r1, lr
-		b	printk
+		b	_printk
diff --git a/arch/arm/vfp/vfphw.S b/arch/arm/vfp/vfphw.S
index d5837bf05a9a..6f7926c9c179 100644
--- a/arch/arm/vfp/vfphw.S
+++ b/arch/arm/vfp/vfphw.S
@@ -23,7 +23,7 @@
 #ifdef DEBUG
 	stmfd	sp!, {r0-r3, ip, lr}
 	ldr	r0, =1f
-	bl	printk
+	bl	_printk
 	ldmfd	sp!, {r0-r3, ip, lr}
 
 	.pushsection .rodata, "a"
@@ -38,7 +38,7 @@
 	stmfd	sp!, {r0-r3, ip, lr}
 	mov	r1, \arg
 	ldr	r0, =1f
-	bl	printk
+	bl	_printk
 	ldmfd	sp!, {r0-r3, ip, lr}
 
 	.pushsection .rodata, "a"
@@ -55,7 +55,7 @@
 	mov	r2, \arg2
 	mov	r1, \arg1
 	ldr	r0, =1f
-	bl	printk
+	bl	_printk
 	ldmfd	sp!, {r0-r3, ip, lr}
 
 	.pushsection .rodata, "a"
diff --git a/arch/ia64/include/uapi/asm/cmpxchg.h b/arch/ia64/include/uapi/asm/cmpxchg.h
index 5d90307fd6e0..d96438322d13 100644
--- a/arch/ia64/include/uapi/asm/cmpxchg.h
+++ b/arch/ia64/include/uapi/asm/cmpxchg.h
@@ -139,9 +139,9 @@ extern long ia64_cmpxchg_called_with_bad_pointer(void);
 do {									\
 	if (_cmpxchg_bugcheck_count-- <= 0) {				\
 		void *ip;						\
-		extern int printk(const char *fmt, ...);		\
+		extern int _printk(const char *fmt, ...);		\
 		ip = (void *) ia64_getreg(_IA64_REG_IP);		\
-		printk("CMPXCHG_BUGCHECK: stuck at %p on word %p\n", ip, (v));\
+		_printk("CMPXCHG_BUGCHECK: stuck at %p on word %p\n", ip, (v));\
 		break;							\
 	}								\
 } while (0)
diff --git a/arch/openrisc/kernel/entry.S b/arch/openrisc/kernel/entry.S
index bc657e55c15f..947613f61d4a 100644
--- a/arch/openrisc/kernel/entry.S
+++ b/arch/openrisc/kernel/entry.S
@@ -551,7 +551,7 @@ EXCEPTION_ENTRY(_external_irq_handler)
 	l.movhi r3,hi(42f)
 	l.ori	r3,r3,lo(42f)
 	l.sw    0x0(r1),r3
-	l.jal   printk
+	l.jal   _printk
 	l.sw    0x4(r1),r4
 	l.addi  r1,r1,0x8
 
@@ -681,8 +681,8 @@ _syscall_debug:
 	l.sw    -4(r1),r27
 	l.sw    -8(r1),r11
 	l.addi  r1,r1,-8
-	l.movhi r27,hi(printk)
-	l.ori   r27,r27,lo(printk)
+	l.movhi r27,hi(_printk)
+	l.ori   r27,r27,lo(_printk)
 	l.jalr  r27
 	 l.nop
 	l.addi  r1,r1,8
diff --git a/arch/powerpc/kernel/head_fsl_booke.S b/arch/powerpc/kernel/head_fsl_booke.S
index a1a5c3f10dc4..08d7153ed04b 100644
--- a/arch/powerpc/kernel/head_fsl_booke.S
+++ b/arch/powerpc/kernel/head_fsl_booke.S
@@ -858,7 +858,7 @@ KernelSPE:
 	ori	r3,r3,87f@l
 	mr	r4,r2		/* current */
 	lwz	r5,_NIP(r1)
-	bl	printk
+	bl	_printk
 #endif
 	b	interrupt_return
 #ifdef CONFIG_PRINTK
diff --git a/arch/um/include/shared/user.h b/arch/um/include/shared/user.h
index e793e4212f0a..dd4badffdeb3 100644
--- a/arch/um/include/shared/user.h
+++ b/arch/um/include/shared/user.h
@@ -38,7 +38,8 @@ extern void panic(const char *fmt, ...)
 #define UM_KERN_CONT	KERN_CONT
 
 #ifdef UML_CONFIG_PRINTK
-extern int printk(const char *fmt, ...)
+#define printk(...) _printk(__VA_ARGS__)
+extern int _printk(const char *fmt, ...)
 	__attribute__ ((format (printf, 1, 2)));
 #else
 static inline int printk(const char *fmt, ...)
diff --git a/arch/x86/kernel/head_32.S b/arch/x86/kernel/head_32.S
index 67f590425d90..d8c64dab0efe 100644
--- a/arch/x86/kernel/head_32.S
+++ b/arch/x86/kernel/head_32.S
@@ -432,7 +432,7 @@ SYM_FUNC_START(early_ignore_irq)
 	pushl 32(%esp)
 	pushl 40(%esp)
 	pushl $int_msg
-	call printk
+	call _printk
 
 	call dump_stack
 
diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 40a9c101565e..ff5c684363da 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h
@@ -483,6 +483,8 @@
 									\
 	TRACEDATA							\
 									\
+	PRINTK_INDEX							\
+									\
 	/* Kernel symbol table: Normal symbols */			\
 	__ksymtab         : AT(ADDR(__ksymtab) - LOAD_OFFSET) {		\
 		__start___ksymtab = .;					\
@@ -893,6 +895,17 @@
 #define TRACEDATA
 #endif
 
+#ifdef CONFIG_PRINTK_INDEX
+#define PRINTK_INDEX							\
+	.printk_index : AT(ADDR(.printk_index) - LOAD_OFFSET) {		\
+		__start_printk_index = .;				\
+		*(.printk_index)					\
+		__stop_printk_index = .;				\
+	}
+#else
+#define PRINTK_INDEX
+#endif
+
 #define NOTES								\
 	.notes : AT(ADDR(.notes) - LOAD_OFFSET) {			\
 		__start_notes = .;					\
diff --git a/include/linux/module.h b/include/linux/module.h
index 8a298d820dbc..c9f1200b2312 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -511,6 +511,11 @@ struct module {
 	struct klp_modinfo *klp_info;
 #endif
 
+#ifdef CONFIG_PRINTK_INDEX
+	unsigned int printk_index_size;
+	struct pi_entry **printk_index_start;
+#endif
+
 #ifdef CONFIG_MODULE_UNLOAD
 	/* What modules depend on me? */
 	struct list_head source_list;
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
@@ -173,12 +173,12 @@ asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
 
 asmlinkage __printf(1, 2) __cold
-int printk(const char *fmt, ...);
+int _printk(const char *fmt, ...);
 
 /*
  * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ !
  */
-__printf(1, 2) __cold int printk_deferred(const char *fmt, ...);
+__printf(1, 2) __cold int _printk_deferred(const char *fmt, ...);
 
 /*
  * Please don't use printk_ratelimit(), because it shares ratelimiting state
@@ -217,12 +217,12 @@ int vprintk(const char *s, va_list args)
 	return 0;
 }
 static inline __printf(1, 2) __cold
-int printk(const char *s, ...)
+int _printk(const char *s, ...)
 {
 	return 0;
 }
 static inline __printf(1, 2) __cold
-int printk_deferred(const char *s, ...)
+int _printk_deferred(const char *s, ...)
 {
 	return 0;
 }
@@ -306,6 +306,93 @@ extern int kptr_restrict;
 #define pr_fmt(fmt) fmt
 #endif
 
+struct module;
+
+#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;
+} __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,			       \
+				.post_fmt = _post_fmt,			       \
+			};						       \
+			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).
+ */
+#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__);				       \
+	})
+
+
+#define printk(fmt, ...) printk_index_wrap(_printk, fmt, ##__VA_ARGS__)
+#define printk_deferred(fmt, ...)					       \
+	printk_index_wrap(_printk_deferred, fmt, ##__VA_ARGS__)
+
 /**
  * pr_emerg - Print an emergency-level message
  * @fmt: format string
diff --git a/init/Kconfig b/init/Kconfig
index 173a474012d7..f98283a851e4 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -781,6 +781,20 @@ config PRINTK_SAFE_LOG_BUF_SHIFT
 		     13 =>   8 KB for each CPU
 		     12 =>   4 KB for each CPU
 
+config PRINTK_INDEX
+	bool "Printk indexing debugfs interface"
+	depends on PRINTK && DEBUG_FS
+	help
+	  Add support for indexing of all printk formats known at compile time
+	  at <debugfs>/printk/index/<module>.
+
+	  This can be used as part of maintaining daemons which monitor
+	  /dev/kmsg, as it permits auditing the printk formats present in a
+	  kernel, allowing detection of cases where monitored printks are
+	  changed or no longer present.
+
+	  There is no additional runtime cost to printk with this enabled.
+
 #
 # Architectures with an unreliable sched_clock() should select this:
 #
diff --git a/kernel/module.c b/kernel/module.c
index decf4601e943..ca704c51f06f 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3349,6 +3349,11 @@ static int find_module_sections(struct module *mod, struct load_info *info)
 						sizeof(unsigned long),
 						&mod->num_kprobe_blacklist);
 #endif
+#ifdef CONFIG_PRINTK_INDEX
+	mod->printk_index_start = section_objs(info, ".printk_index",
+					       sizeof(*mod->printk_index_start),
+					       &mod->printk_index_size);
+#endif
 #ifdef CONFIG_HAVE_STATIC_CALL_INLINE
 	mod->static_call_sites = section_objs(info, ".static_call_sites",
 					      sizeof(*mod->static_call_sites),
diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index eee3dc9b60a9..d118739874c0 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -3,3 +3,4 @@ obj-y	= printk.o
 obj-$(CONFIG_PRINTK)	+= printk_safe.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
 obj-$(CONFIG_PRINTK)	+= printk_ringbuffer.o
+obj-$(CONFIG_PRINTK_INDEX)	+= index.o
diff --git a/kernel/printk/index.c b/kernel/printk/index.c
new file mode 100644
index 000000000000..5d729801e56a
--- /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);
+
+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 struct notifier_block module_printk_fmts_nb = {
+	.notifier_call = pi_module_notify,
+};
+
+static void __init pi_setup_module_notifier(void)
+{
+	register_module_notifier(&module_printk_fmts_nb);
+}
+#else
+static const char *pi_get_module_name(struct module *mod)
+{
+	return "vmlinux";
+}
+
+static void __init pi_setup_module_notifier(void)
+{
+}
+#endif
+
+static struct pi_entry *pi_get_entry(const struct module *mod, loff_t pos)
+{
+	struct pi_entry **entries;
+	unsigned int nr_entries;
+
+#ifdef CONFIG_MODULES
+	if (mod) {
+		entries = mod->printk_index_start;
+		nr_entries = mod->printk_index_size;
+	}
+#endif
+
+	if (!mod) {
+		/* vmlinux, comes from linker symbols */
+		entries = __start_printk_index;
+		nr_entries = __stop_printk_index - __start_printk_index;
+	}
+
+	if (pos >= nr_entries)
+		return NULL;
+
+	return entries[pos];
+}
+
+static void *pi_start(struct seq_file *s, loff_t *pos);
+
+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);
+}
+
+#define seq_escape_printf_format(s, src) \
+	seq_escape_str(s, src, ESCAPE_ANY | ESCAPE_NAP | ESCAPE_APPEND, "\"\\")
+
+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;
+
+	if (entry->level)
+		printk_parse_prefix(entry->level, &level, &flags);
+	else
+		prefix_len = printk_parse_prefix(entry->fmt, &level, &flags);
+
+	seq_printf(s, "<%d%s> %s:%d %s \"",
+			level, flags & LOG_CONT ? ",c" : "", 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;
+}
+
+static void pi_stop(struct seq_file *p, void *v)
+{
+}
+
+static const struct seq_operations dfs_index_seq_ops = {
+	.start = pi_start,
+	.next  = pi_next,
+	.show  = pi_show,
+	.stop  = pi_stop,
+};
+
+
+static int pi_open(struct inode *inode, struct file *file)
+{
+	return seq_open(file, &dfs_index_seq_ops);
+}
+
+static const struct file_operations dfs_index_fops = {
+	.open    = pi_open,
+	.read    = seq_read,
+	.llseek  = seq_lseek,
+	.release = seq_release
+};
+
+
+void pi_create_file(struct module *mod)
+{
+	debugfs_create_file(pi_get_module_name(mod), 0444, dfs_index,
+				       mod, &dfs_index_fops);
+}
+
+void pi_remove_file(struct module *mod)
+{
+	debugfs_remove(debugfs_lookup(pi_get_module_name(mod), dfs_index));
+}
+
+static int __init pi_init(void)
+{
+	struct dentry *dfs_root = debugfs_create_dir("printk", NULL);
+
+	dfs_index = debugfs_create_dir("index", dfs_root);
+	pi_setup_module_notifier();
+	pi_create_file(NULL);
+
+	return 0;
+}
+
+/* debugfs comes up on core and must be initialised first */
+postcore_initcall(pi_init);
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);
 #else
 
 /*
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 3201bb0c269c..085fb05c957a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1957,7 +1957,7 @@ static inline u32 printk_caller_id(void)
 }
 
 /**
- * parse_prefix - Parse level and control flags.
+ * printk_parse_prefix - Parse level and control flags.
  *
  * @text:     The terminated text message.
  * @level:    A pointer to the current level value, will be updated.
@@ -1973,7 +1973,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,
+u16 printk_parse_prefix(const char *text, int *level,
 			enum printk_info_flags *flags)
 {
 	u16 prefix_len = 0;
@@ -2019,7 +2019,7 @@ static u16 printk_sprint(char *text, u16 size, int facility,
 	if (facility == 0) {
 		u16 prefix_len;
 
-		prefix_len = parse_prefix(text, NULL, NULL);
+		prefix_len = printk_parse_prefix(text, NULL, NULL);
 		if (prefix_len) {
 			text_len -= prefix_len;
 			memmove(text, text + prefix_len, text_len);
@@ -2068,7 +2068,7 @@ int vprintk_store(int facility, int level,
 
 	/* Extract log level or control flags. */
 	if (facility == 0)
-		parse_prefix(&prefix_buf[0], &level, &flags);
+		printk_parse_prefix(&prefix_buf[0], &level, &flags);
 
 	if (level == LOGLEVEL_DEFAULT)
 		level = default_message_loglevel;
@@ -2185,10 +2185,13 @@ int vprintk_default(const char *fmt, va_list args)
 EXPORT_SYMBOL_GPL(vprintk_default);
 
 /**
- * printk - print a kernel message
+ * _printk - print a kernel message
  * @fmt: format string
  *
- * This is printk(). It can be called from any context. We want it to work.
+ * This is _printk(). It can be called from any context. We want it to work.
+ *
+ * If printk indexing is enabled, _printk() is called from printk_index_wrap.
+ * Otherwise, printk is simply #defined to _printk.
  *
  * We try to grab the console_lock. If we succeed, it's easy - we log the
  * output and call the console drivers.  If we fail to get the semaphore, we
@@ -2205,7 +2208,7 @@ EXPORT_SYMBOL_GPL(vprintk_default);
  *
  * See the vsnprintf() documentation for format string extensions over C99.
  */
-asmlinkage __visible int printk(const char *fmt, ...)
+asmlinkage __visible int _printk(const char *fmt, ...)
 {
 	va_list args;
 	int r;
@@ -2216,7 +2219,7 @@ asmlinkage __visible int printk(const char *fmt, ...)
 
 	return r;
 }
-EXPORT_SYMBOL(printk);
+EXPORT_SYMBOL(_printk);
 
 #else /* CONFIG_PRINTK */
 
@@ -3201,7 +3204,7 @@ int vprintk_deferred(const char *fmt, va_list args)
 	return r;
 }
 
-int printk_deferred(const char *fmt, ...)
+int _printk_deferred(const char *fmt, ...)
 {
 	va_list args;
 	int r;
-- 
2.31.1


^ permalink raw reply related	[flat|nested] 27+ messages in thread

* [PATCH v6 4/4] printk: index: Add indexing support to dev_printk
  2021-05-18 12:00 [PATCH v6 0/4] printk: Userspace format indexing support Chris Down
                   ` (2 preceding siblings ...)
  2021-05-18 12:00 ` [PATCH v6 3/4] printk: Userspace format indexing support Chris Down
@ 2021-05-18 12:00 ` Chris Down
  2021-05-26  8:57   ` Petr Mladek
  3 siblings, 1 reply; 27+ messages in thread
From: Chris Down @ 2021-05-18 12:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Petr Mladek, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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.

Signed-off-by: Chris Down <chris@chrisdown.name>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Rasmus Villemoes <linux@rasmusvillemoes.dk>
---
 drivers/base/core.c        |  6 ++--
 include/linux/dev_printk.h | 63 ++++++++++++++++++++++++++++----------
 2 files changed, 49 insertions(+), 20 deletions(-)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 60c5f5ea0268..78b8297e7f2b 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -4547,8 +4547,8 @@ static void __dev_printk(const char *level, const struct device *dev,
 		printk("%s(NULL device *): %pV", level, vaf);
 }
 
-void dev_printk(const char *level, const struct device *dev,
-		const char *fmt, ...)
+void _dev_printk(const char *level, const struct device *dev,
+		 const char *fmt, ...)
 {
 	struct va_format vaf;
 	va_list args;
@@ -4562,7 +4562,7 @@ void dev_printk(const char *level, const struct device *dev,
 
 	va_end(args);
 }
-EXPORT_SYMBOL(dev_printk);
+EXPORT_SYMBOL(_dev_printk);
 
 #define define_dev_printk_level(func, kern_level)		\
 void func(const struct device *dev, const char *fmt, ...)	\
diff --git a/include/linux/dev_printk.h b/include/linux/dev_printk.h
index 6f009559ee54..202c6a9ea7eb 100644
--- a/include/linux/dev_printk.h
+++ b/include/linux/dev_printk.h
@@ -38,8 +38,8 @@ __printf(3, 4) __cold
 int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...);
 
 __printf(3, 4) __cold
-void dev_printk(const char *level, const struct device *dev,
-		const char *fmt, ...);
+void _dev_printk(const char *level, const struct device *dev,
+		 const char *fmt, ...);
 __printf(2, 3) __cold
 void _dev_emerg(const struct device *dev, const char *fmt, ...);
 __printf(2, 3) __cold
@@ -69,7 +69,7 @@ static inline void __dev_printk(const char *level, const struct device *dev,
 				struct va_format *vaf)
 {}
 static inline __printf(3, 4)
-void dev_printk(const char *level, const struct device *dev,
+void _dev_printk(const char *level, const struct device *dev,
 		 const char *fmt, ...)
 {}
 
@@ -97,25 +97,54 @@ void _dev_info(const struct device *dev, const char *fmt, ...)
 
 #endif
 
+/*
+ * Some callsites directly call dev_printk rather than going through the
+ * dev_<level> infrastructure, so we need to emit here as well as inside those
+ * level-specific macros. Only one index entry will be produced, either way,
+ * since dev_printk's `fmt` isn't known at compile time if going through the
+ * dev_<level> macros.
+ */
+#define dev_printk(level, dev, fmt, ...) ({			\
+	dev_printk_index_emit(level, fmt);			\
+	_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));		\
+	_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_crit(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_CRIT, dev_fmt(fmt));			\
+	_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_alert(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_ALERT, dev_fmt(fmt));		\
+	_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_err(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_ERR, dev_fmt(fmt));			\
+	_dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_warn(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_WARNING, dev_fmt(fmt));		\
+	_dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_notice(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_NOTICE, dev_fmt(fmt));		\
+	_dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
+#define dev_info(dev, fmt, ...) ({					\
+	dev_printk_index_emit(KERN_INFO, dev_fmt(fmt));			\
+	_dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
+})
 
 #if defined(CONFIG_DYNAMIC_DEBUG) || \
 	(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))
-- 
2.31.1


^ permalink raw reply related	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special
  2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
@ 2021-05-18 13:10   ` Andy Shevchenko
  2021-05-18 14:10     ` Chris Down
  2021-05-25 10:17   ` Petr Mladek
  1 sibling, 1 reply; 27+ messages in thread
From: Andy Shevchenko @ 2021-05-18 13:10 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

On Tue, May 18, 2021 at 01:00:32PM +0100, Chris Down wrote:
> 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.

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 <andriy.shevchenko@linux.intel.com>

> Signed-off-by: Chris Down <chris@chrisdown.name>
> Cc: Andy Shevchenko <andriy.shevchenko@linux.intel.com>
> Cc: Rasmus Villemoes <linux@rasmusvillemoes.dk>
> ---
>  lib/string_helpers.c      |  4 ++++
>  lib/test-string_helpers.c | 14 +++++++-------
>  2 files changed, 11 insertions(+), 7 deletions(-)
> 
> diff --git a/lib/string_helpers.c b/lib/string_helpers.c
> index 5a35c7e16e96..3806a52ce697 100644
> --- a/lib/string_helpers.c
> +++ b/lib/string_helpers.c
> @@ -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
> diff --git a/lib/test-string_helpers.c b/lib/test-string_helpers.c
> index 2185d71704f0..437d8e6b7cb1 100644
> --- a/lib/test-string_helpers.c
> +++ b/lib/test-string_helpers.c
> @@ -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]",
> -- 
> 2.31.1
> 

-- 
With Best Regards,
Andy Shevchenko



^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 12:00 ` [PATCH v6 3/4] printk: Userspace format indexing support Chris Down
@ 2021-05-18 13:30   ` Andy Shevchenko
  2021-05-18 14:07     ` Chris Down
  2021-05-25 15:06   ` Petr Mladek
  1 sibling, 1 reply; 27+ messages in thread
From: Andy Shevchenko @ 2021-05-18 13:30 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

On Tue, May 18, 2021 at 01:00:43PM +0100, 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.
> 
> 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.

...

> +#define __printk_index_emit(_fmt, _level, _pre_fmt, _post_fmt)		       \

> +	({								       \

do {} while (0) is more generic than ({ GCC extension.


> +		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,			       \
> +				.post_fmt = _post_fmt,			       \
> +			};						       \
> +			static const struct pi_entry *_entry_ptr	       \
> +			__used __section(".printk_index") = &_entry;	       \
> +		}							       \

Something wrong with indentation of some of the \
Also in here and in the rest of the series.

> +	})

...

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

Keeping file name in the file is not the best idea.

> + */

...

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

> +}

...

> +	switch (op) {
> +	case MODULE_STATE_COMING:
> +		pi_create_file(mod);
> +		break;
> +	case MODULE_STATE_GOING:
> +		pi_remove_file(mod);
> +		break;

Missed default.

> +	}

...

> +static void __init pi_setup_module_notifier(void)
> +{
> +}

One line and marked inline?

...

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

Not sure I understand why forward declaration is here.
(I deliberately left more context below)

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

...

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

...

> +		seq_puts(s,
> +			 "# <level[,flags]> filename:line function \"format\"\n");

One line.

...

> +	if (entry->pre_fmt)
> +		seq_escape_printf_format(s, entry->pre_fmt);

> +	if (entry->post_fmt)
> +		seq_escape_printf_format(s, entry->post_fmt);

Maybe you can make seq_escape_printf_format() NULL-aware?

...

> +static void pi_stop(struct seq_file *p, void *v)
> +{
> +}

One line?

...

> +static const struct seq_operations dfs_index_seq_ops = {
> +	.start = pi_start,
> +	.next  = pi_next,
> +	.show  = pi_show,
> +	.stop  = pi_stop,
> +};
DEFINE_SEQ_SHOW_ATTRIBUTE(...);

...

> +
> +

One blank line is enough here and everywhere else.

...

> +static int __init pi_init(void)
> +{
> +	struct dentry *dfs_root = debugfs_create_dir("printk", NULL);
> +
> +	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)

...

> +u16 printk_parse_prefix(const char *text, int *level,
>  			enum printk_info_flags *flags)

Now one line?

-- 
With Best Regards,
Andy Shevchenko



^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 13:30   ` Andy Shevchenko
@ 2021-05-18 14:07     ` Chris Down
  2021-05-18 16:00       ` Andy Shevchenko
  0 siblings, 1 reply; 27+ messages in thread
From: Chris Down @ 2021-05-18 14:07 UTC (permalink / raw)
  To: Andy Shevchenko
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

Hey Andy,

Thanks for the detailed feedback! All points not explicitly replied to here are 
acked and will be improved. :-)

Andy Shevchenko writes:
>> +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?

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?

>> +#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":
> 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? :-)

>> +static int __init pi_init(void)
>> +{
>> +	struct dentry *dfs_root = debugfs_create_dir("printk", NULL);
>> +
>> +	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)

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?

Thanks a lot for the feedback! :-)

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special
  2021-05-18 13:10   ` Andy Shevchenko
@ 2021-05-18 14:10     ` Chris Down
  0 siblings, 0 replies; 27+ messages in thread
From: Chris Down @ 2021-05-18 14:10 UTC (permalink / raw)
  To: Andy Shevchenko
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

Andy Shevchenko writes:
>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 <andriy.shevchenko@linux.intel.com>

Thanks for reviewing! :-) I will triple check that and add for v7.

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 14:07     ` Chris Down
@ 2021-05-18 16:00       ` Andy Shevchenko
  2021-05-18 16:28         ` Chris Down
  2021-05-19  6:59         ` Rasmus Villemoes
  0 siblings, 2 replies; 27+ messages in thread
From: Andy Shevchenko @ 2021-05-18 16:00 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

On Tue, May 18, 2021 at 03:07:44PM +0100, Chris Down wrote:
> Andy Shevchenko writes:

...

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

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?

livepatch has to be fixed accordingly.

...

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

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

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

...

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

-- 
With Best Regards,
Andy Shevchenko



^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 16:00       ` Andy Shevchenko
@ 2021-05-18 16:28         ` Chris Down
  2021-05-18 16:59           ` Chris Down
  2021-05-19  6:59         ` Rasmus Villemoes
  1 sibling, 1 reply; 27+ messages in thread
From: Chris Down @ 2021-05-18 16:28 UTC (permalink / raw)
  To: Andy Shevchenko
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

Andy Shevchenko writes:
>> 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?

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.

>> > > +#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.
>
>Ah, makes sense. Yep, it's a bit complicated, but okay, perhaps it needs a
>comment near to the macro.

Sure thing, will do.

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

Hmm. Petr, what do you think? :-)

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 16:28         ` Chris Down
@ 2021-05-18 16:59           ` Chris Down
  0 siblings, 0 replies; 27+ messages in thread
From: Chris Down @ 2021-05-18 16:59 UTC (permalink / raw)
  To: Andy Shevchenko
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, Rasmus Villemoes, kernel-team

Chris Down writes:
>Andy Shevchenko writes:
>>>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?
>
>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.

Now I think about it, we even just call it that in struct module's is_vmlinux, 
and set that by doing `strcmp(modname, "vmlinux") == 0`, so it seems pretty 
static from a terminology point of view.

It would be nice to just always use `mod->name`, but unfortunately with 
!CONFIG_MODULES we don't have `struct module` fleshed out at all in order to do 
so.

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 16:00       ` Andy Shevchenko
  2021-05-18 16:28         ` Chris Down
@ 2021-05-19  6:59         ` Rasmus Villemoes
  2021-05-20  9:25           ` Andy Shevchenko
  1 sibling, 1 reply; 27+ messages in thread
From: Rasmus Villemoes @ 2021-05-19  6:59 UTC (permalink / raw)
  To: Andy Shevchenko, Chris Down
  Cc: linux-kernel, Petr Mladek, Jessica Yu, Sergey Senozhatsky,
	John Ogness, Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner,
	Kees Cook, kernel-team

On 18/05/2021 18.00, Andy Shevchenko wrote:
> On Tue, May 18, 2021 at 03:07:44PM +0100, Chris Down wrote:
>> Andy Shevchenko writes:
> 
> ...
> 
>>>> +	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?
> 
> 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.

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

>  2) finding bugs during boot cycle

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

>  3) (possibly) making better debugging in virtual environments

How?

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

Rasmus

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-19  6:59         ` Rasmus Villemoes
@ 2021-05-20  9:25           ` Andy Shevchenko
  2021-05-25 15:19             ` Petr Mladek
  0 siblings, 1 reply; 27+ messages in thread
From: Andy Shevchenko @ 2021-05-20  9:25 UTC (permalink / raw)
  To: Rasmus Villemoes
  Cc: Chris Down, linux-kernel, Petr Mladek, Jessica Yu,
	Sergey Senozhatsky, John Ogness, Steven Rostedt,
	Greg Kroah-Hartman, Johannes Weiner, Kees Cook, kernel-team

On Wed, May 19, 2021 at 08:59:06AM +0200, Rasmus Villemoes wrote:
> On 18/05/2021 18.00, Andy Shevchenko wrote:
> > On Tue, May 18, 2021 at 03:07:44PM +0100, Chris Down wrote:
> >> Andy Shevchenko writes:

...

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

What I'm talking about is two things:
 - is it guaranteed that the name is always the same?
 - is it guaranteed that nobody will make a mistake in the name when typing it
   over and over?

  ...

> >>>> +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?
> 
> >  2) finding bugs during boot cycle
> 
> What bugs would code that doesn't get executed find?
> 
> >  3) (possibly) making better debugging in virtual environments
> 
> How?
> 
> >  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.

> 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`)

-- 
With Best Regards,
Andy Shevchenko



^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special
  2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
  2021-05-18 13:10   ` Andy Shevchenko
@ 2021-05-25 10:17   ` Petr Mladek
  1 sibling, 0 replies; 27+ messages in thread
From: Petr Mladek @ 2021-05-25 10:17 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Tue 2021-05-18 13:00:32, Chris Down wrote:
> >From an abstract point of view, escape_special's counterpart,

The first line starts with '<'. I guess that it is a typo ;-)

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

Yup. Makes sense.

> Signed-off-by: Chris Down <chris@chrisdown.name>
> Cc: Andy Shevchenko <andriy.shevchenko@linux.intel.com>
> Cc: Rasmus Villemoes <linux@rasmusvillemoes.dk>

I agree with Andy that you should double check the existing users and
add a note that none is affected.

With it, feel free to add:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-18 12:00 ` [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags Chris Down
@ 2021-05-25 10:33   ` Petr Mladek
  2021-05-25 11:35     ` John Ogness
  0 siblings, 1 reply; 27+ messages in thread
From: Petr Mladek @ 2021-05-25 10:33 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Tue 2021-05-18 13:00:38, Chris Down wrote:
> 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 <chris@chrisdown.name>
> Cc: Petr Mladek <pmladek@suse.com>

Reviewed-by: Petr Mladek <pmladek@suse.com>

Just one nit below.

> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
> index 73cc80e01cef..71918d47ca95 100644
> --- a/kernel/printk/printk_ringbuffer.h
> +++ b/kernel/printk/printk_ringbuffer.h
> @@ -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?

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

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-25 10:33   ` Petr Mladek
@ 2021-05-25 11:35     ` John Ogness
  2021-05-26  7:31       ` Petr Mladek
  0 siblings, 1 reply; 27+ messages in thread
From: John Ogness @ 2021-05-25 11:35 UTC (permalink / raw)
  To: Petr Mladek, Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, Steven Rostedt,
	Greg Kroah-Hartman, Johannes Weiner, Kees Cook, Andy Shevchenko,
	Rasmus Villemoes, kernel-team

On 2021-05-25, Petr Mladek <pmladek@suse.com> wrote:
>> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
>> index 73cc80e01cef..71918d47ca95 100644
>> --- a/kernel/printk/printk_ringbuffer.h
>> +++ b/kernel/printk/printk_ringbuffer.h
>> @@ -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?

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

John Ogness

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-18 12:00 ` [PATCH v6 3/4] printk: Userspace format indexing support Chris Down
  2021-05-18 13:30   ` Andy Shevchenko
@ 2021-05-25 15:06   ` Petr Mladek
  2021-06-01 15:15     ` Chris Down
  1 sibling, 1 reply; 27+ messages in thread
From: Petr Mladek @ 2021-05-25 15:06 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

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

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-20  9:25           ` Andy Shevchenko
@ 2021-05-25 15:19             ` Petr Mladek
  0 siblings, 0 replies; 27+ messages in thread
From: Petr Mladek @ 2021-05-25 15:19 UTC (permalink / raw)
  To: Andy Shevchenko
  Cc: Rasmus Villemoes, Chris Down, linux-kernel, Jessica Yu,
	Sergey Senozhatsky, John Ogness, Steven Rostedt,
	Greg Kroah-Hartman, Johannes Weiner, Kees Cook, kernel-team

On Thu 2021-05-20 12:25:55, Andy Shevchenko wrote:
> On Wed, May 19, 2021 at 08:59:06AM +0200, Rasmus Villemoes wrote:
> > On 18/05/2021 18.00, Andy Shevchenko wrote:
> > > On Tue, May 18, 2021 at 03:07:44PM +0100, Chris Down wrote:
> > >>>> +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?
> > 
> > >  2) finding bugs during boot cycle
> > 
> > What bugs would code that doesn't get executed find?
> > 
> > >  3) (possibly) making better debugging in virtual environments
> > 
> > How?
> > 
> > >  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.
> 
> > 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`)

Most exit calls are in "um" arch code. AFAIK, it is a kernel that can be
booted in userspace. And it is very special.

Anyway, this functionality (printk index) do not need any special
handling during suspend, reboot, halt, or other system state
changes.

It only has to be initialized during boot at the right time.
It is after debugfs is initialized and before modules can be
loaded.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-25 11:35     ` John Ogness
@ 2021-05-26  7:31       ` Petr Mladek
  2021-05-26  8:39         ` John Ogness
  0 siblings, 1 reply; 27+ messages in thread
From: Petr Mladek @ 2021-05-26  7:31 UTC (permalink / raw)
  To: John Ogness
  Cc: Chris Down, linux-kernel, Jessica Yu, Sergey Senozhatsky,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Tue 2021-05-25 13:35:29, John Ogness wrote:
> On 2021-05-25, Petr Mladek <pmladek@suse.com> wrote:
> >> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
> >> index 73cc80e01cef..71918d47ca95 100644
> >> --- a/kernel/printk/printk_ringbuffer.h
> >> +++ b/kernel/printk/printk_ringbuffer.h
> >> @@ -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?
> 
> 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?

Anyway, I do not have strong opinion about it.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-26  7:31       ` Petr Mladek
@ 2021-05-26  8:39         ` John Ogness
  2021-05-26  9:25           ` Petr Mladek
  0 siblings, 1 reply; 27+ messages in thread
From: John Ogness @ 2021-05-26  8:39 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Chris Down, linux-kernel, Jessica Yu, Sergey Senozhatsky,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On 2021-05-26, Petr Mladek <pmladek@suse.com> wrote:
>> >> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
>> >> index 73cc80e01cef..71918d47ca95 100644
>> >> --- a/kernel/printk/printk_ringbuffer.h
>> >> +++ b/kernel/printk/printk_ringbuffer.h
>> >> @@ -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?
>> 
>> 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.

John Ogness

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 4/4] printk: index: Add indexing support to dev_printk
  2021-05-18 12:00 ` [PATCH v6 4/4] printk: index: Add indexing support to dev_printk Chris Down
@ 2021-05-26  8:57   ` Petr Mladek
  0 siblings, 0 replies; 27+ messages in thread
From: Petr Mladek @ 2021-05-26  8:57 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Tue 2021-05-18 13:00:48, Chris Down wrote:
> 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

Cool.

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

I prefer to use _dev_printk to disambiguate the macro and function
names. By other words, I prefer the approach used in this patch.

Please, remove the "If preferred..." sentence in the next version.

> diff --git a/include/linux/dev_printk.h b/include/linux/dev_printk.h
> index 6f009559ee54..202c6a9ea7eb 100644
> --- a/include/linux/dev_printk.h
> +++ b/include/linux/dev_printk.h
> @@ -97,25 +97,54 @@ void _dev_info(const struct device *dev, const char *fmt, ...)
>  
>  #endif
>  
> +/*
> + * Some callsites directly call dev_printk rather than going through the
> + * dev_<level> infrastructure, so we need to emit here as well as inside those
> + * level-specific macros. Only one index entry will be produced, either way,
> + * since dev_printk's `fmt` isn't known at compile time if going through the
> + * dev_<level> macros.
> + */
> +#define dev_printk(level, dev, fmt, ...) ({			\
> +	dev_printk_index_emit(level, fmt);			\

Please, define dev_printk_index_emit() macro before it is used
for the first time.

> +	_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));		\
> +	_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})
> +#define dev_crit(dev, fmt, ...) ({					\
> +	dev_printk_index_emit(KERN_CRIT, dev_fmt(fmt));			\
> +	_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})
> +#define dev_alert(dev, fmt, ...) ({					\
> +	dev_printk_index_emit(KERN_ALERT, dev_fmt(fmt));		\
> +	_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
> +})

I would slightly reduce the duplcation the follwing way:

#define dev_printk_index_wrap(_p_func, level, dev, fmt, ...)			\
	({								       \
		printk_index_subsys_emit("%s %s: ", "", level, dev_fmt(fmt));  \
		_p_func(dev, dev_fmt(fmt), ##__VA_ARGS__);			\
	})

#define dev_printk(level, dev, fmt, ...)				\
	dev_printk_index_wrap(_dev_printk, level, dev, ##__VA_ARGS__)

#define dev_crit(dev, fmt, ...)							\
	dev_printk_index_wrap(_dev_crit, KERN_CRIT, dev, ##__VA_ARGS__)
#define dev_alert(dev, fmt, ...)						\
	dev_printk_index_wrap(_dev_alert, KERN_ALERT, dev, ##__VA_ARGS__)


Note that I did not try to complile it, so there might be a mistake.


BTW: I was curious why we actually need _dev_crit() defined as a function.
But it seems to reduce size of the kernel binaries, see
the commit 38a1ec40efa196efbac0253 ("device.h drivers/base/core.c
Convert dev_<level> logging macros to functions"). Sigh.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-26  8:39         ` John Ogness
@ 2021-05-26  9:25           ` Petr Mladek
  2021-06-01 15:16             ` Chris Down
  0 siblings, 1 reply; 27+ messages in thread
From: Petr Mladek @ 2021-05-26  9:25 UTC (permalink / raw)
  To: John Ogness
  Cc: Chris Down, linux-kernel, Jessica Yu, Sergey Senozhatsky,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Wed 2021-05-26 10:39:18, John Ogness wrote:
> On 2021-05-26, Petr Mladek <pmladek@suse.com> wrote:
> >> >> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
> >> >> index 73cc80e01cef..71918d47ca95 100644
> >> >> --- a/kernel/printk/printk_ringbuffer.h
> >> >> +++ b/kernel/printk/printk_ringbuffer.h
> >> >> @@ -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?
> >> 
> >> 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

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-05-25 15:06   ` Petr Mladek
@ 2021-06-01 15:15     ` Chris Down
  2021-06-04 10:19       ` Petr Mladek
  0 siblings, 1 reply; 27+ messages in thread
From: Chris Down @ 2021-06-01 15:15 UTC (permalink / raw)
  To: Petr Mladek
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

Hey Petr,

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

Anything not explicitly replied to here is acked and will be fixed for v7.

Petr Mladek writes:
>Are you aware of any subsystem having some extra post_fmt, please?

Good thinking -- I just checked and I didn't find any, so I guess we can add 
that later if needed and do without it for now. :-)

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

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

In this case it's not super useful, but for cases where you can put something 
more useful (like "BTRFS: ...") it can make matching significantly less 
ambiguous.

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. :-)

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

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.

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

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?

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

I must confess, I'm not entirely sure why, although it's ironic/interesting 
that it happens on _the_ NULL-related deref printk...

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

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.

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

Ah yes, that's a decent point, since we don't treat this as meaning 
LOGLEVEL_DEFAULT. I'll have a think about how to make it better for v7.

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

That's great! I really appreciate your time and your diligent review, you've 
definitely helped improve this patchset for the better :-)

Thanks,

Chris

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags
  2021-05-26  9:25           ` Petr Mladek
@ 2021-06-01 15:16             ` Chris Down
  0 siblings, 0 replies; 27+ messages in thread
From: Chris Down @ 2021-06-01 15:16 UTC (permalink / raw)
  To: Petr Mladek
  Cc: John Ogness, linux-kernel, Jessica Yu, Sergey Senozhatsky,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

Petr Mladek writes:
>Fair enough. Chris, please move enum printk_info_flags declaration
>into kernel/printk/internal.h

Sure thing, will do for v7 once the points in the other patch are agreed on. 
Thanks! :-)

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-06-01 15:15     ` Chris Down
@ 2021-06-04 10:19       ` Petr Mladek
  2021-06-04 11:50         ` Chris Down
  0 siblings, 1 reply; 27+ messages in thread
From: Petr Mladek @ 2021-06-04 10:19 UTC (permalink / raw)
  To: Chris Down
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

On Tue 2021-06-01 16:15:50, Chris Down wrote:
> Hey Petr,
> 
> Thanks for the feedback -- apologies for the delay in getting back.

No problem at all.

> Petr Mladek writes:
> > 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;


> > 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. :-)

Fair enough.

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

I see.

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

I see. It was not obvious to me.


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

I actually see the above format in the index/vmlinux. So, I added some
debugging info ad the problem seems to be with

   [   94.840349] Err: Printk index entry without format defined
   [   94.841160]   arch/x86/mm/fault.c:435, is_errata93

The string is defined as:

static const char errata93_warning[] =
KERN_ERR 
"******* Your BIOS seems to not contain a fix for K8 errata #93\n"
"******* Working around it, but it may cause SEGVs or burn power.\n"
"******* Please consider a BIOS update.\n"
"******* Disabling USB legacy in the BIOS may also help.\n";

And it is used:
		printk_once(errata93_warning);

Strange. I do not understand what is so special about it. The string
is constant so it should not be the problem handled by the double
__builtin_constant_p.

Anyway, we should keep the check for entry->fmt == NULL to be
on the same side. And it is likely needed also in situations
that are handled by the double __builtin_constant_p.


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

I re-read the discussion about this,
namely https://lore.kernel.org/r/3Kf896Zt9O+/Yh@chrisdown.name

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

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

Fair enough.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 27+ messages in thread

* Re: [PATCH v6 3/4] printk: Userspace format indexing support
  2021-06-04 10:19       ` Petr Mladek
@ 2021-06-04 11:50         ` Chris Down
  0 siblings, 0 replies; 27+ messages in thread
From: Chris Down @ 2021-06-04 11:50 UTC (permalink / raw)
  To: Petr Mladek
  Cc: linux-kernel, Jessica Yu, Sergey Senozhatsky, John Ogness,
	Steven Rostedt, Greg Kroah-Hartman, Johannes Weiner, Kees Cook,
	Andy Shevchenko, Rasmus Villemoes, kernel-team

Petr Mladek writes:
>> Petr Mladek writes:
>> > 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;

Sounds totally reasonable, will do.

>> > 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.
>
>I re-read the discussion about this,
>namely https://lore.kernel.org/r/3Kf896Zt9O+/Yh@chrisdown.name
>
>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.
> */

Oh yes, that does sound more clear. I'll update it :-)

Thanks!

^ permalink raw reply	[flat|nested] 27+ messages in thread

end of thread, other threads:[~2021-06-04 11:51 UTC | newest]

Thread overview: 27+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-05-18 12:00 [PATCH v6 0/4] printk: Userspace format indexing support Chris Down
2021-05-18 12:00 ` [PATCH v6 1/4] string_helpers: Escape double quotes in escape_special Chris Down
2021-05-18 13:10   ` Andy Shevchenko
2021-05-18 14:10     ` Chris Down
2021-05-25 10:17   ` Petr Mladek
2021-05-18 12:00 ` [PATCH v6 2/4] printk: Straighten out log_flags into printk_info_flags Chris Down
2021-05-25 10:33   ` Petr Mladek
2021-05-25 11:35     ` John Ogness
2021-05-26  7:31       ` Petr Mladek
2021-05-26  8:39         ` John Ogness
2021-05-26  9:25           ` Petr Mladek
2021-06-01 15:16             ` Chris Down
2021-05-18 12:00 ` [PATCH v6 3/4] printk: Userspace format indexing support Chris Down
2021-05-18 13:30   ` Andy Shevchenko
2021-05-18 14:07     ` Chris Down
2021-05-18 16:00       ` Andy Shevchenko
2021-05-18 16:28         ` Chris Down
2021-05-18 16:59           ` Chris Down
2021-05-19  6:59         ` Rasmus Villemoes
2021-05-20  9:25           ` Andy Shevchenko
2021-05-25 15:19             ` Petr Mladek
2021-05-25 15:06   ` Petr Mladek
2021-06-01 15:15     ` Chris Down
2021-06-04 10:19       ` Petr Mladek
2021-06-04 11:50         ` Chris Down
2021-05-18 12:00 ` [PATCH v6 4/4] printk: index: Add indexing support to dev_printk Chris Down
2021-05-26  8:57   ` Petr Mladek

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.