Re: [PATCH] printk: Userspace format enumeration support

Hi,

I would like to hear opinion from a bigger audience. It is an
userspace interface that we might need to maintain forewer.
Adding few more people in to CC:

Steven Rostedt [off-list ref]: printk co-maintainer
Alexey Dobriyan [off-list ref]: fs/proc maintainer
Greg Kroah-Hartman [off-list ref]: sysfs maintainer
Jason Baron [off-list ref]: dynamic_debug maintainer
Kees Cook [off-list ref]: security POV
linux-api@vger.kernel.org: Linux API mailing list

Of course, we should also ask if this is the right approach
for the think that you want to achieve.

The motivation for this patch is that the strings printed by kernels
are not reliable and you want a simple way to compare differences
bethween versions. Do I get it right?

See more comments below.



On Thu 2021-02-04 15:37:52, 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 you'd 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.

Another is that printk() is not reliable on its own. Messages might
get lost. The size of the log buffer is limited. Deamon reading
/dev/kmsg need not be scheduled in time or often enough. Console
might be slow. The messages are filtered on the console by console_loglevel.

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 some rare hardware bug which you want 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 patch provides a solution to the issue of silently changed or
deleted printks: we record pointers to all printk format strings known
at compile time into a new .printk_fmts section, both in vmlinux and
modules. At runtime, this can then be iterated by looking at
/proc/printk_formats, which emits the same format as `printk` itself,
which we already export elsewhere (for example, in netconsole):

    # Format: <module>,<facility><level><format>\0
    $ perl -p -e 's/\n/\\n/g;s/\0/\n/g' /proc/printk_formats | shuf -n 5
    vmlinux,6Disabling APIC timer\n
    intel_rapl_common,3intel_rapl_common: Cannot find matching power limit for constraint %d\n
    dm_crypt,3device-mapper: crypt: %s: INTEGRITY AEAD ERROR, sector %llu\n
    mac80211,6%s: AP bug: HT capability missing from AssocResp\n
    vmlinux,3zpool: couldn't create zpool - out of memory\n

The facility and log level are not well separated from the format string.

Also this is yet another style how the format is displayed. We already have

	+ console/syslog: formated by record_print_text()
	+ /dev/kmsg: formatted by info_print_ext_header(),  msg_print_ext_body().
	+ /sys/kernel/debug/dynamic_debug/control
	+ /sys/kernel/debug/tracing/printk_formats

We should get some inspiration from the existing interfaces.

But we first should decide what information might be useful:

   + 'facility' should not be needed. All messages should be from
      kernel.

   + <module> is already optinaly added by pr_fmt() to the printed strings
     as:  pr_fmt(): ...

   + dynamic_debug seems to print KBUILD_MODNAME even when the module
     is built in.

   + dynamic debug also prints <source_file:line>

It should be defined after #define TRACEDATA to follow the existing
style.

But honestly I am not much familiar with the sections definitions.
I am curious why TRACE_PRINTKS() and __dyndbg are defined
a bit different way.

You probably should get inspiration from t_show() in trace_printk.c.
It handles newlines, ...

Or by ddebug_proc_show(). It uses seq_escape().

Anyway, there is something wrong at the moment. The output looks fine
with cat. But "less" says that it is a binary format and the output
is a bit messy:

$> less /proc/printk_formats 
"/proc/printk_formats" may be a binary file.  See it anyway? 
vmlinux,^A3Warning: unable to open an initial console.
^@vmlinux,^A3Failed to execute %s (error %d)
^@vmlinux,^A6Kernel memory protection disabled.
^@vmlinux,^A3Starting init: %s exists but couldn't execute it (error %d)


That is for now. I still have to think about it. And I am also curious
about what others thing about this idea.

Best Regards,
Petr

On Fri, 5 Feb 2021 17:42:55 +0100
Petr Mladek [off-list ref] wrote:

Hi,

I would like to hear opinion from a bigger audience. It is an
userspace interface that we might need to maintain forewer.
Adding few more people in to CC:

Steven Rostedt [off-list ref]: printk co-maintainer

Thanks for Cc'ing me.

Alexey Dobriyan [off-list ref]: fs/proc maintainer
Greg Kroah-Hartman [off-list ref]: sysfs maintainer
Jason Baron [off-list ref]: dynamic_debug maintainer
Kees Cook [off-list ref]: security POV
linux-api@vger.kernel.org: Linux API mailing list

Of course, we should also ask if this is the right approach
for the think that you want to achieve.

The motivation for this patch is that the strings printed by kernels
are not reliable and you want a simple way to compare differences
bethween versions. Do I get it right?

See more comments below.

Also this is yet another style how the format is displayed. We already have

	+ console/syslog: formated by record_print_text()
	+ /dev/kmsg: formatted by info_print_ext_header(),  msg_print_ext_body().
	+ /sys/kernel/debug/dynamic_debug/control

	+ /sys/kernel/debug/tracing/printk_formats

We should get some inspiration from the existing interfaces.

Interesting, because when I was looking at the original patch (looked at
the lore link before reading your reply), I thought to myself "this looks
exactly like what I did for trace_printk formats", which the above file is
where it is shown. I'm curious if this work was inspired by that?

quoted

diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h
index 34b7e0d2346c..0ca6e28e05d6 100644
--- a/include/asm-generic/vmlinux.lds.h
+++ b/include/asm-generic/vmlinux.lds.h

@@ -309,6 +309,17 @@
 #define ACPI_PROBE_TABLE(name)
 #endif
 
+#ifdef CONFIG_PRINTK_ENUMERATION
+#define PRINTK_FMTS							\
+	.printk_fmts : AT(ADDR(.printk_fmts) - LOAD_OFFSET) {		\
+		__start_printk_fmts = .;				\
+		*(.printk_fmts)						\
+		__stop_printk_fmts = .;					\
+	}
+#else
+#define PRINTK_FMTS
+#endif  

