2021-03-01 23:09:04

by Stephen Boyd

[permalink] [raw]
Subject: [PATCH 5/7] printk: Make %pS and friends print module build ID

The %pS printk format (among some others) is used to print kernel
addresses symbolically. When the kernel prints an address inside of a
module, the kernel prints the addresses' symbol name along with the
module's name that contains the address. Let's make kernel stacktraces
easier to identify on KALLSYMS builds by including the build ID of a
module when we print the address.

This is especially helpful for crash debugging with pstore or crashdump
kernels. If we have the build ID for the module in the stacktrace we can
request the debug symbols for the module from a remote debuginfod server
or parse stacktraces at a later time with decode_stacktrace.sh by
downloading the correct symbols based on the build ID. This cuts down on
the amount of time and effort needed to find the correct kernel modules
for a stacktrace by encoding that information into it.

An alternative to changing the printk format would be to update the
"Modules linked in:" line to include the build ID of each module linked
in. This can become quite long when many modules are loaded (i.e. on a
distro) so I've opted for the printk format instead. Similarly,
collecting each module build ID in a stacktrace and then printing it
after the trace would require some architecture level surgery to the
dump stack code and also provide the ID "too late" for code that is
parsing each line of the stacktrace.

Example:

WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
Modules linked in: lkdtm rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE
CPU: 4 PID: 3255 Comm: bash Not tainted 5.11 #3 aa23f7a1231c229de205662d5a9e0d4c580f19a1
Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
pc : lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
lr : lkdtm_do_action+0x24/0x40 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
sp : ffffffc0134fbca0
x29: ffffffc0134fbca0 x28: ffffff92d53ba240
x27: 0000000000000000 x26: 0000000000000000
x25: 0000000000000000 x24: ffffffe3622352c0
x23: 0000000000000020 x22: ffffffe362233366
x21: ffffffe3622352e0 x20: ffffffc0134fbde0
x19: 0000000000000008 x18: 0000000000000000
x17: ffffff929b6536fc x16: 0000000000000000
x15: 0000000000000000 x14: 0000000000000012
x13: ffffffe380ed892c x12: ffffffe381d05068
x11: 0000000000000000 x10: 0000000000000000
x9 : 0000000000000001 x8 : ffffffe362237000
x7 : aaaaaaaaaaaaaaaa x6 : 0000000000000000
x5 : 0000000000000000 x4 : 0000000000000001
x3 : 0000000000000008 x2 : ffffff93fef25a70
x1 : ffffff93fef15788 x0 : ffffffe3622352e0
Call trace:
lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
direct_entry+0x16c/0x1b4 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
full_proxy_write+0x74/0xa4
vfs_write+0xec/0x2e8
ksys_write+0x84/0xf0
__arm64_sys_write+0x24/0x30
el0_svc_common+0xf4/0x1c0
do_el0_svc_compat+0x28/0x3c
el0_svc_compat+0x10/0x1c
el0_sync_compat_handler+0xa8/0xcc
el0_sync_compat+0x178/0x180
---[ end trace 3d95032303e59e68 ]---

Cc: Jiri Olsa <[email protected]>
Cc: Alexei Starovoitov <[email protected]>
Cc: Jessica Yu <[email protected]>
Cc: Evan Green <[email protected]>
Cc: Hsin-Yi Wang <[email protected]>
Cc: Petr Mladek <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: Sergey Senozhatsky <[email protected]>
Cc: Andy Shevchenko <[email protected]>
Cc: Rasmus Villemoes <[email protected]>
Cc: <[email protected]>
Signed-off-by: Stephen Boyd <[email protected]>
---

Yet another alternative is to add a printk format like %pSB for
backtrace prints. This would require a handful of architecture updates
and I'm not sure it's worth the effort for that.

Documentation/core-api/printk-formats.rst | 6 +++
include/linux/kallsyms.h | 6 ++-
include/linux/module.h | 2 +-
kernel/kallsyms.c | 45 +++++++++++++++--------
kernel/module.c | 4 +-
5 files changed, 44 insertions(+), 19 deletions(-)

diff --git a/Documentation/core-api/printk-formats.rst b/Documentation/core-api/printk-formats.rst
index 160e710d992f..7f05962f7f68 100644
--- a/Documentation/core-api/printk-formats.rst
+++ b/Documentation/core-api/printk-formats.rst
@@ -114,6 +114,12 @@ used when printing stack backtraces. The specifier takes into
consideration the effect of compiler optimisations which may occur
when tail-calls are used and marked with the noreturn GCC attribute.

+If the pointer is within a module, the module name and build ID is printed after
+the symbol name.
+
+::
+ %pS versatile_init+0x0/0x110 [module_name] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
+
Probed Pointers from BPF / tracing
----------------------------------

diff --git a/include/linux/kallsyms.h b/include/linux/kallsyms.h
index 465060acc981..c2f1660823cb 100644
--- a/include/linux/kallsyms.h
+++ b/include/linux/kallsyms.h
@@ -7,6 +7,7 @@
#define _LINUX_KALLSYMS_H

#include <linux/errno.h>
+#include <linux/buildid.h>
#include <linux/kernel.h>
#include <linux/stddef.h>
#include <linux/mm.h>
@@ -15,8 +16,9 @@
#include <asm/sections.h>

#define KSYM_NAME_LEN 128
-#define KSYM_SYMBOL_LEN (sizeof("%s+%#lx/%#lx [%s]") + (KSYM_NAME_LEN - 1) + \
- 2*(BITS_PER_LONG*3/10) + (MODULE_NAME_LEN - 1) + 1)
+#define KSYM_SYMBOL_LEN (sizeof("%s+%#lx/%#lx [%s] (%s)") + (KSYM_NAME_LEN - 1) + \
+ 2*(BITS_PER_LONG*3/10) + (MODULE_NAME_LEN - 1) + \
+ (BUILD_ID_STR_SIZE_MAX - 1) + 1)

struct cred;
struct module;
diff --git a/include/linux/module.h b/include/linux/module.h
index 9d1f6a5240c1..c12f9215f63e 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -634,7 +634,7 @@ void *dereference_module_function_descriptor(struct module *mod, void *ptr);
const char *module_address_lookup(unsigned long addr,
unsigned long *symbolsize,
unsigned long *offset,
- char **modname,
+ char **modname, char **modbuildid,
char *namebuf);
int lookup_module_symbol_name(unsigned long addr, char *symname);
int lookup_module_symbol_attrs(unsigned long addr, unsigned long *size, unsigned long *offset, char *modname, char *name);
diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
index 8043a90aa50e..a70c53764b8a 100644
--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -273,21 +273,13 @@ int kallsyms_lookup_size_offset(unsigned long addr, unsigned long *symbolsize,
get_symbol_pos(addr, symbolsize, offset);
return 1;
}
- return !!module_address_lookup(addr, symbolsize, offset, NULL, namebuf) ||
+ return !!module_address_lookup(addr, symbolsize, offset, NULL, NULL, namebuf) ||
!!__bpf_address_lookup(addr, symbolsize, offset, namebuf);
}

-/*
- * Lookup an address
- * - modname is set to NULL if it's in the kernel.
- * - We guarantee that the returned name is valid until we reschedule even if.
- * It resides in a module.
- * - We also guarantee that modname will be valid until rescheduled.
- */
-const char *kallsyms_lookup(unsigned long addr,
- unsigned long *symbolsize,
- unsigned long *offset,
- char **modname, char *namebuf)
+const char *kallsyms_lookup_buildid(unsigned long addr, unsigned long *symbolsize,
+ unsigned long *offset, char **modname,
+ char **modbuildid, char *namebuf)
{
const char *ret;

@@ -303,12 +295,14 @@ const char *kallsyms_lookup(unsigned long addr,
namebuf, KSYM_NAME_LEN);
if (modname)
*modname = NULL;
+ if (modbuildid)
+ *modbuildid = NULL;
return namebuf;
}

/* See if it's in a module or a BPF JITed image. */
ret = module_address_lookup(addr, symbolsize, offset,
- modname, namebuf);
+ modname, modbuildid, namebuf);
if (!ret)
ret = bpf_address_lookup(addr, symbolsize,
offset, modname, namebuf);
@@ -319,6 +313,22 @@ const char *kallsyms_lookup(unsigned long addr,
return ret;
}