It should be defined after #define TRACEDATA to follow the existing
style.

But honestly I am not much familiar with the sections definitions.
I am curious why TRACE_PRINTKS() and __dyndbg are defined
a bit different way.

I'm not sure what difference you mean.

quoted

+static int proc_pf_show(struct seq_file *s, void *v)
+{
+	const struct printk_fmt_sec *ps = NULL;
+	const char **fptr = NULL;
+
+	mutex_lock(&printk_fmts_mutex);
+
+	list_for_each_entry(ps, &printk_fmts_list, list) {
+		const char *mod_name = ps_get_module_name(ps);
+
+		for (fptr = ps->start; fptr < ps->end; fptr++) {
+			seq_puts(s, mod_name);
+			seq_putc(s, ',');
+			seq_puts(s, *fptr);
+			seq_putc(s, '\0');
+		}  

You probably should get inspiration from t_show() in trace_printk.c.
It handles newlines, ...

Or by ddebug_proc_show(). It uses seq_escape().

Anyway, there is something wrong at the moment. The output looks fine
with cat. But "less" says that it is a binary format and the output
is a bit messy:

Hmm, that's usually the case when lseek gets messed up. Not sure how that
happened.

$> less /proc/printk_formats   
"/proc/printk_formats" may be a binary file.  See it anyway? 
vmlinux,^A3Warning: unable to open an initial console.
^@vmlinux,^A3Failed to execute %s (error %d)
^@vmlinux,^A6Kernel memory protection disabled.
^@vmlinux,^A3Starting init: %s exists but couldn't execute it (error %d)


That is for now. I still have to think about it. And I am also curious
about what others thing about this idea.

I'm not against the idea. I don't think it belongs in /proc. Perhaps
debugfs is a better place to put it.

-- Steve

Hi Steven,

Steven Rostedt writes:

Interesting, because when I was looking at the original patch (looked at
the lore link before reading your reply), I thought to myself "this looks
exactly like what I did for trace_printk formats", which the above file is
where it is shown. I'm curious if this work was inspired by that?

The double __builtin_constant_p() trick was suggested by Johannes based on 
prior art in trace_puts() just prior to patch submission. Other than that, it 
seems we came up with basically the same solution independently. :-)

quoted

Anyway, there is something wrong at the moment. The output looks fine
with cat. But "less" says that it is a binary format and the output
is a bit messy:

Hmm, that's usually the case when lseek gets messed up. Not sure how that
happened.

It looks as intended to me -- none of the newlines, nulls, or other control 
sequences are escaped currently, since I didn't immediately see a reason to do 
that. If that's a blocker though, I'm happy to change it.

quoted

$> less /proc/printk_formats
"/proc/printk_formats" may be a binary file.  See it anyway?
vmlinux,^A3Warning: unable to open an initial console.
^@vmlinux,^A3Failed to execute %s (error %d)
^@vmlinux,^A6Kernel memory protection disabled.
^@vmlinux,^A3Starting init: %s exists but couldn't execute it (error %d)


That is for now. I still have to think about it. And I am also curious
about what others thing about this idea.

I'm not against the idea. I don't think it belongs in /proc. Perhaps
debugfs is a better place to put it.

Any location is fine with me, as long as it gets to userspace. How does 
<debugfs>/printk/formats or <debugfs>/printk/formats/<module> sound to you?

Thanks,

Chris

Hi Petr,

Thanks for looking over the patch. :-)

Petr Mladek writes:

quoted

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 you'd 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.

Another is that printk() is not reliable on its own. Messages might
get lost. The size of the log buffer is limited. Deamon reading
/dev/kmsg need not be scheduled in time or often enough. Console
might be slow. The messages are filtered on the console by console_loglevel.

This is of course true. We don't use kmsg as the last line of defence for 
monitoring or remediation, of course, but it would be unwise to not have 
infrastructure capable of monitoring it. We often need to act quickly when 
production incidents happen, and often kmsg is the place where those 
"unexpected" issues are surfaced. It's often much more likely that there is 
some kmsg log which we can act on in those scenarios than anything else, and 
even if it's not ideal, in reality, it's typically reliable enough to at least 
mitigate the problem when dealing with a large fleet of machines :-)

quoted

    # Format: <module>,<facility><level><format>\0
    $ perl -p -e 's/\n/\\n/g;s/\0/\n/g' /proc/printk_formats | shuf -n 5
    vmlinux,6Disabling APIC timer\n
    intel_rapl_common,3intel_rapl_common: Cannot find matching power limit for constraint %d\n
    dm_crypt,3device-mapper: crypt: %s: INTEGRITY AEAD ERROR, sector %llu\n
    mac80211,6%s: AP bug: HT capability missing from AssocResp\n
    vmlinux,3zpool: couldn't create zpool - out of memory\n

The facility and log level are not well separated from the format string.

Also this is yet another style how the format is displayed. We already have

+ console/syslog: formated by record_print_text()
+ /dev/kmsg: formatted by info_print_ext_header(),  msg_print_ext_body().
+ /sys/kernel/debug/dynamic_debug/control
+ /sys/kernel/debug/tracing/printk_formats

We should get some inspiration from the existing interfaces.

Sure, I'm not super bound to the format, as long as we have something that can 
aid those maintaining these systems which monitor printk in identifying that a 
format was mutated or removed. The module is more or less optional -- it's just 
intended as a hint about where to look.

But we first should decide what information might be useful:

  + 'facility' should not be needed. All messages should be from
     kernel.

That's fair enough, it can be omitted. I just didn't want to stray too far from 
the netconsole format, since we already mostly have it in this format there.

My intention is to _not_ deviate from existing interfaces, really, so I'll be 
happy with any suggested format that will achieve this patch's stated goals, 
since this kind of data is sorely needed :-)

  + <module> is already optinaly added by pr_fmt() to the printed strings
    as:  pr_fmt(): ...

pr_fmts are not consistently used across the kernel, and sometimes differ from 
the module itself. Many modules don't use it at all, and we also don't have it 
for pr_cont. Just picking some random examples:

     % grep -av vmlinux /proc/printk_formats | shuf -n 10
     mac80211,6%s: mesh STA %pM switches to channel requiring DFS (%d MHz, width:%d, CF1/2: %d/%d MHz), aborting
     thinkpad_acpi,c N/Athinkpad_acpi,c %dthinkpad_acpi,5thinkpad_acpi: temperatures (Celsius):thinkpad_acpi,3thinkpad_acpi: Out of memory for LED data
     i915,6drm/i915 developers can then reassign to the right component if it's not a kernel issue.
     video,4[Firmware Bug]: _BCQ is used instead of _BQC
     i915,3gvt: requesting SMI service
     are MMIO SPTEs.
     i915,3gvt: invalid tiling mode: %x
     video,3ACPI: Create sysfs link
     cec,6cec-%s: duplicate logical address type
     soundwire_bus,3%s: %s: inconsistent state state %d

quoted

+static int proc_pf_show(struct seq_file *s, void *v)
+{
+	const struct printk_fmt_sec *ps = NULL;
+	const char **fptr = NULL;
+
+	mutex_lock(&printk_fmts_mutex);
+
+	list_for_each_entry(ps, &printk_fmts_list, list) {
+		const char *mod_name = ps_get_module_name(ps);
+
+		for (fptr = ps->start; fptr < ps->end; fptr++) {
+			seq_puts(s, mod_name);
+			seq_putc(s, ',');
+			seq_puts(s, *fptr);
+			seq_putc(s, '\0');
+		}

You probably should get inspiration from t_show() in trace_printk.c.
It handles newlines, ...

Or by ddebug_proc_show(). It uses seq_escape().

Anyway, there is something wrong at the moment. The output looks fine
with cat. But "less" says that it is a binary format and the output
is a bit messy:

Hmm, why should that be a problem? It's intentional that this pretty much just 
directly replicates the format string passed to printk, since it's easy to 
write a parser for it:

1. Go up to the comma, take the module
2. Take the facility and level
3. Take the rest up to a \0 as the format
4. Go to 1

I don't mind to have it escaped, but I'm not immediately seeing the benefit. We 
also don't escape `\0` in (for example) `/proc/pid/cmdline`, since it serves as 
a good natural delimiter.

Thanks for taking the time to review :-)

Chris

On Fri, 5 Feb 2021 22:45:19 +0000
Chris Down [off-list ref] wrote:

quoted

I'm not against the idea. I don't think it belongs in /proc. Perhaps
debugfs is a better place to put it.  

Any location is fine with me, as long as it gets to userspace. How does 
<debugfs>/printk/formats or <debugfs>/printk/formats/<module> sound to you?

I'm fine with it, if others are.

Something like this will probably need approval from others on the Cc list
here.

-- Steve

On Fri, Feb 05, 2021 at 10:45:19PM +0000, Chris Down wrote:

Hi Steven,

Steven Rostedt writes:

quoted

Interesting, because when I was looking at the original patch (looked at
the lore link before reading your reply), I thought to myself "this looks
exactly like what I did for trace_printk formats", which the above file is
where it is shown. I'm curious if this work was inspired by that?

The double __builtin_constant_p() trick was suggested by Johannes based on
prior art in trace_puts() just prior to patch submission. Other than that,
it seems we came up with basically the same solution independently. :-)

quoted

quoted

Anyway, there is something wrong at the moment. The output looks fine
with cat. But "less" says that it is a binary format and the output
is a bit messy:

Hmm, that's usually the case when lseek gets messed up. Not sure how that
happened.

It looks as intended to me -- none of the newlines, nulls, or other control
sequences are escaped currently, since I didn't immediately see a reason to
do that. If that's a blocker though, I'm happy to change it.

quoted

quoted

$> less /proc/printk_formats
"/proc/printk_formats" may be a binary file.  See it anyway?
vmlinux,^A3Warning: unable to open an initial console.
^@vmlinux,^A3Failed to execute %s (error %d)
^@vmlinux,^A6Kernel memory protection disabled.
^@vmlinux,^A3Starting init: %s exists but couldn't execute it (error %d)


That is for now. I still have to think about it. And I am also curious
about what others thing about this idea.

I'm not against the idea. I don't think it belongs in /proc. Perhaps
debugfs is a better place to put it.

Any location is fine with me, as long as it gets to userspace. How does
<debugfs>/printk/formats or <debugfs>/printk/formats/<module> sound to you?

That's fine with me, but I'd like to see the patch with this in it first
before approving it :)

thanks,

greg k-h

Greg Kroah-Hartman writes:

quoted

quoted

I'm not against the idea. I don't think it belongs in /proc. Perhaps
debugfs is a better place to put it.

Any location is fine with me, as long as it gets to userspace. How does
<debugfs>/printk/formats or <debugfs>/printk/formats/<module> sound to you?

That's fine with me, but I'd like to see the patch with this in it first
before approving it :)

Thanks! I'll send v2 soon then with the aforementioned changes, and a move to 
debugfs.

On Fri, 2021-02-05 at 22:25 +0000, Chris Down wrote:

Petr Mladek writes:

quoted

  + <module> is already optinaly added by pr_fmt() to the printed strings
    as:  pr_fmt(): ...