+/*
+ * Lookup an address
+ * - modname is set to NULL if it's in the kernel.
+ * - We guarantee that the returned name is valid until we reschedule even if.
+ * It resides in a module.
+ * - We also guarantee that modname will be valid until rescheduled.
+ */
+const char *kallsyms_lookup(unsigned long addr,
+ unsigned long *symbolsize,
+ unsigned long *offset,
+ char **modname, char *namebuf)
+{
+ return kallsyms_lookup_buildid(addr, symbolsize, offset, modname,
+ NULL, namebuf);
+}
+
int lookup_symbol_name(unsigned long addr, char *symname)
{
symname[0] = '\0';
@@ -362,12 +372,14 @@ static int __sprint_symbol(char *buffer, unsigned long address,
int symbol_offset, int add_offset)
{
char *modname;
+ char *modbuildid;
const char *name;
unsigned long offset, size;
int len;

address += symbol_offset;
- name = kallsyms_lookup(address, &size, &offset, &modname, buffer);
+ name = kallsyms_lookup_buildid(address, &size, &offset, &modname, &modbuildid,
+ buffer);
if (!name)
return sprintf(buffer, "0x%lx", address - symbol_offset);

@@ -379,8 +391,11 @@ static int __sprint_symbol(char *buffer, unsigned long address,
if (add_offset)
len += sprintf(buffer + len, "+%#lx/%#lx", offset, size);

- if (modname)
+ if (modname) {
len += sprintf(buffer + len, " [%s]", modname);
+ if (modbuildid)
+ len += sprintf(buffer + len, " (%s)", modbuildid);
+ }

return len;
}
diff --git a/kernel/module.c b/kernel/module.c
index a7559a0de9d8..2909e62f147b 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -4255,7 +4255,7 @@ void * __weak dereference_module_function_descriptor(struct module *mod,
const char *module_address_lookup(unsigned long addr,
unsigned long *size,
unsigned long *offset,
- char **modname,
+ char **modname, char **modbuildid,
char *namebuf)
{
const char *ret = NULL;
@@ -4266,6 +4266,8 @@ const char *module_address_lookup(unsigned long addr,
if (mod) {
if (modname)
*modname = mod->name;
+ if (modbuildid)
+ *modbuildid = mod->build_id;

ret = find_kallsyms_symbol(mod, addr, size, offset);
}
--
https://chromeos.dev


2021-03-02 18:48:09

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Mon, 1 Mar 2021 09:47:47 -0800
Stephen Boyd <[email protected]> wrote:

> The %pS printk format (among some others) is used to print kernel
> addresses symbolically. When the kernel prints an address inside of a
> module, the kernel prints the addresses' symbol name along with the
> module's name that contains the address. Let's make kernel stacktraces
> easier to identify on KALLSYMS builds by including the build ID of a
> module when we print the address.

Please no!

This kills the output of tracing with offset, and can possibly break
scripts. I don't want to look at traces like this!

<idle>-0 [004] ..s1 353.842577: ipv4_conntrack_in+0x0/0x10 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0
<idle>-0 [004] ..s1 353.842577: nf_conntrack_in+0x0/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0
<idle>-0 [004] ..s1 353.842577: get_l4proto+0x0/0x190 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x92/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s1 353.842577: nf_ct_get_tuple+0x0/0x240 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0xec/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s1 353.842577: hash_conntrack_raw+0x0/0x170 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x28c/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s1 353.842578: __nf_conntrack_find_get.isra.0+0x0/0x2f0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x29d/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s1 353.842578: nf_conntrack_tcp_packet+0x0/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x3c8/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s2 353.842578: nf_ct_seq_offset+0x0/0x40 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_tcp_packet+0x26d/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
<idle>-0 [004] ..s1 353.842578: __nf_ct_refresh_acct+0x0/0x50 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_tcp_packet+0x558/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)

NACK!

-- Steve

2021-03-04 08:12:43

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Steven Rostedt (2021-03-02 18:01:36)
> On Mon, 1 Mar 2021 09:47:47 -0800
> Stephen Boyd <[email protected]> wrote:
>
> > WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > Modules linked in: lkdtm rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE
> > CPU: 4 PID: 3255 Comm: bash Not tainted 5.11 #3 aa23f7a1231c229de205662d5a9e0d4c580f19a1
> > Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
> > pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
> > pc : lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > lr : lkdtm_do_action+0x24/0x40 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
>
> Why not just change the "Modules linked in:" portion to show the build IDs
> instead of every function call? Maybe make it a config option to do so?
>

As I wrote in the commit text

│ An alternative to changing the printk format would be to update the
│ "Modules linked in:" line to include the build ID of each module linked
│ in. This can become quite long when many modules are loaded (i.e. on a
│ distro) so I've opted for the printk format instead.

Implementing it is fairly simple compared to a new printk format. In
fact I did that initially but decided against it because it felt
unreadable and provided more information than was necessary if the
stacktrace wasn't in a module.

Example:

Modules linked in: rfcomm 4de3e669b9fee915 algif_hash 915c61c32d476f01 algif_skcipher 53a4a330149bf071 af_alg b49d66496907f376 xt_cgroup 36fbbb65e7620df9 uinput a0ff6a06c1c53685 xt_MASQUERADE d130585f728315d2 snd_soc_sc7180 5c130cd310c81a12 venus_dec 2071e263fde9ca07 qcom_spmi_temp_alarm 41e28f2a9cc8b562 qcom_spmi_adc_tm5 7e0e48d0b6550c7a qcom_spmi_adc5 40b81a00bc2d0c1d qcom_vadc_common 09bb012dd1662dea snd_soc_rt5682_i2c c92b8935ad4a1729 venus_enc efaf3335b88287bf snd_soc_qcom_common 56d1e87c267ed02e videobuf2_dma_sg e9bc3c9e2758dfc9 snd_soc_rt5682 c4c9b31bf9a43f8b snd_soc_rl6231 908446e32436898c hci_uart 107b5fe6884df077 btqca 401a2fcc17b80a39 bluetooth 3369c881496a3cf8 venus_core a11eee3aa201ad8e ecdh_generic 883e01f98b778108 ecc 226b258cf40ad1ba v4l2_mem2mem 592f197cbad39e6b snd_soc_lpass_sc7180 42a99cb812d5e2e3 snd_soc_lpass_hdmi 95cce2160cfc58e2 snd_soc_lpass_cpu 475a4b395577affd snd_soc_lpass_platform 67517083263035ec snd_soc_max98357a 03ec1af0493d1c59
fuse 82d170244a4d4ac6 iio_trig_sysfs b879a6228e059834 cros_ec_lid_angle a713c5f0a06a7a82 cros_ec_sensors 03f0c142ec521f67 cros_ec_sensors_core ada3f44647980056 cros_ec_sensors_ring f99590e87e998485 industrialio_triggered_buffer c697969d67f73d77 kfifo_buf e8a3aeb3069188f0 cros_ec_sensorhub 041ed1ffcefc991b ath10k_snoc 2f60802a74ff6ca7 lzo_rle 49a6228cec0c6885 ath10k_core 9407c36a2b8f8fae lzo_compress e9b4375d4bad668a ath 20c585ba6f3998f0 zram c5cdfc1d7d8a35d9 mac80211 9eaed1c76e000c02 cfg80211 872178d2dcebb722 cdc_ether 2baa214f72289402 usbnet 2bec73d0922ade28 uvcvideo eee0352cb1846ee4 r8152 47b76561b78e9b1b mii b306d150923fe614 videobuf2_vmalloc 55431ec52fa6af84 videobuf2_memops 4d43ad18fa7b1e4e videobuf2_v4l2 cdda06b9d95ab11d videobuf2_common 69cef0ca55a70a4a joydev 148399325b72d4a0

compared to

Modules linked in: rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE snd_soc_sc7180 venus_dec qcom_spmi_temp_alarm qcom_spmi_adc_tm5 qcom_spmi_adc5 qcom_vadc_common snd_soc_rt5682_i2c venus_enc snd_soc_qcom_common videobuf2_dma_sg snd_soc_rt5682 snd_soc_rl6231 hci_uart btqca bluetooth venus_core ecdh_generic ecc v4l2_mem2mem snd_soc_lpass_sc7180 snd_soc_lpass_hdmi snd_soc_lpass_cpu snd_soc_lpass_platform snd_soc_max98357a
fuse iio_trig_sysfs cros_ec_lid_angle cros_ec_sensors cros_ec_sensors_core cros_ec_sensors_ring industrialio_triggered_buffer kfifo_buf cros_ec_sensorhub ath10k_snoc lzo_rle ath10k_core lzo_compress ath zram mac80211 cfg80211 cdc_ether usbnet uvcvideo r8152 mii videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common joydev

I suppose it could be surrounded by parenthesis or brackets and that
would be a little better? I'll try this approach again and see what
folks think.

2021-03-04 09:52:25

by Andy Shevchenko

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Tue, Mar 02, 2021 at 07:00:32PM -0800, Stephen Boyd wrote:
> Quoting Steven Rostedt (2021-03-02 18:01:36)
> > On Mon, 1 Mar 2021 09:47:47 -0800
> > Stephen Boyd <[email protected]> wrote:
> >
> > > WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > > Modules linked in: lkdtm rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE
> > > CPU: 4 PID: 3255 Comm: bash Not tainted 5.11 #3 aa23f7a1231c229de205662d5a9e0d4c580f19a1
> > > Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
> > > pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
> > > pc : lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > > lr : lkdtm_do_action+0x24/0x40 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> >
> > Why not just change the "Modules linked in:" portion to show the build IDs
> > instead of every function call? Maybe make it a config option to do so?
> >
>
> As I wrote in the commit text
>
> │ An alternative to changing the printk format would be to update the
> │ "Modules linked in:" line to include the build ID of each module linked
> │ in. This can become quite long when many modules are loaded (i.e. on a
> │ distro) so I've opted for the printk format instead.
>
> Implementing it is fairly simple compared to a new printk format. In
> fact I did that initially but decided against it because it felt
> unreadable and provided more information than was necessary if the
> stacktrace wasn't in a module.
>
> Example:
>
> Modules linked in: rfcomm 4de3e669b9fee915 algif_hash 915c61c32d476f01 algif_skcipher 53a4a330149bf071 af_alg b49d66496907f376 xt_cgroup 36fbbb65e7620df9 uinput a0ff6a06c1c53685 xt_MASQUERADE d130585f728315d2 snd_soc_sc7180 5c130cd310c81a12 venus_dec 2071e263fde9ca07 qcom_spmi_temp_alarm 41e28f2a9cc8b562 qcom_spmi_adc_tm5 7e0e48d0b6550c7a qcom_spmi_adc5 40b81a00bc2d0c1d qcom_vadc_common 09bb012dd1662dea snd_soc_rt5682_i2c c92b8935ad4a1729 venus_enc efaf3335b88287bf snd_soc_qcom_common 56d1e87c267ed02e videobuf2_dma_sg e9bc3c9e2758dfc9 snd_soc_rt5682 c4c9b31bf9a43f8b snd_soc_rl6231 908446e32436898c hci_uart 107b5fe6884df077 btqca 401a2fcc17b80a39 bluetooth 3369c881496a3cf8 venus_core a11eee3aa201ad8e ecdh_generic 883e01f98b778108 ecc 226b258cf40ad1ba v4l2_mem2mem 592f197cbad39e6b snd_soc_lpass_sc7180 42a99cb812d5e2e3 snd_soc_lpass_hdmi 95cce2160cfc58e2 snd_soc_lpass_cpu 475a4b395577affd snd_soc_lpass_platform 67517083263035ec snd_soc_max98357a 03ec1af0493d1c59
> fuse 82d170244a4d4ac6 iio_trig_sysfs b879a6228e059834 cros_ec_lid_angle a713c5f0a06a7a82 cros_ec_sensors 03f0c142ec521f67 cros_ec_sensors_core ada3f44647980056 cros_ec_sensors_ring f99590e87e998485 industrialio_triggered_buffer c697969d67f73d77 kfifo_buf e8a3aeb3069188f0 cros_ec_sensorhub 041ed1ffcefc991b ath10k_snoc 2f60802a74ff6ca7 lzo_rle 49a6228cec0c6885 ath10k_core 9407c36a2b8f8fae lzo_compress e9b4375d4bad668a ath 20c585ba6f3998f0 zram c5cdfc1d7d8a35d9 mac80211 9eaed1c76e000c02 cfg80211 872178d2dcebb722 cdc_ether 2baa214f72289402 usbnet 2bec73d0922ade28 uvcvideo eee0352cb1846ee4 r8152 47b76561b78e9b1b mii b306d150923fe614 videobuf2_vmalloc 55431ec52fa6af84 videobuf2_memops 4d43ad18fa7b1e4e videobuf2_v4l2 cdda06b9d95ab11d videobuf2_common 69cef0ca55a70a4a joydev 148399325b72d4a0
>
> compared to
>
> Modules linked in: rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE snd_soc_sc7180 venus_dec qcom_spmi_temp_alarm qcom_spmi_adc_tm5 qcom_spmi_adc5 qcom_vadc_common snd_soc_rt5682_i2c venus_enc snd_soc_qcom_common videobuf2_dma_sg snd_soc_rt5682 snd_soc_rl6231 hci_uart btqca bluetooth venus_core ecdh_generic ecc v4l2_mem2mem snd_soc_lpass_sc7180 snd_soc_lpass_hdmi snd_soc_lpass_cpu snd_soc_lpass_platform snd_soc_max98357a
> fuse iio_trig_sysfs cros_ec_lid_angle cros_ec_sensors cros_ec_sensors_core cros_ec_sensors_ring industrialio_triggered_buffer kfifo_buf cros_ec_sensorhub ath10k_snoc lzo_rle ath10k_core lzo_compress ath zram mac80211 cfg80211 cdc_ether usbnet uvcvideo r8152 mii videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common joydev
> I suppose it could be surrounded by parenthesis or brackets and that
> would be a little better? I'll try this approach again and see what
> folks think.

But you can do:
Modules linked: module1 [buildidX]
module2 [buildidY]
module3 [buildidZ]
...

i.o.w. one module per line.

* Yes, I understand that downside maybe split message, so it's just for
consideration.

--
With Best Regards,
Andy Shevchenko


2021-03-04 11:26:35

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Wed, 3 Mar 2021 11:25:58 +0100
Petr Mladek <[email protected]> wrote:

> Alternative solution would be to minimize the information, for
> example, by printing only the modules that appear in the backtrace.
> But this might be complicated to implement.

It could be a list after the backtrace perhaps, and not part of the
"modules linked in"?

But then you need a generic way of capturing those modules in the backtrace
that works for every architecture.

Honestly, I don't even know what a buildid is, and it is totally useless
information for myself. What exactly is it used for?

-- Steve

2021-03-04 12:11:54

by Andy Shevchenko

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Wed, Mar 03, 2021 at 10:00:12AM -0500, Steven Rostedt wrote:
> On Wed, 3 Mar 2021 11:25:58 +0100
> Petr Mladek <[email protected]> wrote:
>
> > Alternative solution would be to minimize the information, for
> > example, by printing only the modules that appear in the backtrace.
> > But this might be complicated to implement.
>
> It could be a list after the backtrace perhaps, and not part of the
> "modules linked in"?
>
> But then you need a generic way of capturing those modules in the backtrace
> that works for every architecture.

> Honestly, I don't even know what a buildid is, and it is totally useless
> information for myself. What exactly is it used for?

Dunno Stephen's motivation, but build ID is very useful when you do tracing,
then based on ID the decoders can know what exactly was the layout of the
binary and list of (exported) functions, etc.

At least that was my (shallow) experience with perf last time I have tried it.

--
With Best Regards,
Andy Shevchenko


2021-03-04 14:14:55

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Andy Shevchenko (2021-03-03 08:17:01)
> On Wed, Mar 03, 2021 at 10:00:12AM -0500, Steven Rostedt wrote:
> > On Wed, 3 Mar 2021 11:25:58 +0100
> > Petr Mladek <[email protected]> wrote:
> >
> > > Alternative solution would be to minimize the information, for
> > > example, by printing only the modules that appear in the backtrace.
> > > But this might be complicated to implement.
> >
> > It could be a list after the backtrace perhaps, and not part of the
> > "modules linked in"?
> >
> > But then you need a generic way of capturing those modules in the backtrace
> > that works for every architecture.

Right, and doing that is sort of complicated for something that really
shouldn't need to be complicated. We're printing out information about a
crash/hang/bug and that should be fast and not too computationally
intensive so that the stacktrace can be printed before everything starts
falling apart. I'd rather not save things away while processing the
stacktrace and then print more info after the stacktrace. Seems fragile.

>
> > Honestly, I don't even know what a buildid is, and it is totally useless
> > information for myself. What exactly is it used for?
>
> Dunno Stephen's motivation, but build ID is very useful when you do tracing,
> then based on ID the decoders can know what exactly was the layout of the
> binary and list of (exported) functions, etc.
>
> At least that was my (shallow) experience with perf last time I have tried it.
>

I'm starting to feel like nobody read the commit text, or I messed up
somehow and the commit text was confusing? :(

│ This is especially helpful for crash debugging with pstore or crashdump
│ kernels. If we have the build ID for the module in the stacktrace we can
│ request the debug symbols for the module from a remote debuginfod server
│ or parse stacktraces at a later time with decode_stacktrace.sh by
│ downloading the correct symbols based on the build ID. This cuts down on
│ the amount of time and effort needed to find the correct kernel modules
│ for a stacktrace by encoding that information into it.

In some distro (read: non-kernel dev) workflows the vmlinux isn't
shipped on the device and crash handling is done offline or much later.
Using the build ID[1] is a common way to identify the binary that's
running on the device. In conjunction with a debuginfod[2] server you
can download the symbols for a crash automatically if you have the build
ID information.

I can add a patch that updates decode_stacktrace.sh to show how it can
download the correct vmlinux/modules if it isn't provided on the
commandline.

If the debug symbols are on some public server then in theory we could
have some robot sitting on the mailing list that looks for stacktraces
and automatically replies with information about the line number/file
and even provides the code snippet for the code that's crashing from
that binary, because it's all stored in the full debuginfo builds.

[1] https://fedoraproject.org/wiki/RolandMcGrath/BuildID
[2] https://sourceware.org/elfutils/Debuginfod.html

2021-03-04 15:13:50

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Steven Rostedt (2021-03-03 17:19:32)
> On Wed, 03 Mar 2021 16:38:28 -0800
> Stephen Boyd <[email protected]> wrote:
>
> > I'm starting to feel like nobody read the commit text, or I messed up
> > somehow and the commit text was confusing? :(
> >
>
> I read it, I'm just unfamiliar with it. I don't use pstore, and I'm not
> sure what "crashdump" is. Do you mean the kexec/kdump? in which case
> you can retrieve data within the kernel quite easily.

Right, I meant kexec/kdump. Given that it is easy to retrieve it in
kdump (presumably with some scripting?) I can remove this motivation
from the commit text.

>
> I haven't used debuginfod (never heard of it before actually).

Got it. Hopefully the links I provided were good enough? I will provide
a link next time.

>
> > │ This is especially helpful for crash debugging with pstore or crashdump
> > │ kernels. If we have the build ID for the module in the stacktrace we can
> > │ request the debug symbols for the module from a remote debuginfod server
> > │ or parse stacktraces at a later time with decode_stacktrace.sh by
> > │ downloading the correct symbols based on the build ID. This cuts down on
> > │ the amount of time and effort needed to find the correct kernel modules
> > │ for a stacktrace by encoding that information into it.
>
> Are you saying it's common to have modules from different builds?

No.

>
> >
> > In some distro (read: non-kernel dev) workflows the vmlinux isn't
> > shipped on the device and crash handling is done offline or much later.
> > Using the build ID[1] is a common way to identify the binary that's
> > running on the device. In conjunction with a debuginfod[2] server you
> > can download the symbols for a crash automatically if you have the build
> > ID information.
> >
> > I can add a patch that updates decode_stacktrace.sh to show how it can
> > download the correct vmlinux/modules if it isn't provided on the
> > commandline.
>
> Are you just trying to match modules with the builds that they were
> created with?

Not exactly. I don't have a mapping of modules to the kernel they're
built/used with. I could create a mapping, but then that's something
else to maintain vs. what I have right now which is just a big database
of debuginfo mapped to build IDs (i.e. a debuginfod server).

>
> >
> > If the debug symbols are on some public server then in theory we could
> > have some robot sitting on the mailing list that looks for stacktraces
> > and automatically replies with information about the line number/file
> > and even provides the code snippet for the code that's crashing from
> > that binary, because it's all stored in the full debuginfo builds.
>
> Again, I have no idea how buildids are created or what they are used
> for. This is the first time I've even heard about them. I'm all for
> helping other people out to make their workflow easier, if it doesn't
> make a mess for everyone else.
>
>

Makes sense and sounds good. Thanks.

2021-03-04 19:18:13

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Matthew Wilcox (2021-03-04 09:19:40)
> On Mon, Mar 01, 2021 at 09:43:19PM -0500, Steven Rostedt wrote:
> > On Mon, 1 Mar 2021 09:47:47 -0800
> > Stephen Boyd <[email protected]> wrote:
> >
> > > The %pS printk format (among some others) is used to print kernel
> > > addresses symbolically. When the kernel prints an address inside of a
> > > module, the kernel prints the addresses' symbol name along with the
> > > module's name that contains the address. Let's make kernel stacktraces
> > > easier to identify on KALLSYMS builds by including the build ID of a
> > > module when we print the address.
> >
> > Please no!
> >
> > This kills the output of tracing with offset, and can possibly break
> > scripts. I don't want to look at traces like this!
> >
> > <idle>-0 [004] ..s1 353.842577: ipv4_conntrack_in+0x0/0x10 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0
>
> Would it make sense to only print the build-id if it differs from the
> build-id of the kernel which has loaded it?

No. The build-id of the module is different from the kernel that loaded
it all the time, so it would always be printed.

2021-03-04 19:22:23

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Matthew Wilcox (2021-03-04 09:00:52)
> On Mon, Mar 01, 2021 at 09:47:47AM -0800, Stephen Boyd wrote:
> > Example:
> >
> > WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
>
> Would the first 12 characters instead of all 40 make it more palatable
> without reducing its utility?

I can't seem to request debuginfo from debuginfod without the full 40
characters. It's not a git sha1 hash.

> And I feel it should be within the [], so maybe this:
>
> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm ed5019fdf5e5]
>

Sure I could put the hex numbers inside the brackets. I suspect changing
%pS or updating the "Modules linked in:" line isn't going to be
palatable. I've decided to introduce another printk format %pT to print
the stacktrace and then updated the architecture code on arm64 and x86
to see how it goes. Other architecures can be updated if this is
acceptable. I'll send out a patch series in a little bit that also
updates the decode_stacktrace.sh script to parse this.

2021-03-04 20:36:28

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Steven Rostedt (2021-03-01 18:43:19)
> On Mon, 1 Mar 2021 09:47:47 -0800
> Stephen Boyd <[email protected]> wrote:
>
> > The %pS printk format (among some others) is used to print kernel
> > addresses symbolically. When the kernel prints an address inside of a
> > module, the kernel prints the addresses' symbol name along with the
> > module's name that contains the address. Let's make kernel stacktraces
> > easier to identify on KALLSYMS builds by including the build ID of a
> > module when we print the address.
>
> Please no!
>
> This kills the output of tracing with offset, and can possibly break
> scripts. I don't want to look at traces like this!
>
> <idle>-0 [004] ..s1 353.842577: ipv4_conntrack_in+0x0/0x10 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0
> <idle>-0 [004] ..s1 353.842577: nf_conntrack_in+0x0/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0
> <idle>-0 [004] ..s1 353.842577: get_l4proto+0x0/0x190 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x92/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s1 353.842577: nf_ct_get_tuple+0x0/0x240 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0xec/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s1 353.842577: hash_conntrack_raw+0x0/0x170 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x28c/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s1 353.842578: __nf_conntrack_find_get.isra.0+0x0/0x2f0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x29d/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s1 353.842578: nf_conntrack_tcp_packet+0x0/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_in+0x3c8/0x5c0 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s2 353.842578: nf_ct_seq_offset+0x0/0x40 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_tcp_packet+0x26d/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
> <idle>-0 [004] ..s1 353.842578: __nf_ct_refresh_acct+0x0/0x50 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_conntrack_tcp_packet+0x558/0x1760 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051)
>
> NACK!
>

Heh, OK. Would adding a new printk format work then? From after the cut:

> Yet another alternative is to add a printk format like %pSB for
> backtrace prints. This would require a handful of architecture updates
> and I'm not sure it's worth the effort for that.
>

Or maybe take the approach of putting all the linked in module build IDs
in the "Modules linked in:" section? But as I said in the commit text
that can become quite verbose. Looking forward to your suggestions here.

2021-03-04 20:49:18

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Mon, 1 Mar 2021 09:47:47 -0800
Stephen Boyd <[email protected]> wrote:

> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> Modules linked in: lkdtm rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE
> CPU: 4 PID: 3255 Comm: bash Not tainted 5.11 #3 aa23f7a1231c229de205662d5a9e0d4c580f19a1
> Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
> pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
> pc : lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> lr : lkdtm_do_action+0x24/0x40 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)

Why not just change the "Modules linked in:" portion to show the build IDs
instead of every function call? Maybe make it a config option to do so?

-- Steve

2021-03-04 21:48:56

by Petr Mladek

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Mon 2021-03-01 09:47:47, Stephen Boyd wrote:
> The %pS printk format (among some others) is used to print kernel
> addresses symbolically. When the kernel prints an address inside of a
> module, the kernel prints the addresses' symbol name along with the
> module's name that contains the address. Let's make kernel stacktraces
> easier to identify on KALLSYMS builds by including the build ID of a
> module when we print the address.
>
> This is especially helpful for crash debugging with pstore or crashdump
> kernels. If we have the build ID for the module in the stacktrace we can
> request the debug symbols for the module from a remote debuginfod server

I have read the thread so for. IMHO, all mentioned variants complicate
the logs a lot. Either the backtrace lines are hard to parse.
Or the OOps/panic blocks gets too long when the ID is mentioned
for every loaded module. IMHO, neither proposed solution
is acceptable to be always used.

First, I think that only I some developers would actually use
this information. Many of them either know what module was
used or they do not have an easy way to get the debugging
information by the ID. So, it should be configurable
at minimum.

Second, I am not sure that it should be part of each OOps/panic blob.
One solution would be to print the ID by the module loader when
the module gets loaded. It would be mentioned earlier in the log
then.

Or we could make it available, for example, via /proc. It is a kind
of information that might be gathered later on a rebooted system.
SUSE has "supportconfig" command that allows to gather a lot
of similar information about the system. We use it when
analyzing crashdumps and kernel bugs in general.

Anyway, I consider this a very detailed information that is not
suitable for everyone. It should be availabe on request, like
for example, backtraces from all CPUs, list of tasks, memory info.

Alternative solution would be to minimize the information, for
example, by printing only the modules that appear in the backtrace.
But this might be complicated to implement.

Best Regards,
Petr

2021-03-04 21:50:10

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Andy Shevchenko (2021-03-03 00:19:05)
> On Tue, Mar 02, 2021 at 07:00:32PM -0800, Stephen Boyd wrote:
> > Quoting Steven Rostedt (2021-03-02 18:01:36)
> > > On Mon, 1 Mar 2021 09:47:47 -0800
> > > Stephen Boyd <[email protected]> wrote:
> > >
> > > > WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > > > Modules linked in: lkdtm rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE
> > > > CPU: 4 PID: 3255 Comm: bash Not tainted 5.11 #3 aa23f7a1231c229de205662d5a9e0d4c580f19a1
> > > > Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
> > > > pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
> > > > pc : lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > > > lr : lkdtm_do_action+0x24/0x40 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> > >
> > > Why not just change the "Modules linked in:" portion to show the build IDs
> > > instead of every function call? Maybe make it a config option to do so?
> > >
> >
> > As I wrote in the commit text
> >
> > │ An alternative to changing the printk format would be to update the
> > │ "Modules linked in:" line to include the build ID of each module linked
> > │ in. This can become quite long when many modules are loaded (i.e. on a
> > │ distro) so I've opted for the printk format instead.
> >
> > Implementing it is fairly simple compared to a new printk format. In
> > fact I did that initially but decided against it because it felt
> > unreadable and provided more information than was necessary if the
> > stacktrace wasn't in a module.
> >
> > Example:
> >
> > Modules linked in: rfcomm 4de3e669b9fee915 algif_hash 915c61c32d476f01 algif_skcipher 53a4a330149bf071 af_alg b49d66496907f376 xt_cgroup 36fbbb65e7620df9 uinput a0ff6a06c1c53685 xt_MASQUERADE d130585f728315d2 snd_soc_sc7180 5c130cd310c81a12 venus_dec 2071e263fde9ca07 qcom_spmi_temp_alarm 41e28f2a9cc8b562 qcom_spmi_adc_tm5 7e0e48d0b6550c7a qcom_spmi_adc5 40b81a00bc2d0c1d qcom_vadc_common 09bb012dd1662dea snd_soc_rt5682_i2c c92b8935ad4a1729 venus_enc efaf3335b88287bf snd_soc_qcom_common 56d1e87c267ed02e videobuf2_dma_sg e9bc3c9e2758dfc9 snd_soc_rt5682 c4c9b31bf9a43f8b snd_soc_rl6231 908446e32436898c hci_uart 107b5fe6884df077 btqca 401a2fcc17b80a39 bluetooth 3369c881496a3cf8 venus_core a11eee3aa201ad8e ecdh_generic 883e01f98b778108 ecc 226b258cf40ad1ba v4l2_mem2mem 592f197cbad39e6b snd_soc_lpass_sc7180 42a99cb812d5e2e3 snd_soc_lpass_hdmi 95cce2160cfc58e2 snd_soc_lpass_cpu 475a4b395577affd snd_soc_lpass_platform 67517083263035ec snd_soc_max98357a 03ec1af0493d1c59
> > fuse 82d170244a4d4ac6 iio_trig_sysfs b879a6228e059834 cros_ec_lid_angle a713c5f0a06a7a82 cros_ec_sensors 03f0c142ec521f67 cros_ec_sensors_core ada3f44647980056 cros_ec_sensors_ring f99590e87e998485 industrialio_triggered_buffer c697969d67f73d77 kfifo_buf e8a3aeb3069188f0 cros_ec_sensorhub 041ed1ffcefc991b ath10k_snoc 2f60802a74ff6ca7 lzo_rle 49a6228cec0c6885 ath10k_core 9407c36a2b8f8fae lzo_compress e9b4375d4bad668a ath 20c585ba6f3998f0 zram c5cdfc1d7d8a35d9 mac80211 9eaed1c76e000c02 cfg80211 872178d2dcebb722 cdc_ether 2baa214f72289402 usbnet 2bec73d0922ade28 uvcvideo eee0352cb1846ee4 r8152 47b76561b78e9b1b mii b306d150923fe614 videobuf2_vmalloc 55431ec52fa6af84 videobuf2_memops 4d43ad18fa7b1e4e videobuf2_v4l2 cdda06b9d95ab11d videobuf2_common 69cef0ca55a70a4a joydev 148399325b72d4a0
> >
> > compared to
> >
> > Modules linked in: rfcomm algif_hash algif_skcipher af_alg xt_cgroup uinput xt_MASQUERADE snd_soc_sc7180 venus_dec qcom_spmi_temp_alarm qcom_spmi_adc_tm5 qcom_spmi_adc5 qcom_vadc_common snd_soc_rt5682_i2c venus_enc snd_soc_qcom_common videobuf2_dma_sg snd_soc_rt5682 snd_soc_rl6231 hci_uart btqca bluetooth venus_core ecdh_generic ecc v4l2_mem2mem snd_soc_lpass_sc7180 snd_soc_lpass_hdmi snd_soc_lpass_cpu snd_soc_lpass_platform snd_soc_max98357a
> > fuse iio_trig_sysfs cros_ec_lid_angle cros_ec_sensors cros_ec_sensors_core cros_ec_sensors_ring industrialio_triggered_buffer kfifo_buf cros_ec_sensorhub ath10k_snoc lzo_rle ath10k_core lzo_compress ath zram mac80211 cfg80211 cdc_ether usbnet uvcvideo r8152 mii videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common joydev
> > I suppose it could be surrounded by parenthesis or brackets and that
> > would be a little better? I'll try this approach again and see what
> > folks think.
>
> But you can do:
> Modules linked: module1 [buildidX]
> module2 [buildidY]
> module3 [buildidZ]
> ...
>
> i.o.w. one module per line.
>
> * Yes, I understand that downside maybe split message, so it's just for
> consideration.
>

Yes that's another option. We could put every module on a different
line. That could be over 100 more lines of error message though. That's
probably a bad idea? Or we could print at most 5, 10 or 20 modules per
line. Given that the build id is 20 characters and then 2 brackets, 4 or
5 modules per line comes out to 120 to 150 or so characters per line.

Right now I see this:

WARNING: CPU: 1 PID: 2124 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm]
Modules linked in: vhost_vsock[b5de74de4890f7f9b6c6b9a75bf75cf2b7f828b9] vmw_vsock_virtio_transport_common[939626f71b43da4aab49d0490a3d86da3647f0ec] vsock[edf8bdd739f3bc46d8b9ee00fd5243e0d719aceb] vhost[d2f63a2bc2d33122a520ea624a5ed45709691edc] vhost_iotlb[4042a67c527796e0e2e19b9acd5b38c938e19bf8] lkdtm[6c2215028606bda50de823490723dc4bc5bf46f9] rfcomm[1853b40495371f7bbfdc07d27018693d0a65e32e] algif_hash[d0035cb2ccdd3e20faea6138168f5b3ee7f55027] algif_skcipher[290ded176708249e5f3fe6c20fb2645f46c38c7b] af_alg[9e1891ab46476a7f1252a23b14a8e8fd59026986] xt_cgroup[3b8d96cd8b13e760e88162b441be9ceb98500f75] uinput[3027573e498d509f71b6cb29aa7474bac9fbdba6] uvcvideo[a7676ff139a41297fcc33b80582af3ef68bbdbfa] videobuf2_vmalloc[591709b0f39979156cf3e8b90a61af75da36902a] xt_MASQUERADE[52bbd416ac57cf9c1081cb85ae0dd46fe7c256c7] venus_dec[50bf3f03f8a694acfe61f66dcdac73fde4b08384] videobuf2_dma_sg[a4d4ec21723a234278ddfe27081033ce366e82f4] hci_uart[152d461e1a2a8b5831507fc96fe18cd94391d5db]
videobuf2_memops[3b3feac7d6440b52ac9fde356cc434f98b26f91d] btqca[0f921bc6d55432a7552dbe0677477d81bb44c6e4] bluetooth[8a98be2c3e842b9c1284775096c3d3504d5723e5] ath10k_snoc[525af7ae4d44d0f467980b67769cacaf6d9a5445] cros_ec_typec[9bc93ec5d8d14765642576b24901d5313c5db1b4] venus_core[3cea3f6cd84bdaee7bbce46f58d1eb0bf046763c] typec[e90cdc31cd39d173af46fa3b964215c8d0316534] ecdh_generic[26db794ec69dcbfbabf8dec23c7311ca529dbe6f] qcom_spmi_adc5[5fd6407c665b2af74b8b7d7a7f2ee49e6cec0bdf] ath10k_core[f54f6fd17fb433f83d1c60e32737beba72fbd151] qcom_spmi_temp_alarm[74c703822ed24645942437dda1772bc9cfdc431b] ecc[328c5244919fb66e50bd7319de74a73232d23e42] qcom_vadc_common[bc2afd1da3c27b19cfd96ea70bf23ffd710e2aad] snd_soc_rt5682_i2c[4296e093615aaf4ec303fb605bb4d870f4cf2eb4] snd_soc_rt5682[eb897b37a96eb95bae1581adf4cd0386b224cc4d] v4l2_mem2mem[b4b843c3844f4c492d0e9f89714fb7133e1d3e8c] snd_soc_sc7180[8216abc2f56916ca36e5073b776ed493f1af8e4e]
snd_soc_qcom_common[54fbd61a2f457db385b40ae0a37c5a0719e2a8de] videobuf2_v4l2[d100d30e4b9ad480471dab30494d85d1ae2f4044] snd_soc_lpass_sc7180[aa5e3313ee630c10a1c890213c8777f6365f5ef5] ath[8f4ab51a49478f7955b3a2a95101de0de4bf0864] snd_soc_rl6231[a668e6b9790e698a5f64e3e0e45713adce578de7] videobuf2_common[bd4f81493fa674a6804ecf3244932f5a3e921d5d] snd_soc_lpass_hdmi[90a3aaff7f90ed2086b896bbdd9df09e48e3a6f6] snd_soc_lpass_cpu[c3f3eefc220abcf50857b0c202b0002ebf90a41a] snd_soc_lpass_platform[9a20405ac4e1778db7632aecf68c5cf777dc4254] mac80211[6f6acbb06c6c2c9538c37062bbfa4865708bf66b] snd_soc_max98357a[61ed67be8e6cf3c82da549b30f09c8ec1dbf7270] fuse[3b0043fe3eec1552df28ffc568bf787d75347269] iio_trig_sysfs[43a2fd24bb26966e7faa3f7532193407afb9b1ae] cros_ec_lid_angle[2e7c1c179ab8c9ee76f8abcd6e6139546743cf84] cros_ec_sensors[1bf8ac89e90b6549b9935729882722eda7b924fa] cros_ec_sensors_core[273e9b0a90fbb7066e55023a27f8b6d86371018f] cros_ec_sensors_ring[16ff4eb75deb8bcd81b1ddc5eea1eecf32c7fb14]
industrialio_triggered_buffer[8fe79c5203ccb4f16ed9638554924a42c4a7ec9d] kfifo_buf[c1b3c4d10b52365c3887ba106b3b879c04f96f1d] cfg80211[c4084b0457e32a8408e230cdbc22432ace087c31] cros_ec_sensorhub[e1e51bc2c5324bb000c335ce427263cd17974144] lzo_rle[7c620147cbf701a30e9efa51c176394f2534a2a5] lzo_compress[4fcd02f3181b4d541032ff1f1759d482205e7c5c] zram[bec5be42fb85409cb0776b5d63c1a257b15af2ef] r8152[0a4bcdca4912d965082c8e0f27c2325c3b3e48d3] mii[0e40467221c7b7455a93ceafea794e4ce5c4d09e] joydev[0eabd30a73ec9378792dfb343ed38c2ad5a599bc]
CPU: 1 PID: 2124 Comm: bash Not tainted 5.11 #6 5a995ea7d5d0bd2ed0ccfc90e8c36fcccc04b81b
Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
pc : lkdtm_WARNING+0x28/0x30 [lkdtm]
lr : lkdtm_do_action+0x24/0x40 [lkdtm]
sp : ffffffc013043ca0
x29: ffffffc013043ca0 x28: ffffff987e295540
x27: 0000000000000000 x26: 0000000000000000
x25: 0000000000000000 x24: ffffffe179b7b2c0
x23: 0000000000000020 x22: ffffffe179b79366
x21: ffffffe179b7b2e0 x20: ffffffc013043de0
x19: 0000000000000008 x18: 0000000000000000
x17: ffffff9847b569fc x16: 0000000000000000
x15: 0000000000000000 x14: 0000000000000012
x13: ffffffe1d96d892c x12: ffffffe1da505068
x11: 0000000000000000 x10: 0000000000000000
x9 : 0000000000000001 x8 : ffffffe179b7d000
x7 : aaaaaaaaaaaaaaaa x6 : 0000000000000000
x5 : 0000000000000000 x4 : 0000000000000001
x3 : 0000000000000008 x2 : ffffff99beec5a70
x1 : ffffff99beeb5788 x0 : ffffffe179b7b2e0
Call trace:
lkdtm_WARNING+0x28/0x30 [lkdtm]
direct_entry+0x16c/0x1b4 [lkdtm]
full_proxy_write+0x74/0xa4
vfs_write+0xec/0x2e8
ksys_write+0x84/0xf0
__arm64_sys_write+0x24/0x30
el0_svc_common+0xf4/0x1c0
do_el0_svc_compat+0x28/0x3c
el0_svc_compat+0x10/0x1c
el0_sync_compat_handler+0xa8/0xcc
el0_sync_compat+0x178/0x180
---[ end trace e1c971e4a46de18e ]---

And here's 10 per line with spacing

WARNING: CPU: 0 PID: 2009 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm]
Modules linked in: lkdtm [6c2215028606bda50de823490723dc4bc5bf46f9] rfcomm [1853b40495371f7bbfdc07d27018693d0a65e32e] algif_hash [d0035cb2ccdd3e20faea6138168f5b3ee7f55027] algif_skcipher [290ded176708249e5f3fe6c20fb2645f46c38c7b] af_alg [9e1891ab46476a7f1252a23b14a8e8fd59026986] xt_cgroup [3b8d96cd8b13e760e88162b441be9ceb98500f75] uinput [3027573e498d509f71b6cb29aa7474bac9fbdba6] uvcvideo [a7676ff139a41297fcc33b80582af3ef68bbdbfa] videobuf2_vmalloc [591709b0f39979156cf3e8b90a61af75da36902a] xt_MASQUERADE [52bbd416ac57cf9c1081cb85ae0dd46fe7c256c7]
venus_dec [50bf3f03f8a694acfe61f66dcdac73fde4b08384] videobuf2_dma_sg [a4d4ec21723a234278ddfe27081033ce366e82f4] videobuf2_memops [3b3feac7d6440b52ac9fde356cc434f98b26f91d] hci_uart [152d461e1a2a8b5831507fc96fe18cd94391d5db] btqca [0f921bc6d55432a7552dbe0677477d81bb44c6e4] bluetooth [8a98be2c3e842b9c1284775096c3d3504d5723e5] venus_core [3cea3f6cd84bdaee7bbce46f58d1eb0bf046763c] ath10k_snoc [525af7ae4d44d0f467980b67769cacaf6d9a5445] ecdh_generic [26db794ec69dcbfbabf8dec23c7311ca529dbe6f] v4l2_mem2mem [b4b843c3844f4c492d0e9f89714fb7133e1d3e8c]
videobuf2_v4l2 [d100d30e4b9ad480471dab30494d85d1ae2f4044] cros_ec_typec [9bc93ec5d8d14765642576b24901d5313c5db1b4] ath10k_core [f54f6fd17fb433f83d1c60e32737beba72fbd151] qcom_spmi_adc5 [5fd6407c665b2af74b8b7d7a7f2ee49e6cec0bdf] videobuf2_common [bd4f81493fa674a6804ecf3244932f5a3e921d5d] typec [e90cdc31cd39d173af46fa3b964215c8d0316534] snd_soc_sc7180 [8216abc2f56916ca36e5073b776ed493f1af8e4e] snd_soc_rt5682_i2c [4296e093615aaf4ec303fb605bb4d870f4cf2eb4] ecc [328c5244919fb66e50bd7319de74a73232d23e42] qcom_vadc_common [bc2afd1da3c27b19cfd96ea70bf23ffd710e2aad]
snd_soc_rt5682 [eb897b37a96eb95bae1581adf4cd0386b224cc4d] qcom_spmi_temp_alarm [74c703822ed24645942437dda1772bc9cfdc431b] ath [8f4ab51a49478f7955b3a2a95101de0de4bf0864] snd_soc_qcom_common [54fbd61a2f457db385b40ae0a37c5a0719e2a8de] snd_soc_rl6231 [a668e6b9790e698a5f64e3e0e45713adce578de7] snd_soc_lpass_sc7180 [aa5e3313ee630c10a1c890213c8777f6365f5ef5] snd_soc_lpass_hdmi [90a3aaff7f90ed2086b896bbdd9df09e48e3a6f6] snd_soc_lpass_cpu [c3f3eefc220abcf50857b0c202b0002ebf90a41a] mac80211 [6f6acbb06c6c2c9538c37062bbfa4865708bf66b] snd_soc_lpass_platform [9a20405ac4e1778db7632aecf68c5cf777dc4254]
snd_soc_max98357a [61ed67be8e6cf3c82da549b30f09c8ec1dbf7270] fuse [3b0043fe3eec1552df28ffc568bf787d75347269] cfg80211 [c4084b0457e32a8408e230cdbc22432ace087c31] iio_trig_sysfs [43a2fd24bb26966e7faa3f7532193407afb9b1ae] cros_ec_lid_angle [2e7c1c179ab8c9ee76f8abcd6e6139546743cf84] cros_ec_sensors [1bf8ac89e90b6549b9935729882722eda7b924fa] cros_ec_sensors_core [273e9b0a90fbb7066e55023a27f8b6d86371018f] industrialio_triggered_buffer [8fe79c5203ccb4f16ed9638554924a42c4a7ec9d] cros_ec_sensors_ring [16ff4eb75deb8bcd81b1ddc5eea1eecf32c7fb14] kfifo_buf [c1b3c4d10b52365c3887ba106b3b879c04f96f1d]
cros_ec_sensorhub [e1e51bc2c5324bb000c335ce427263cd17974144] lzo_rle [7c620147cbf701a30e9efa51c176394f2534a2a5] lzo_compress [4fcd02f3181b4d541032ff1f1759d482205e7c5c] zram [bec5be42fb85409cb0776b5d63c1a257b15af2ef] r8152 [0a4bcdca4912d965082c8e0f27c2325c3b3e48d3] mii [0e40467221c7b7455a93ceafea794e4ce5c4d09e] [last unloaded: joydev]
CPU: 0 PID: 2009 Comm: bash Not tainted 5.11 #8 715ebac18cc41a59b9a429ad9273467cba4680ae
Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
pc : lkdtm_WARNING+0x28/0x30 [lkdtm]
lr : lkdtm_do_action+0x24/0x40 [lkdtm]
sp : ffffffc012e9bca0
x29: ffffffc012e9bca0 x28: ffffffbc34fbc440
x27: 0000000000000000 x26: 0000000000000000
x25: 0000000000000000 x24: ffffffdc41c382c0
x23: 0000000000000020 x22: ffffffdc41c36366
x21: ffffffdc41c382e0 x20: ffffffc012e9bde0
x19: 0000000000000008 x18: ffffffbc1bf65618
x17: ffffffbc003cc7fc x16: 0000000000000000
x15: 001d23f6e6650cfa x14: 0000000000000012
x13: ffffffdcad4d892c x12: ffffffdcadef2c94
x11: 0000000000000000 x10: 0000000000000000
x9 : 0000000000000001 x8 : ffffffdc41c3a000
x7 : bbbbbbbbbbbbbbbb x6 : 0000000000000020
x5 : ffffffc010683d40 x4 : 0000000000000001
x3 : 0000000000000008 x2 : ffffffbd7eea5a70
x1 : ffffffbd7ee95788 x0 : ffffffdc41c382e0
Call trace:
lkdtm_WARNING+0x28/0x30 [lkdtm]
direct_entry+0x16c/0x1b4 [lkdtm]
full_proxy_write+0x74/0xa4
vfs_write+0xec/0x2e8
ksys_write+0x84/0xf0
__arm64_sys_write+0x24/0x30
el0_svc_common+0xf4/0x1c0
do_el0_svc_compat+0x28/0x3c
el0_svc_compat+0x10/0x1c
el0_sync_compat_handler+0xa8/0xcc
el0_sync_compat+0x178/0x180
---[ end trace 5f51a26c92780793 ]---

5 looks pretty nice

WARNING: CPU: 2 PID: 3836 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm]
Modules linked in: lkdtm [6c2215028606bda50de823490723dc4bc5bf46f9] vhost_vsock [b5de74de4890f7f9b6c6b9a75bf75cf2b7f828b9] vmw_vsock_virtio_transport_common [939626f71b43da4aab49d0490a3d86da3647f0ec] vsock [edf8bdd739f3bc46d8b9ee00fd5243e0d719aceb] vhost [d2f63a2bc2d33122a520ea624a5ed45709691edc]
vhost_iotlb [4042a67c527796e0e2e19b9acd5b38c938e19bf8] rfcomm [1853b40495371f7bbfdc07d27018693d0a65e32e] algif_hash [d0035cb2ccdd3e20faea6138168f5b3ee7f55027] algif_skcipher [290ded176708249e5f3fe6c20fb2645f46c38c7b] af_alg [9e1891ab46476a7f1252a23b14a8e8fd59026986]
uinput [3027573e498d509f71b6cb29aa7474bac9fbdba6] xt_cgroup [3b8d96cd8b13e760e88162b441be9ceb98500f75] uvcvideo [a7676ff139a41297fcc33b80582af3ef68bbdbfa] videobuf2_vmalloc [591709b0f39979156cf3e8b90a61af75da36902a] xt_MASQUERADE [52bbd416ac57cf9c1081cb85ae0dd46fe7c256c7]
venus_dec [50bf3f03f8a694acfe61f66dcdac73fde4b08384] videobuf2_dma_sg [a4d4ec21723a234278ddfe27081033ce366e82f4] hci_uart [152d461e1a2a8b5831507fc96fe18cd94391d5db] btqca [0f921bc6d55432a7552dbe0677477d81bb44c6e4] videobuf2_memops [3b3feac7d6440b52ac9fde356cc434f98b26f91d]
snd_soc_rt5682_i2c [4296e093615aaf4ec303fb605bb4d870f4cf2eb4] qcom_spmi_temp_alarm [74c703822ed24645942437dda1772bc9cfdc431b] snd_soc_rt5682 [eb897b37a96eb95bae1581adf4cd0386b224cc4d] snd_soc_sc7180 [8216abc2f56916ca36e5073b776ed493f1af8e4e] qcom_spmi_adc5 [5fd6407c665b2af74b8b7d7a7f2ee49e6cec0bdf]
qcom_vadc_common [bc2afd1da3c27b19cfd96ea70bf23ffd710e2aad] bluetooth [8a98be2c3e842b9c1284775096c3d3504d5723e5] snd_soc_qcom_common [54fbd61a2f457db385b40ae0a37c5a0719e2a8de] snd_soc_rl6231 [a668e6b9790e698a5f64e3e0e45713adce578de7] ecdh_generic [26db794ec69dcbfbabf8dec23c7311ca529dbe6f]
ecc [328c5244919fb66e50bd7319de74a73232d23e42] ath10k_snoc [525af7ae4d44d0f467980b67769cacaf6d9a5445] cros_ec_typec [9bc93ec5d8d14765642576b24901d5313c5db1b4] ath10k_core [f54f6fd17fb433f83d1c60e32737beba72fbd151] typec [e90cdc31cd39d173af46fa3b964215c8d0316534]
venus_core [3cea3f6cd84bdaee7bbce46f58d1eb0bf046763c] v4l2_mem2mem [b4b843c3844f4c492d0e9f89714fb7133e1d3e8c] videobuf2_v4l2 [d100d30e4b9ad480471dab30494d85d1ae2f4044] videobuf2_common [bd4f81493fa674a6804ecf3244932f5a3e921d5d] snd_soc_lpass_sc7180 [aa5e3313ee630c10a1c890213c8777f6365f5ef5]
ath [8f4ab51a49478f7955b3a2a95101de0de4bf0864] snd_soc_lpass_hdmi [90a3aaff7f90ed2086b896bbdd9df09e48e3a6f6] snd_soc_lpass_cpu [c3f3eefc220abcf50857b0c202b0002ebf90a41a] snd_soc_lpass_platform [9a20405ac4e1778db7632aecf68c5cf777dc4254] mac80211 [6f6acbb06c6c2c9538c37062bbfa4865708bf66b]
snd_soc_max98357a [61ed67be8e6cf3c82da549b30f09c8ec1dbf7270] fuse [3b0043fe3eec1552df28ffc568bf787d75347269] iio_trig_sysfs [43a2fd24bb26966e7faa3f7532193407afb9b1ae] cfg80211 [c4084b0457e32a8408e230cdbc22432ace087c31] cros_ec_sensors_ring [16ff4eb75deb8bcd81b1ddc5eea1eecf32c7fb14]
cros_ec_lid_angle [2e7c1c179ab8c9ee76f8abcd6e6139546743cf84] cros_ec_sensors [1bf8ac89e90b6549b9935729882722eda7b924fa] cros_ec_sensors_core [273e9b0a90fbb7066e55023a27f8b6d86371018f] industrialio_triggered_buffer [8fe79c5203ccb4f16ed9638554924a42c4a7ec9d] kfifo_buf [c1b3c4d10b52365c3887ba106b3b879c04f96f1d]
cros_ec_sensorhub [e1e51bc2c5324bb000c335ce427263cd17974144] lzo_rle [7c620147cbf701a30e9efa51c176394f2534a2a5] lzo_compress [4fcd02f3181b4d541032ff1f1759d482205e7c5c] zram [bec5be42fb85409cb0776b5d63c1a257b15af2ef] cdc_ether [ced80b6f61771514901ed65242f51b60f2fe762b]
usbnet [6b967ceea5e9faff6f054218e2a7fc4296313688] r8152 [0a4bcdca4912d965082c8e0f27c2325c3b3e48d3] mii [0e40467221c7b7455a93ceafea794e4ce5c4d09e] [last unloaded: joydev]
CPU: 2 PID: 3836 Comm: bash Not tainted 5.11 #9 775145666670b360a22616ad8188bd8edf5dfd36
Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
pc : lkdtm_WARNING+0x28/0x30 [lkdtm]
lr : lkdtm_do_action+0x24/0x40 [lkdtm]
sp : ffffffc01892bca0
x29: ffffffc01892bca0 x28: ffffff9329533340
x27: 0000000000000000 x26: 0000000000000000
x25: 0000000000000000 x24: ffffffe95a2cc2c0
x23: 0000000000000020 x22: ffffffe95a2ca366
x21: ffffffe95a2cc2e0 x20: ffffffc01892bde0
x19: 0000000000000008 x18: 0000000000000000
x17: 0000000000000000 x16: 0000000000000037
x15: ffffffe98d6ab134 x14: 0000000000000003
x13: 0000000000000004 x12: 0000000000000000
x11: 0000000000000000 x10: 0000000000000000
x9 : 0000000000000001 x8 : ffffffe95a2ce000
x7 : 0000000000000000 x6 : ffffffe98e3f6b54
x5 : 0000000000000000 x4 : 0000000000000000
x3 : ffffffc01892b938 x2 : ffffff947eee5a70
x1 : ffffff947eed5788 x0 : ffffffe95a2cc2e0
Call trace:
lkdtm_WARNING+0x28/0x30 [lkdtm]
direct_entry+0x16c/0x1b4 [lkdtm]
full_proxy_write+0x74/0xa4
vfs_write+0xec/0x2e8
ksys_write+0x84/0xf0
__arm64_sys_write+0x24/0x30
el0_svc_common+0xf4/0x1c0
do_el0_svc_compat+0x28/0x3c
el0_svc_compat+0x10/0x1c
el0_sync_compat_handler+0xa8/0xcc
el0_sync_compat+0x178/0x180
---[ end trace afd0105bfc489130 ]---