pr_fmts are not consistently used across the kernel, and sometimes differ from 
the module itself. Many modules don't use it at all, and we also don't have it 
for pr_cont. Just picking some random examples:

     % grep -av vmlinux /proc/printk_formats | shuf -n 10
     mac80211,6%s: mesh STA %pM switches to channel requiring DFS (%d MHz, width:%d, CF1/2: %d/%d MHz), aborting
     thinkpad_acpi,c N/Athinkpad_acpi,c %dthinkpad_acpi,5thinkpad_acpi: temperatures (Celsius):thinkpad_acpi,3thinkpad_acpi: Out of memory for LED data

I don't understand this format.

"Out of memory for LED data" is a single printk ending with a '\n' newline 
I expected this to be broken up into multiple lines, one for each printk
that endsd in a newline.

And what would happen if the function was refactored removing the pr_cont
uses like the below: (basically, any output that uses a mechanism that
aggregates a buffer then emits it, and there are a _lot_ of those)

	printk("%s\n", buffer);

And there is already a relatively trivial way to do this using a modified
version of strings that looks for KERN_SOH[0-6], and if dynamic_debug is
enabled, look in the dynamic_debug section, either __verbose or __dyndbg
depending on the kernel version.

---
 drivers/platform/x86/thinkpad_acpi.c | 15 ++++++++++-----
 1 file changed, 10 insertions(+), 5 deletions(-)

diff --git a/drivers/platform/x86/thinkpad_acpi.c b/drivers/platform/x86/thinkpad_acpi.c
index 18b390153e7f..ff1c09c600f8 100644
--- a/drivers/platform/x86/thinkpad_acpi.c
+++ b/drivers/platform/x86/thinkpad_acpi.c

@@ -6353,21 +6353,26 @@ static void thermal_dump_all_sensors(void)
 {
 	int n, i;
 	struct ibm_thermal_sensors_struct t;
+	char output[256];
+	int len = 0;
 
 	n = thermal_get_sensors(&t);
 	if (n <= 0)
 		return;
 
-	pr_notice("temperatures (Celsius):");
+	len += scnprintf(output + len, sizeof(output) - len,
+		       "temperatures (Celsius):");
 
 	for (i = 0; i < n; i++) {
-		if (t.temp[i] != TPACPI_THERMAL_SENSOR_NA)
-			pr_cont(" %d", (int)(t.temp[i] / 1000));
+		if (t.temp[i] == TPACPI_THERMAL_SENSOR_NA)
+			len += scnprintf(output + len, sizeof(output) - len,
+					 " N/A");
 		else
-			pr_cont(" N/A");
+			len += scnprintf(output + len, sizeof(output) - len,
+					 " %d", t.temp[i] / 1000);
 	}
 
-	pr_cont("\n");
+	pr_notice("%s\n", output);
 }
 
 /* sysfs temp##_input -------------------------------------------------- */

Joe Perches writes:

On Fri, 2021-02-05 at 22:25 +0000, Chris Down wrote:

quoted

Petr Mladek writes:

quoted

  + <module> is already optinaly added by pr_fmt() to the printed strings
    as:  pr_fmt(): ...

pr_fmts are not consistently used across the kernel, and sometimes differ from
the module itself. Many modules don't use it at all, and we also don't have it
for pr_cont. Just picking some random examples:

     % grep -av vmlinux /proc/printk_formats | shuf -n 10
     mac80211,6%s: mesh STA %pM switches to channel requiring DFS (%d MHz, width:%d, CF1/2: %d/%d MHz), aborting
     thinkpad_acpi,c N/Athinkpad_acpi,c %dthinkpad_acpi,5thinkpad_acpi: temperatures (Celsius):thinkpad_acpi,3thinkpad_acpi: Out of memory for LED data

I don't understand this format.

"Out of memory for LED data" is a single printk ending with a '\n' newline
I expected this to be broken up into multiple lines, one for each printk
that endsd in a newline.

Hmm, that's just a manifestation of directly using `shuf` without doing the 
transformation of trailing nulls to newlines shown in the changelog. They are 
still distinct and separated by nulls.

And what would happen if the function was refactored removing the pr_cont
uses like the below: (basically, any output that uses a mechanism that
aggregates a buffer then emits it, and there are a _lot_ of those)

printk("%s\n", buffer);

There are certainly printks which can't be trivially monitored using the printk 
format alone, but the vast majority of the ones that are monitored _do_ have 
meaningful formats and can be monitored over time. No solution to this is going 
to catch every single case, especially when so much of the information can be 
generated dyamically, but this patchset still goes a long way to making printk 
monitoring more tractable for use cases like the one described in the 
changelog.

On Sat, 2021-02-06 at 21:21 +0000, Chris Down wrote:

Joe Perches writes:

quoted

On Fri, 2021-02-05 at 22:25 +0000, Chris Down wrote:

quoted

Petr Mladek writes:

quoted

  + <module> is already optinaly added by pr_fmt() to the printed strings
    as:  pr_fmt(): ...

pr_fmts are not consistently used across the kernel, and sometimes differ from
the module itself. Many modules don't use it at all, and we also don't have it
for pr_cont. Just picking some random examples:

     % grep -av vmlinux /proc/printk_formats | shuf -n 10
     mac80211,6%s: mesh STA %pM switches to channel requiring DFS (%d MHz, width:%d, CF1/2: %d/%d MHz), aborting
     thinkpad_acpi,c N/Athinkpad_acpi,c %dthinkpad_acpi,5thinkpad_acpi: temperatures (Celsius):thinkpad_acpi,3thinkpad_acpi: Out of memory for LED data

I don't understand this format.

"Out of memory for LED data" is a single printk ending with a '\n' newline
I expected this to be broken up into multiple lines, one for each printk
that endsd in a newline.

Hmm, that's just a manifestation of directly using `shuf` without doing the 
transformation of trailing nulls to newlines shown in the changelog. They are 
still distinct and separated by nulls.

quoted

And what would happen if the function was refactored removing the pr_cont
uses like the below: (basically, any output that uses a mechanism that
aggregates a buffer then emits it, and there are a _lot_ of those)

	printk("%s\n", buffer);

There are certainly printks which can't be trivially monitored using the printk 
format alone, but the vast majority of the ones that are monitored _do_ have 
meaningful formats and can be monitored over time. No solution to this is going 
to catch every single case, especially when so much of the information can be 
generated dyamically, but this patchset still goes a long way to making printk 
monitoring more tractable for use cases like the one described in the 
changelog.

For the _vast_ majority of printk strings, this can easily be found
and compared using a trivial modification to strings.

Module specific formats are stored in the .ko files and could be
examined separately.

Here's the possible patch to strings:

---
 binutils/strings.c | 98 +++++++++++++++++++++++++++++++++++++++++++++---------
 1 file changed, 82 insertions(+), 16 deletions(-)

diff --git a/binutils/strings.c b/binutils/strings.c
index 3444fbc7222..d4abeb0cdbb 100644
--- a/binutils/strings.c
+++ b/binutils/strings.c

@@ -26,6 +26,10 @@
    --data
    -d		Scan only the initialized data section(s) of object files.
 
+   --section=<section>
+   -S <section> Scan only the specific section(s)
+   --kernel
+   -k		Scan only linux-kernel KERN_SOH strings
    --print-file-name
    -f		Print the name of the file before each string.
 

@@ -108,6 +112,14 @@ static bfd_boolean print_filenames;
 /* TRUE means for object files scan only the data section.  */
 static bfd_boolean datasection_only;
 
+/* TRUE means for object files scan only the specified sections.  */
+static bfd_boolean specified_sections_only;
+static int specified_sections_count;
+static char **specified_sections;
+
+/* TRUE means scan only linux-kernel printk strings with KERN_SOH.  */
+static bfd_boolean linux_kernel_soh;
+
 /* The BFD object file format.  */
 static char *target;
 