And the one per line approach

WARNING: CPU: 1 PID: 3402 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm]
Modules linked in: lkdtm [6c2215028606bda50de823490723dc4bc5bf46f9]
rfcomm [1853b40495371f7bbfdc07d27018693d0a65e32e]
algif_hash [d0035cb2ccdd3e20faea6138168f5b3ee7f55027]
algif_skcipher [290ded176708249e5f3fe6c20fb2645f46c38c7b]
af_alg [9e1891ab46476a7f1252a23b14a8e8fd59026986]
xt_cgroup [3b8d96cd8b13e760e88162b441be9ceb98500f75]
uinput [3027573e498d509f71b6cb29aa7474bac9fbdba6]
venus_dec [50bf3f03f8a694acfe61f66dcdac73fde4b08384]
videobuf2_dma_sg [a4d4ec21723a234278ddfe27081033ce366e82f4]
xt_MASQUERADE [52bbd416ac57cf9c1081cb85ae0dd46fe7c256c7]
qcom_spmi_adc5 [5fd6407c665b2af74b8b7d7a7f2ee49e6cec0bdf]
hci_uart [152d461e1a2a8b5831507fc96fe18cd94391d5db]
btqca [0f921bc6d55432a7552dbe0677477d81bb44c6e4]
qcom_spmi_temp_alarm [74c703822ed24645942437dda1772bc9cfdc431b]
qcom_vadc_common [bc2afd1da3c27b19cfd96ea70bf23ffd710e2aad]
bluetooth [8a98be2c3e842b9c1284775096c3d3504d5723e5]
snd_soc_sc7180 [8216abc2f56916ca36e5073b776ed493f1af8e4e]
snd_soc_qcom_common [54fbd61a2f457db385b40ae0a37c5a0719e2a8de]
ecdh_generic [26db794ec69dcbfbabf8dec23c7311ca529dbe6f]
ath10k_snoc [525af7ae4d44d0f467980b67769cacaf6d9a5445]
cros_ec_typec [9bc93ec5d8d14765642576b24901d5313c5db1b4]
typec [e90cdc31cd39d173af46fa3b964215c8d0316534]
snd_soc_rt5682_i2c [4296e093615aaf4ec303fb605bb4d870f4cf2eb4]
ecc [328c5244919fb66e50bd7319de74a73232d23e42]
ath10k_core [f54f6fd17fb433f83d1c60e32737beba72fbd151]
snd_soc_rt5682 [eb897b37a96eb95bae1581adf4cd0386b224cc4d]
venus_core [3cea3f6cd84bdaee7bbce46f58d1eb0bf046763c]
snd_soc_rl6231 [a668e6b9790e698a5f64e3e0e45713adce578de7]
ath [8f4ab51a49478f7955b3a2a95101de0de4bf0864]
v4l2_mem2mem [b4b843c3844f4c492d0e9f89714fb7133e1d3e8c]
snd_soc_lpass_sc7180 [aa5e3313ee630c10a1c890213c8777f6365f5ef5]
mac80211 [6f6acbb06c6c2c9538c37062bbfa4865708bf66b]
snd_soc_lpass_hdmi [90a3aaff7f90ed2086b896bbdd9df09e48e3a6f6]
snd_soc_lpass_cpu [c3f3eefc220abcf50857b0c202b0002ebf90a41a]
snd_soc_lpass_platform [9a20405ac4e1778db7632aecf68c5cf777dc4254]
snd_soc_max98357a [61ed67be8e6cf3c82da549b30f09c8ec1dbf7270]
fuse [3b0043fe3eec1552df28ffc568bf787d75347269]
iio_trig_sysfs [43a2fd24bb26966e7faa3f7532193407afb9b1ae]
cfg80211 [c4084b0457e32a8408e230cdbc22432ace087c31]
cros_ec_lid_angle [2e7c1c179ab8c9ee76f8abcd6e6139546743cf84]
cros_ec_sensors_ring [16ff4eb75deb8bcd81b1ddc5eea1eecf32c7fb14]
cros_ec_sensors [1bf8ac89e90b6549b9935729882722eda7b924fa]
cros_ec_sensors_core [273e9b0a90fbb7066e55023a27f8b6d86371018f]
industrialio_triggered_buffer [8fe79c5203ccb4f16ed9638554924a42c4a7ec9d]
kfifo_buf [c1b3c4d10b52365c3887ba106b3b879c04f96f1d]
cros_ec_sensorhub [e1e51bc2c5324bb000c335ce427263cd17974144]
lzo_rle [7c620147cbf701a30e9efa51c176394f2534a2a5]
lzo_compress [4fcd02f3181b4d541032ff1f1759d482205e7c5c]
zram [bec5be42fb85409cb0776b5d63c1a257b15af2ef]
cdc_ether [ced80b6f61771514901ed65242f51b60f2fe762b]
usbnet [6b967ceea5e9faff6f054218e2a7fc4296313688]
r8152 [0a4bcdca4912d965082c8e0f27c2325c3b3e48d3]
uvcvideo [a7676ff139a41297fcc33b80582af3ef68bbdbfa]
mii [0e40467221c7b7455a93ceafea794e4ce5c4d09e]
videobuf2_vmalloc [591709b0f39979156cf3e8b90a61af75da36902a]
videobuf2_memops [3b3feac7d6440b52ac9fde356cc434f98b26f91d]
videobuf2_v4l2 [d100d30e4b9ad480471dab30494d85d1ae2f4044]
videobuf2_common [bd4f81493fa674a6804ecf3244932f5a3e921d5d]
joydev [0eabd30a73ec9378792dfb343ed38c2ad5a599bc]
CPU: 1 PID: 3402 Comm: bash Not tainted 5.11 #10 03359bc46737cb22e11f0e92cefc7144afedf9c3
Hardware name: Google Lazor (rev3+) with KB Backlight (DT)
pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)
pc : lkdtm_WARNING+0x28/0x30 [lkdtm]
lr : lkdtm_do_action+0x24/0x40 [lkdtm]
sp : ffffffc0125cbca0
x29: ffffffc0125cbca0 x28: ffffffb26a3a8040
x27: 0000000000000000 x26: 0000000000000000
x25: 0000000000000000 x24: ffffffdd7129b2c0
x23: 0000000000000020 x22: ffffffdd71299366
x21: ffffffdd7129b2e0 x20: ffffffc0125cbde0
x19: 0000000000000008 x18: 0000000000000000
x17: 0000000000000000 x16: 0000000000000037
x15: ffffffdd908ab0b4 x14: 0000000000000003
x13: 0000000000000004 x12: 0000000000000000
x11: 0000000000000000 x10: 0000000000000000
x9 : 0000000000000001 x8 : ffffffdd7129d000
x7 : 0000000000000000 x6 : ffffffdd915f6b54
x5 : 0000000000000000 x4 : 0000000000000000
x3 : ffffffc0125cb938 x2 : ffffffb3beec5a70
x1 : ffffffb3beeb5788 x0 : ffffffdd7129b2e0
Call trace:
lkdtm_WARNING+0x28/0x30 [lkdtm]
direct_entry+0x16c/0x1b4 [lkdtm]
full_proxy_write+0x74/0xa4
vfs_write+0xec/0x2e8
ksys_write+0x84/0xf0
__arm64_sys_write+0x24/0x30
el0_svc_common+0xf4/0x1c0
do_el0_svc_compat+0x28/0x3c
el0_svc_compat+0x10/0x1c
el0_sync_compat_handler+0xa8/0xcc
el0_sync_compat+0x178/0x180
---[ end trace de6a15f0c875cfee ]---