@@ -122,6 +134,8 @@ static struct option long_options[] =
 {
   {"all", no_argument, NULL, 'a'},
   {"data", no_argument, NULL, 'd'},
+  {"section", required_argument, NULL, 'S'},
+  {"kernel", no_argument, NULL, 'k'},
   {"print-file-name", no_argument, NULL, 'f'},
   {"bytes", required_argument, NULL, 'n'},
   {"radix", required_argument, NULL, 't'},

@@ -173,7 +187,7 @@ main (int argc, char **argv)
   encoding = 's';
   output_separator = NULL;
 
-  while ((optc = getopt_long (argc, argv, "adfhHn:wot:e:T:s:Vv0123456789",
+  while ((optc = getopt_long (argc, argv, "adS:s:kfhHn:wot:e:T:s:Vv0123456789",
 			      long_options, (int *) 0)) != EOF)
     {
       switch (optc)

@@ -186,6 +200,17 @@ main (int argc, char **argv)
 	  datasection_only = TRUE;
 	  break;
 
+	case 'S':
+	  specified_sections_only = TRUE;
+	  specified_sections = xrealloc(specified_sections,
+					(specified_sections_count + 1) * sizeof(const char *));
+	  specified_sections[specified_sections_count++] = optarg;
+	  break;
+
+	case 'k':
+	  linux_kernel_soh = TRUE;
+	  break;
+
 	case 'f':
 	  print_filenames = TRUE;
 	  break;

@@ -318,6 +343,19 @@ main (int argc, char **argv)
   return (exit_status);
 }
 

+static bfd_boolean
+section_is_specified_section (asection *sect)
+{
+  int i;
+  for (i = 0; i < specified_sections_count; i++)
+    {
+      if (strcmp(specified_sections[i], sect->name) == 0) {
+	return TRUE;
+    }
+  }
+  return FALSE;
+}
+
 /* Scan section SECT of the file ABFD, whose printable name is
    FILENAME.  If it contains initialized data set GOT_A_SECTION and
    print the strings in it.  */

@@ -329,7 +367,9 @@ strings_a_section (bfd *abfd, asection *sect, const char *filename,
   bfd_size_type sectsize;
   bfd_byte *mem;
 
-  if ((sect->flags & DATA_FLAGS) != DATA_FLAGS)
+  if (specified_sections_only && !section_is_specified_section (sect))
+    return;
+  if (datasection_only && ((sect->flags & DATA_FLAGS) != DATA_FLAGS))
     return;
 
   sectsize = bfd_section_size (sect);

@@ -417,7 +457,7 @@ strings_file (char *file)
      try to open it as an object file and only look at
      initialized data sections.  If that fails, fall back to the
      whole file.  */
-  if (!datasection_only || !strings_object_file (file))
+  if (!(datasection_only || specified_sections_only) || !strings_object_file (file))
     {
       FILE *stream;
 

@@ -571,6 +611,7 @@ print_strings (const char *filename, FILE *stream, file_ptr address,
 	       int stop_point, int magiccount, char *magic)
 {
   char *buf = (char *) xmalloc (sizeof (char) * (string_min + 1));
+  int is_kernel = 0;
 
   while (1)
     {

@@ -594,6 +635,7 @@ print_strings (const char *filename, FILE *stream, file_ptr address,
 
 	  if (! STRING_ISGRAPHIC (c))
 	    {
+	      is_kernel = c == 1;
 	      /* Found a non-graphic.  Try again starting with next byte.  */
 	      unget_part_char (c, &address, &magiccount, &magic);
 	      goto tryline;

@@ -601,6 +643,22 @@ print_strings (const char *filename, FILE *stream, file_ptr address,
 	  buf[i] = c;
 	}
 
+      if ((linux_kernel_soh && !is_kernel) ||
+	  (linux_kernel_soh && !strchr("01234567cd", buf[0])))
+	{
+	  while (1) {
+	    c = get_char (stream, &address, &magiccount, &magic);
+	    if (c == EOF)
+	      return;
+	    if (! STRING_ISGRAPHIC (c))
+	      {
+	        unget_part_char (c, &address, &magiccount, &magic);
+	        break;
+	      }
+	    }
+	goto tryline;
+	}
+
       /* We found a run of `string_min' graphic characters.  Print up
 	 to the next non-graphic character.  */
 

@@ -668,8 +726,11 @@ print_strings (const char *filename, FILE *stream, file_ptr address,
 	    break;
 	  }
 
-      buf[i] = '\0';
-      fputs (buf, stdout);
+      if (!linux_kernel_soh || is_kernel)
+        {
+	  buf[i] = '\0';
+	  fputs (buf, stdout);
+        }
 
       while (1)
 	{

@@ -681,13 +742,20 @@ print_strings (const char *filename, FILE *stream, file_ptr address,
 	      unget_part_char (c, &address, &magiccount, &magic);
 	      break;
 	    }
-	  putchar (c);
+	  if (!linux_kernel_soh || is_kernel)
+	    {
+	      putchar (c);
+	    }
 	}
 
-      if (output_separator)
-	fputs (output_separator, stdout);
-      else
-	putchar ('\n');
+      if (!linux_kernel_soh || is_kernel)
+	{
+          if (output_separator)
+	    fputs (output_separator, stdout);
+	  else
+	    putchar ('\n');
+	}
+      is_kernel = 0;
     }
   free (buf);
 }

@@ -702,13 +770,11 @@ usage (FILE *stream, int status)
   if (DEFAULT_STRINGS_ALL)
     fprintf (stream, _("\
   -a - --all                Scan the entire file, not just the data section [default]\n\
-  -d --data                 Only scan the data sections in the file\n"));
-  else
-    fprintf (stream, _("\
+  -d --data                 Only scan the data sections in the file\n\
+  -S --section=[section]    Only scan the specific sections\n\
+  -k --kernel               Only scan for linux-kernel strings with KERN_SOH\n\
   -a - --all                Scan the entire file, not just the data section\n\
-  -d --data                 Only scan the data sections in the file [default]\n"));
-
-  fprintf (stream, _("\
+  -d --data                 Only scan the data sections in the file [default]\n\
   -f --print-file-name      Print the name of the file before each string\n\
   -n --bytes=[number]       Locate & print any NUL-terminated sequence of at\n\
   -<number>                   least [number] characters (default 4).\n\

Joe Perches writes:

quoted

There are certainly printks which can't be trivially monitored using the printk
format alone, but the vast majority of the ones that are monitored _do_ have
meaningful formats and can be monitored over time. No solution to this is going
to catch every single case, especially when so much of the information can be
generated dyamically, but this patchset still goes a long way to making printk
monitoring more tractable for use cases like the one described in the
changelog.

For the _vast_ majority of printk strings, this can easily be found
and compared using a trivial modification to strings.

There are several issues with your proposed approach that make it unsuitable 
for use as part of a reliable production environment:

1. It misses printk() formats without KERN_SOH

printk() formats without KERN_SOH are legal and use MESSAGE_LOGLEVEL_DEFAULT.  
On my test kernel, your proposed patch loses >5% of printk formats -- over 200 
messages -- due to this, including critical ones like those about hardware or 
other errors.

2. Users don't always have the kernel image available

Many of our machines and many of the machines of others like us do not boot 
using local storage, but instead use PXE or other technologies where the kernel 
may not be stored during runtime.

As is described in the changelog, it is necessary to be able to vary 
remediations not only based on what is already in /dev/kmsg, but also to be 
able to make decisions about our methodology based on what's _supported_ in the 
running kernel at runtime, and your proposed approach makes this not viable.

3. `KERN_SOH + level' can appear in other places than just printk strings

KERN_SOH is just ASCII '\001' -- it's not distinctive or unique, even when 
paired with a check for something that looks like a level after it. For this 
reason, your proposed patch results in a non-trivial amount of non-printk 
related garbage in its output. For example:

     % binutils/strings -k /tmp/vmlinux | head -5
     3L)s
     3L)s
     c,[]A\
     c(L)c
     d$pL)d$`u4

Fundamentally, one cannot use a tool which just determines whether something is 
printable to determine semantic intent.

4. strings(1) output cannot differentiate embedded newlines and new formats

The following has exactly the same output from strings(1), but will manifest 
completely differently at printk() time:

     printk(KERN_ERR "line one\nline two\nline three\n");
     printk("line four\n");

With strings, the hypothetical output would be:*

     3line one\nline two\nline three\nline four\n

* "line four\n" would also be missing with your current -k check.

But this makes it impossible to distinguish between this, compared to:

     printk(KERN_ERR "line one\nline two\n");
     printk("line three\n");
     printk("line four\n");

The originally posted patch _does_ differentiate between these cases, using \0 
as a reliable separator. Its outputs are, respectively:

     \0013line one\nline two\nline three\0\nline four\n\0
     \0013line one\nline two\n\0line three\nline four\n\0

This isn't just a theoretical concern -- there are plenty of places which use 
multiline printks, and we must be able to distinguish between that and 
_multiple_ printks. Not being able to differentiate cases like these would 
dramatically reduce the effectiveness of printk enumeration, as we can no 
longer ascertain which formats will always be used together (for example, in 
the case of sequences of printks guarded by conditionals, which are all over 
the place).

5. strings(1) is not contextually aware, and cannot be made to act as if it is

strings has no idea about what it is reading, which is why it is more than 
happy to output the kind of meaningless output shown in #3. There are plenty of 
places across the kernel where there might be a sequence of bytes which the 
strings utility happens to interpret as being semantically meaningful, but in 
reality just happens to be an unrelated sequence of coincidentally printable 
bytes that just happens to contain a \001.

I appreciate your willingness to propose other solutions, but for these 
reasons, the proposed strings(1) patch would not suffice as an interface for 
printk enumeration.

On Sun, 2021-02-07 at 14:13 +0000, Chris Down wrote:

Joe Perches writes:

quoted

quoted

There are certainly printks which can't be trivially monitored using the printk
format alone, but the vast majority of the ones that are monitored _do_ have
meaningful formats and can be monitored over time. No solution to this is going
to catch every single case, especially when so much of the information can be
generated dyamically, but this patchset still goes a long way to making printk
monitoring more tractable for use cases like the one described in the
changelog.

For the _vast_ majority of printk strings, this can easily be found
and compared using a trivial modification to strings.

There are several issues with your proposed approach that make it unsuitable 
for use as part of a reliable production environment:

1. It misses printk() formats without KERN_SOH

printk() formats without KERN_SOH are legal and use MESSAGE_LOGLEVEL_DEFAULT.  
On my test kernel, your proposed patch loses >5% of printk formats -- over 200 
messages -- due to this, including critical ones like those about hardware or 
other errors.

There are _very_ few of those printks without KERN_<level> and those
very few are not generally being changed.

2. Users don't always have the kernel image available

Many of our machines and many of the machines of others like us do not boot 
using local storage, but instead use PXE or other technologies where the kernel 
may not be stored during runtime.

As is described in the changelog, it is necessary to be able to vary 
remediations not only based on what is already in /dev/kmsg, but also to be 
able to make decisions about our methodology based on what's _supported_ in the 
running kernel at runtime, and your proposed approach makes this not viable.

Indirection would alway work.

You could load a separate file with output strings along with your
kernel image.

3. `KERN_SOH + level' can appear in other places than just printk strings

KERN_SOH is just ASCII '\001' -- it's not distinctive or unique, even when 
paired with a check for something that looks like a level after it. For this 
reason, your proposed patch results in a non-trivial amount of non-printk 
related garbage in its output. For example:

     % binutils/strings -k /tmp/vmlinux | head -5
     3L)s
     3L)s
     c,[]A\
     c(L)c
     d$pL)d$`u4

Fundamentally, one cannot use a tool which just determines whether something is 
printable to determine semantic intent.

$ kernel_strings --kernel --section ".rodata" vmlinux

I got exactly 0.

4. strings(1) output cannot differentiate embedded newlines and new formats

The following has exactly the same output from strings(1), but will manifest 
completely differently at printk() time:

     printk(KERN_ERR "line one\nline two\nline three\n");
     printk("line four\n");

This is not the preferred output style and is only done in old and
unchanging code.

Your use case in your commit log is looking for _changed_ formats.

On Thu, 2021-02-04 at 15:37 +0000, Chris Down wrote:

This patch provides a solution to the issue of silently changed or
deleted printks:

Exactly _how_ many of these use cases do you think exist?

The generally preferred style for the example above would be:

	pr_err("line one\n");
	pr_err("line two\n");
	pr_err("line three\n");
	pr_err("line four\n");

The originally posted patch _does_ differentiate between these cases, using \0 
as a reliable separator. Its outputs are, respectively:

     \0013line one\nline two\nline three\0\nline four\n\0
     \0013line one\nline two\n\0line three\nline four\n\0

This isn't just a theoretical concern -- there are plenty of places which use 
multiline printks, and we must be able to distinguish between that and 
_multiple_ printks.

Just like there are many places that use buffered printks as the
example I gave earlier.  None of which your proposed solution would find.

5. strings(1) is not contextually aware, and cannot be made to act as if it is

strings has no idea about what it is reading, which is why it is more than 
happy to output the kind of meaningless output shown in #3. There are plenty of 
places across the kernel where there might be a sequence of bytes which the 
strings utility happens to interpret as being semantically meaningful, but in 
reality just happens to be an unrelated sequence of coincidentally printable 
bytes that just happens to contain a \001.

I appreciate your willingness to propose other solutions, but for these 
reasons, the proposed strings(1) patch would not suffice as an interface for 
printk enumeration.

I think you are on a path to try to make printk output immutable.
I think that's a _very_ bad path.

I also think this is adding needless complexity.

A possible complexity I would like to support would be optionally
compressing printk format strings at compile time and uncompressing
them at use time.

Joe Perches writes:

quoted

There are several issues with your proposed approach that make it unsuitable
for use as part of a reliable production environment:

1. It misses printk() formats without KERN_SOH

printk() formats without KERN_SOH are legal and use MESSAGE_LOGLEVEL_DEFAULT.
On my test kernel, your proposed patch loses >5% of printk formats -- over 200
messages -- due to this, including critical ones like those about hardware or
other errors.

There are _very_ few of those printks without KERN_<level> and those
very few are not generally being changed.

I already specified how many are lost: 5%. That's not "very few". That's a huge 
proportion of the coverage afforded by this patch, including several important 
cases.

Relying on "they generally don't change" is not a recipe for reliability or 
success (and they do change, more data on that below).

quoted

2. Users don't always have the kernel image available

Many of our machines and many of the machines of others like us do not boot
using local storage, but instead use PXE or other technologies where the kernel
may not be stored during runtime.

As is described in the changelog, it is necessary to be able to vary
remediations not only based on what is already in /dev/kmsg, but also to be
able to make decisions about our methodology based on what's _supported_ in the
running kernel at runtime, and your proposed approach makes this not viable.

Indirection would alway work.

You could load a separate file with output strings along with your
kernel image.

You're moving the goalposts quite quickly here, which makes it harder to reply 
to your points. Now you're proposing an entirely separate distribution path, 
compared to interfaces that we already have precedent for in the kernel (eg.  
trace_printk). That requires a strong justification, and I'm not seeing one 
here.

quoted

3. `KERN_SOH + level' can appear in other places than just printk strings

KERN_SOH is just ASCII '\001' -- it's not distinctive or unique, even when
paired with a check for something that looks like a level after it. For this
reason, your proposed patch results in a non-trivial amount of non-printk
related garbage in its output. For example:

     % binutils/strings -k /tmp/vmlinux | head -5
     3L)s
     3L)s
     c,[]A\
     c(L)c
     d$pL)d$`u4

Fundamentally, one cannot use a tool which just determines whether something is
printable to determine semantic intent.

$ kernel_strings --kernel --section ".rodata" vmlinux

I got exactly 0.

"It works on my computer" is not a valid testing methodology, especially for 
something as complex as the Linux kernel. It's especially not a valid rebuttal 
to someone demonstrating that it clearly doesn't work on theirs.

Even filtering to the .rodata section, there's plenty of garbage just in the 
first five cases:

     % binutils/strings --kernel --section ".rodata" /tmp/vmlinux | head -5
     3******* Your BIOS seems to not contain a fix for K8 errata #93
     1>pBC)
     dTRAC
     6Run %s as init process
     7calling  %pS @ %i

Clearly there are cases that you are not considering. My kernel config is 
attached if you want to try and replicate, but regardless, it's really not 
valid to say "it works for me" in response to someone showing that it doesn't.

quoted

4. strings(1) output cannot differentiate embedded newlines and new formats

The following has exactly the same output from strings(1), but will manifest
completely differently at printk() time:

     printk(KERN_ERR "line one\nline two\nline three\n");
     printk("line four\n");

This is not the preferred output style and is only done in old and
unchanging code.

Your use case in your commit log is looking for _changed_ formats.

Joe, it's fine to present alternatives to people's patches, but please do your 
research before spouting things like this. It's a waste of everyone's time to 
refute things which are so easily demonstrated to be false.

Here are a bunch of recent changes to printk I found just from literally 2 
minutes of looking through `git log`:

- ea34f78f3df6: 2020, printk site deleted (which of course we also need to know.)
- a0f6d924cada: 2020, new callsite. the level is printed dynamically, so your proposed patch would not match.
- bf13718bc57a: 2020, existing printk changed. 
- 994388f228c6: 2020, printk site changed to au0828_isocdbg, reworded entirely.
- a8b62fd08505: 2020, new callsite, dynamic level.

I could find literally pages and pages of these just from the last few years.  
Your belief that these printks are only in "unchanging" code does not match 
reality.

On Thu, 2021-02-04 at 15:37 +0000, Chris Down wrote:

quoted

This patch provides a solution to the issue of silently changed or
deleted printks:

Exactly _how_ many of these use cases do you think exist?

The generally preferred style for the example above would be:

pr_err("line one\n");
pr_err("line two\n");
pr_err("line three\n");
pr_err("line four\n");

I have no idea why you think this is so rare -- we have mixed pr_* and 
unadorned printk() all over the codebase. A number of the patches I just gave 
above are in files with mixed calls.

quoted

The originally posted patch _does_ differentiate between these cases, using \0
as a reliable separator. Its outputs are, respectively:

     \0013line one\nline two\nline three\0\nline four\n\0
     \0013line one\nline two\n\0line three\nline four\n\0

This isn't just a theoretical concern -- there are plenty of places which use
multiline printks, and we must be able to distinguish between that and
_multiple_ printks.

Just like there are many places that use buffered printks as the
example I gave earlier.  None of which your proposed solution would find.

There are always going to be cases which are not caught. The point is that the 
patch proposed in this thread captures significantly more cases than the 
`strings` case (not to mention that it avoids outputting garbage from .rodata), 
not that it covers every imaginable scenario.

quoted

5. strings(1) is not contextually aware, and cannot be made to act as if it is

strings has no idea about what it is reading, which is why it is more than
happy to output the kind of meaningless output shown in #3. There are plenty of
places across the kernel where there might be a sequence of bytes which the
strings utility happens to interpret as being semantically meaningful, but in
reality just happens to be an unrelated sequence of coincidentally printable
bytes that just happens to contain a \001.

I appreciate your willingness to propose other solutions, but for these
reasons, the proposed strings(1) patch would not suffice as an interface for
printk enumeration.

I think you are on a path to try to make printk output immutable.
I think that's a _very_ bad path.

That's literally the opposite of what this patchset does. This patchset 
offloads the responsibility of worrying about userspace parsers breaking 
because of changes to kernel printks, because those userspace parsers and 
maintainers now have a mechanism to detect changes. If anything, it _reduces_ 
the risk of what you're describing.

Chris Down writes:

quoted

quoted

3. `KERN_SOH + level' can appear in other places than just printk strings

KERN_SOH is just ASCII '\001' -- it's not distinctive or unique, even when
paired with a check for something that looks like a level after it. For this
reason, your proposed patch results in a non-trivial amount of non-printk
related garbage in its output. For example:

    % binutils/strings -k /tmp/vmlinux | head -5
    3L)s
    3L)s
    c,[]A\
    c(L)c
    d$pL)d$`u4

Fundamentally, one cannot use a tool which just determines whether something is
printable to determine semantic intent.

$ kernel_strings --kernel --section ".rodata" vmlinux

I got exactly 0.

"It works on my computer" is not a valid testing methodology, 
especially for something as complex as the Linux kernel. It's 
especially not a valid rebuttal to someone demonstrating that it 
clearly doesn't work on theirs.

Even filtering to the .rodata section, there's plenty of garbage just 
in the first five cases:

   % binutils/strings --kernel --section ".rodata" /tmp/vmlinux | head -5
   3******* Your BIOS seems to not contain a fix for K8 errata #93
   1>pBC)
   dTRAC
   6Run %s as init process
   7calling  %pS @ %i

Clearly there are cases that you are not considering. My kernel config 
is attached if you want to try and replicate, but regardless, it's 
really not valid to say "it works for me" in response to someone 
showing that it doesn't.

Attached.