2021-03-04 23:58:44

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Petr Mladek (2021-03-03 02:25:58)
> On Mon 2021-03-01 09:47:47, Stephen Boyd wrote:
> > The %pS printk format (among some others) is used to print kernel
> > addresses symbolically. When the kernel prints an address inside of a
> > module, the kernel prints the addresses' symbol name along with the
> > module's name that contains the address. Let's make kernel stacktraces
> > easier to identify on KALLSYMS builds by including the build ID of a
> > module when we print the address.
> >
> > This is especially helpful for crash debugging with pstore or crashdump
> > kernels. If we have the build ID for the module in the stacktrace we can
> > request the debug symbols for the module from a remote debuginfod server
>
> I have read the thread so for. IMHO, all mentioned variants complicate
> the logs a lot. Either the backtrace lines are hard to parse.
> Or the OOps/panic blocks gets too long when the ID is mentioned
> for every loaded module. IMHO, neither proposed solution
> is acceptable to be always used.

The modules line is already pretty hard to read once it gets beyond 8 or
10 modules. Probably it should be broken up into multiple lines just so
it can be read more easily. I find myself having to hunt in there
already even without the build ID encoded there. I've also seen folks
cut out that line in commit text and when posting to the mailing list
because it's just long and noisy already.

>
> First, I think that only I some developers would actually use
> this information. Many of them either know what module was
> used or they do not have an easy way to get the debugging
> information by the ID. So, it should be configurable
> at minimum.

It should be configurable because it isn't used or is hard to use?
Wouldn't a config variable limit the uptake of this information and
further reinforce the fact that nobody will use it? If we always exposed
it then maybe we would get new users. I imagine that we could have a
robot search crash reports and find the "crashiest" places in the kernel
all the way down to the line level and poke kernel developers to look
and see why it crashes so much there. If the information is behind a
config then the benefit of that analysis will be limited.

>
> Second, I am not sure that it should be part of each OOps/panic blob.
> One solution would be to print the ID by the module loader when
> the module gets loaded. It would be mentioned earlier in the log
> then.

Please no. The kernel log could wrap around before an oops/panic happens
and then the ID would be lost.

>
> Or we could make it available, for example, via /proc. It is a kind
> of information that might be gathered later on a rebooted system.
> SUSE has "supportconfig" command that allows to gather a lot
> of similar information about the system. We use it when
> analyzing crashdumps and kernel bugs in general.

Please no. The build ID is already available via
/sys/module/<modulename>/sections/<sectionname> and /sys/kernel/notes
(for vmlinux) but that won't help for panics that reboot. If a panic
happens and a new kernel is booted then post processing on the modules
and vmlinux could all be incorrect. Furthermore, the modules will have
to be found and parsed by some userspace crash processing tool after the
reboot.

I'd really prefer to rely on the standard build ID vs. a per-distro
bespoke solution to finding the information about the binaries the
kernel was running. It's just simpler to not need to find out this sort
of information about the system when the kernel knows what binary is
running already. This is the same reason coredump_filter exists to let
coredumping code figure out the build ID of the process that crashes vs.
connecting that to some system information daemon.

>
> Anyway, I consider this a very detailed information that is not
> suitable for everyone. It should be availabe on request, like
> for example, backtraces from all CPUs, list of tasks, memory info.

I suppose I can make a config option for this module printing stuff in
the "Modules linked in:" line. Then we can remove it if most distros
decide to enable it? I'm slightly disappointed that it can't just be
printed all the time for every stacktrace but if there isn't opposition
if it's all behind a config option then I will be happy to get 99% of
the code upstream.

2021-03-04 23:59:30

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Wed, 03 Mar 2021 16:38:28 -0800
Stephen Boyd <[email protected]> wrote:

> I'm starting to feel like nobody read the commit text, or I messed up
> somehow and the commit text was confusing? :(
>

I read it, I'm just unfamiliar with it. I don't use pstore, and I'm not
sure what "crashdump" is. Do you mean the kexec/kdump? in which case
you can retrieve data within the kernel quite easily.

I haven't used debuginfod (never heard of it before actually).

> │ This is especially helpful for crash debugging with pstore or crashdump
> │ kernels. If we have the build ID for the module in the stacktrace we can
> │ request the debug symbols for the module from a remote debuginfod server
> │ or parse stacktraces at a later time with decode_stacktrace.sh by
> │ downloading the correct symbols based on the build ID. This cuts down on
> │ the amount of time and effort needed to find the correct kernel modules
> │ for a stacktrace by encoding that information into it.

Are you saying it's common to have modules from different builds?

>
> In some distro (read: non-kernel dev) workflows the vmlinux isn't
> shipped on the device and crash handling is done offline or much later.
> Using the build ID[1] is a common way to identify the binary that's
> running on the device. In conjunction with a debuginfod[2] server you
> can download the symbols for a crash automatically if you have the build
> ID information.
>
> I can add a patch that updates decode_stacktrace.sh to show how it can
> download the correct vmlinux/modules if it isn't provided on the
> commandline.

Are you just trying to match modules with the builds that they were
created with?

>
> If the debug symbols are on some public server then in theory we could
> have some robot sitting on the mailing list that looks for stacktraces
> and automatically replies with information about the line number/file
> and even provides the code snippet for the code that's crashing from
> that binary, because it's all stored in the full debuginfo builds.

Again, I have no idea how buildids are created or what they are used
for. This is the first time I've even heard about them. I'm all for
helping other people out to make their workflow easier, if it doesn't
make a mess for everyone else.

-- Steve

2021-03-05 00:53:00

by Matthew Wilcox

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Mon, Mar 01, 2021 at 09:47:47AM -0800, Stephen Boyd wrote:
> Example:
>
> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)

Would the first 12 characters instead of all 40 make it more palatable
without reducing its utility?
And I feel it should be within the [], so maybe this:

WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm ed5019fdf5e5]

2021-03-05 00:54:06

by Matthew Wilcox

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On Mon, Mar 01, 2021 at 09:43:19PM -0500, Steven Rostedt wrote:
> On Mon, 1 Mar 2021 09:47:47 -0800
> Stephen Boyd <[email protected]> wrote:
>
> > The %pS printk format (among some others) is used to print kernel
> > addresses symbolically. When the kernel prints an address inside of a
> > module, the kernel prints the addresses' symbol name along with the
> > module's name that contains the address. Let's make kernel stacktraces
> > easier to identify on KALLSYMS builds by including the build ID of a
> > module when we print the address.
>
> Please no!
>
> This kills the output of tracing with offset, and can possibly break
> scripts. I don't want to look at traces like this!
>
> <idle>-0 [004] ..s1 353.842577: ipv4_conntrack_in+0x0/0x10 [nf_conntrack] (3b39eb771b2566331887f671c741f90bfba0b051) <-nf_hook_slow+0x40/0xb0

Would it make sense to only print the build-id if it differs from the
build-id of the kernel which has loaded it?

2021-03-05 01:03:23

by Rasmus Villemoes

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

On 04/03/2021 20.15, Stephen Boyd wrote:
> Quoting Matthew Wilcox (2021-03-04 09:00:52)
>> On Mon, Mar 01, 2021 at 09:47:47AM -0800, Stephen Boyd wrote:
>>> Example:
>>>
>>> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
>>
>> Would the first 12 characters instead of all 40 make it more palatable
>> without reducing its utility?
>
> I can't seem to request debuginfo from debuginfod without the full 40
> characters. It's not a git sha1 hash.
>
>> And I feel it should be within the [], so maybe this:
>>
>> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm ed5019fdf5e5]
>>
>
> Sure I could put the hex numbers inside the brackets. I suspect changing
> %pS or updating the "Modules linked in:" line isn't going to be
> palatable. I've decided to introduce another printk format %pT to print
> the stacktrace

Can you avoid claiming a new "top-level" %p modifier? Isn't it better to
add a new flag to '%pS', say '%pSb' to include build-id?

Rasmus

2021-03-05 04:22:15

by Stephen Boyd

[permalink] [raw]
Subject: Re: [PATCH 5/7] printk: Make %pS and friends print module build ID

Quoting Rasmus Villemoes (2021-03-04 15:11:47)
> On 04/03/2021 20.15, Stephen Boyd wrote:
> > Quoting Matthew Wilcox (2021-03-04 09:00:52)
> >> On Mon, Mar 01, 2021 at 09:47:47AM -0800, Stephen Boyd wrote:
> >>> Example:
> >>>
> >>> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm] (ed5019fdf5e53be37cb1ba7899292d7e143b259e)
> >>
> >> Would the first 12 characters instead of all 40 make it more palatable
> >> without reducing its utility?
> >
> > I can't seem to request debuginfo from debuginfod without the full 40
> > characters. It's not a git sha1 hash.
> >
> >> And I feel it should be within the [], so maybe this:
> >>
> >> WARNING: CPU: 4 PID: 3255 at drivers/misc/lkdtm/bugs.c:83 lkdtm_WARNING+0x28/0x30 [lkdtm ed5019fdf5e5]
> >>
> >
> > Sure I could put the hex numbers inside the brackets. I suspect changing
> > %pS or updating the "Modules linked in:" line isn't going to be
> > palatable. I've decided to introduce another printk format %pT to print
> > the stacktrace
>
> Can you avoid claiming a new "top-level" %p modifier? Isn't it better to
> add a new flag to '%pS', say '%pSb' to include build-id?
>

I see that %pSR is used in alpha for the stacktrace. I guess we can have
%pSb and %pSr then.