From 11e4b63abbe23872b45f325a7c6c8b7f9ff42cad Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Fri, 2 Jul 2021 17:06:57 +0200 Subject: printk/console: Check consistent sequence number when handling race in console_unlock() The standard printk() tries to flush the message to the console immediately. It tries to take the console lock. If the lock is already taken then the current owner is responsible for flushing even the new message. There is a small race window between checking whether a new message is available and releasing the console lock. It is solved by re-checking the state after releasing the console lock. If the check is positive then console_unlock() tries to take the lock again and process the new message as well. The commit 996e966640ddea7b535c ("printk: remove logbuf_lock") causes that console_seq is not longer read atomically. As a result, the re-check might be done with an inconsistent 64-bit index. Solve it by using the last sequence number that has been checked under the console lock. In the worst case, it will take the lock again only to realized that the new message has already been proceed. But it was possible even before. The variable next_seq is marked as __maybe_unused to call down compiler warning when CONFIG_PRINTK is not defined. Fixes: commit 996e966640ddea7b535c ("printk: remove logbuf_lock") Reported-by: kernel test robot # unused next_seq warning Cc: stable@vger.kernel.org # 5.13 Signed-off-by: Petr Mladek Acked-by: Sergey Senozhatsky Reviewed-by: John Ogness Link: https://lore.kernel.org/r/20210702150657.26760-1-pmladek@suse.com --- kernel/printk/printk.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 142a58d124d9..6dad7da8f383 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2545,6 +2545,7 @@ void console_unlock(void) bool do_cond_resched, retry; struct printk_info info; struct printk_record r; + u64 __maybe_unused next_seq; if (console_suspended) { up_console_sem(); @@ -2654,8 +2655,10 @@ skip: cond_resched(); } - console_locked = 0; + /* Get consistent value of the next-to-be-used sequence number. */ + next_seq = console_seq; + console_locked = 0; up_console_sem(); /* @@ -2664,7 +2667,7 @@ skip: * there's a new owner and the console_unlock() from them will do the * flush, no worries. */ - retry = prb_read_valid(prb, console_seq, NULL); + retry = prb_read_valid(prb, next_seq, NULL); printk_safe_exit_irqrestore(flags); if (retry && console_trylock()) -- cgit From 91027d0a7a0e309b94674923dc1b245b709b5c1e Mon Sep 17 00:00:00 2001 From: Chris Down Date: Tue, 15 Jun 2021 17:52:45 +0100 Subject: string_helpers: Escape double quotes in escape_special From an abstract point of view, escape_special's counterpart, unescape_special, already handles the unescaping of blackslashed double quote sequences. As a more practical example, printk indexing is an example case where this is already practically useful. Compare an example with `ESCAPE_SPECIAL | ESCAPE_SPACE`, with quotes not escaped: [root@ktst ~]# grep drivers/pci/pci-stub.c:69 /sys/kernel/debug/printk/index/vmlinux <4> drivers/pci/pci-stub.c:69 pci_stub_init "pci-stub: invalid ID string "%s"\n" ...and the same after this patch: [root@ktst ~]# grep drivers/pci/pci-stub.c:69 /sys/kernel/debug/printk/index/vmlinux <4> drivers/pci/pci-stub.c:69 pci_stub_init "pci-stub: invalid ID string \"%s\"\n" One can of course, alternatively, use ESCAPE_APPEND with a quote in @only, but without this patch quotes are coerced into hex or octal which can hurt readability quite significantly. I've checked uses of ESCAPE_SPECIAL and %pE across the codebase, and I'm pretty confident that this shouldn't affect any stable interfaces. Signed-off-by: Chris Down Reviewed-by: Andy Shevchenko Reviewed-by: Petr Mladek Cc: Rasmus Villemoes Acked-by: Andy Shevchenko Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/af144c5b75e41ce417386253ba2694456bc04118.1623775748.git.chris@chrisdown.name --- lib/string_helpers.c | 4 ++++ lib/test-string_helpers.c | 14 +++++++------- 2 files changed, 11 insertions(+), 7 deletions(-) diff --git a/lib/string_helpers.c b/lib/string_helpers.c index 5a35c7e16e96..3806a52ce697 100644 --- a/lib/string_helpers.c +++ b/lib/string_helpers.c @@ -361,6 +361,9 @@ static bool escape_special(unsigned char c, char **dst, char *end) case '\e': to = 'e'; break; + case '"': + to = '"'; + break; default: return false; } @@ -474,6 +477,7 @@ static bool escape_hex(unsigned char c, char **dst, char *end) * '\t' - horizontal tab * '\v' - vertical tab * %ESCAPE_SPECIAL: + * '\"' - double quote * '\\' - backslash * '\a' - alert (BEL) * '\e' - escape diff --git a/lib/test-string_helpers.c b/lib/test-string_helpers.c index 2185d71704f0..437d8e6b7cb1 100644 --- a/lib/test-string_helpers.c +++ b/lib/test-string_helpers.c @@ -140,13 +140,13 @@ static const struct test_string_2 escape0[] __initconst = {{ },{ .in = "\\h\\\"\a\e\\", .s1 = {{ - .out = "\\\\h\\\\\"\\a\\e\\\\", + .out = "\\\\h\\\\\\\"\\a\\e\\\\", .flags = ESCAPE_SPECIAL, },{ - .out = "\\\\\\150\\\\\\042\\a\\e\\\\", + .out = "\\\\\\150\\\\\\\"\\a\\e\\\\", .flags = ESCAPE_SPECIAL | ESCAPE_OCTAL, },{ - .out = "\\\\\\x68\\\\\\x22\\a\\e\\\\", + .out = "\\\\\\x68\\\\\\\"\\a\\e\\\\", .flags = ESCAPE_SPECIAL | ESCAPE_HEX, },{ /* terminator */ @@ -157,10 +157,10 @@ static const struct test_string_2 escape0[] __initconst = {{ .out = "\eb \\C\007\"\x90\\r]", .flags = ESCAPE_SPACE, },{ - .out = "\\eb \\\\C\\a\"\x90\r]", + .out = "\\eb \\\\C\\a\\\"\x90\r]", .flags = ESCAPE_SPECIAL, },{ - .out = "\\eb \\\\C\\a\"\x90\\r]", + .out = "\\eb \\\\C\\a\\\"\x90\\r]", .flags = ESCAPE_SPACE | ESCAPE_SPECIAL, },{ .out = "\\033\\142\\040\\134\\103\\007\\042\\220\\015\\135", @@ -169,10 +169,10 @@ static const struct test_string_2 escape0[] __initconst = {{ .out = "\\033\\142\\040\\134\\103\\007\\042\\220\\r\\135", .flags = ESCAPE_SPACE | ESCAPE_OCTAL, },{ - .out = "\\e\\142\\040\\\\\\103\\a\\042\\220\\015\\135", + .out = "\\e\\142\\040\\\\\\103\\a\\\"\\220\\015\\135", .flags = ESCAPE_SPECIAL | ESCAPE_OCTAL, },{ - .out = "\\e\\142\\040\\\\\\103\\a\\042\\220\\r\\135", + .out = "\\e\\142\\040\\\\\\103\\a\\\"\\220\\r\\135", .flags = ESCAPE_SPACE | ESCAPE_SPECIAL | ESCAPE_OCTAL, },{ .out = "\eb \\C\007\"\x90\r]", -- cgit From a1ad4b8a19566b11e0306f8b197f2fd4567340e5 Mon Sep 17 00:00:00 2001 From: Chris Down Date: Tue, 15 Jun 2021 17:52:48 +0100 Subject: printk: Straighten out log_flags into printk_info_flags In the past, `enum log_flags` was part of `struct log`, hence the name. `struct log` has since been reworked and now this struct is stored inside `struct printk_info`. However, the name was never updated, which is somewhat confusing -- especially since these flags operate at the record level rather than at the level of an abstract log. printk_info_flags also joins its other metadata struct friends in printk_ringbuffer.h. Signed-off-by: Chris Down Reviewed-by: Petr Mladek Acked-by: Andy Shevchenko Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/3dd801982f02603e6e3aa4f8bc4f5ebb830a4949.1623775748.git.chris@chrisdown.name --- kernel/printk/internal.h | 6 ++++++ kernel/printk/printk.c | 43 ++++++++++++++++++++----------------------- 2 files changed, 26 insertions(+), 23 deletions(-) diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 51615c909b2f..1075e60fcd98 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -12,6 +12,12 @@ #define PRINTK_NMI_CONTEXT_OFFSET 0x010000000 +/* Flags for a single printk record. */ +enum printk_info_flags { + LOG_NEWLINE = 2, /* text ended with a newline */ + LOG_CONT = 8, /* text is a fragment of a continuation line */ +}; + __printf(4, 0) int vprintk_store(int facility, int level, const struct dev_printk_info *dev_info, diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 142a58d124d9..39f1ec22a6a6 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -350,11 +350,6 @@ static int console_msg_format = MSG_FORMAT_DEFAULT; * non-prinatable characters are escaped in the "\xff" notation. */ -enum log_flags { - LOG_NEWLINE = 2, /* text ended with a newline */ - LOG_CONT = 8, /* text is a fragment of a continuation line */ -}; - /* syslog_lock protects syslog_* variables and write access to clear_seq. */ static DEFINE_RAW_SPINLOCK(syslog_lock); @@ -1965,19 +1960,20 @@ static inline u32 printk_caller_id(void) * * @text: The terminated text message. * @level: A pointer to the current level value, will be updated. - * @lflags: A pointer to the current log flags, will be updated. + * @flags: A pointer to the current printk_info flags, will be updated. * * @level may be NULL if the caller is not interested in the parsed value. * Otherwise the variable pointed to by @level must be set to * LOGLEVEL_DEFAULT in order to be updated with the parsed value. * - * @lflags may be NULL if the caller is not interested in the parsed value. - * Otherwise the variable pointed to by @lflags will be OR'd with the parsed + * @flags may be NULL if the caller is not interested in the parsed value. + * Otherwise the variable pointed to by @flags will be OR'd with the parsed * value. * * Return: The length of the parsed level and control flags. */ -static u16 parse_prefix(char *text, int *level, enum log_flags *lflags) +static u16 parse_prefix(char *text, int *level, + enum printk_info_flags *flags) { u16 prefix_len = 0; int kern_level; @@ -1993,8 +1989,8 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags) *level = kern_level - '0'; break; case 'c': /* KERN_CONT */ - if (lflags) - *lflags |= LOG_CONT; + if (flags) + *flags |= LOG_CONT; } prefix_len += 2; @@ -2004,8 +2000,9 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags) return prefix_len; } -static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags, - const char *fmt, va_list args) +static u16 printk_sprint(char *text, u16 size, int facility, + enum printk_info_flags *flags, const char *fmt, + va_list args) { u16 text_len; @@ -2014,7 +2011,7 @@ static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lfl /* Mark and strip a trailing newline. */ if (text_len && text[text_len - 1] == '\n') { text_len--; - *lflags |= LOG_NEWLINE; + *flags |= LOG_NEWLINE; } /* Strip log level and control flags. */ @@ -2038,7 +2035,7 @@ int vprintk_store(int facility, int level, { const u32 caller_id = printk_caller_id(); struct prb_reserved_entry e; - enum log_flags lflags = 0; + enum printk_info_flags flags = 0; struct printk_record r; u16 trunc_msg_len = 0; char prefix_buf[8]; @@ -2070,22 +2067,22 @@ int vprintk_store(int facility, int level, /* Extract log level or control flags. */ if (facility == 0) - parse_prefix(&prefix_buf[0], &level, &lflags); + parse_prefix(&prefix_buf[0], &level, &flags); if (level == LOGLEVEL_DEFAULT) level = default_message_loglevel; if (dev_info) - lflags |= LOG_NEWLINE; + flags |= LOG_NEWLINE; - if (lflags & LOG_CONT) { + if (flags & LOG_CONT) { prb_rec_init_wr(&r, reserve_size); if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) { text_len = printk_sprint(&r.text_buf[r.info->text_len], reserve_size, - facility, &lflags, fmt, args); + facility, &flags, fmt, args); r.info->text_len += text_len; - if (lflags & LOG_NEWLINE) { + if (flags & LOG_NEWLINE) { r.info->flags |= LOG_NEWLINE; prb_final_commit(&e); } else { @@ -2112,20 +2109,20 @@ int vprintk_store(int facility, int level, } /* fill message */ - text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &lflags, fmt, args); + text_len = printk_sprint(&r.text_buf[0], reserve_size, facility, &flags, fmt, args); if (trunc_msg_len) memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len); r.info->text_len = text_len + trunc_msg_len; r.info->facility = facility; r.info->level = level & 7; - r.info->flags = lflags & 0x1f; + r.info->flags = flags & 0x1f; r.info->ts_nsec = ts_nsec; r.info->caller_id = caller_id; if (dev_info) memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info)); /* A message without a trailing newline can be continued. */ - if (!(lflags & LOG_NEWLINE)) + if (!(flags & LOG_NEWLINE)) prb_commit(&e); else prb_final_commit(&e); -- cgit From f3d75cf537db57f7918a17a75527951de850e5ec Mon Sep 17 00:00:00 2001 From: Chris Down Date: Tue, 15 Jun 2021 17:52:51 +0100 Subject: printk: Rework parse_prefix into printk_parse_prefix parse_prefix is needed externally by later patches, so move it into a context where it can be used as such. Also give it the printk_ prefix to reduce the chance of collisions. Signed-off-by: Chris Down Cc: Petr Mladek Reviewed-by: Petr Mladek Acked-by: Andy Shevchenko Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/b22ba314a860e5c7f887958f1eab2649f9bd1d06.1623775748.git.chris@chrisdown.name --- kernel/printk/internal.h | 2 ++ kernel/printk/printk.c | 8 ++++---- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 1075e60fcd98..1596e2837318 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -57,6 +57,8 @@ bool printk_percpu_data_ready(void); void defer_console_output(void); +u16 printk_parse_prefix(const char *text, int *level, + enum printk_info_flags *flags); #else /* diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 39f1ec22a6a6..03956c3eb745 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1956,7 +1956,7 @@ static inline u32 printk_caller_id(void) } /** - * parse_prefix - Parse level and control flags. + * printk_parse_prefix - Parse level and control flags. * * @text: The terminated text message. * @level: A pointer to the current level value, will be updated. @@ -1972,7 +1972,7 @@ static inline u32 printk_caller_id(void) * * Return: The length of the parsed level and control flags. */ -static u16 parse_prefix(char *text, int *level, +u16 printk_parse_prefix(const char *text, int *level, enum printk_info_flags *flags) { u16 prefix_len = 0; @@ -2018,7 +2018,7 @@ static u16 printk_sprint(char *text, u16 size, int facility, if (facility == 0) { u16 prefix_len; - prefix_len = parse_prefix(text, NULL, NULL); + prefix_len = printk_parse_prefix(text, NULL, NULL); if (prefix_len) { text_len -= prefix_len; memmove(text, text + prefix_len, text_len); @@ -2067,7 +2067,7 @@ int vprintk_store(int facility, int level, /* Extract log level or control flags. */ if (facility == 0) - parse_prefix(&prefix_buf[0], &level, &flags); + printk_parse_prefix(&prefix_buf[0], &level, &flags); if (level == LOGLEVEL_DEFAULT) level = default_message_loglevel; -- cgit From 337015573718b161891a3473d25f59273f2e626b Mon Sep 17 00:00:00 2001 From: Chris Down Date: Tue, 15 Jun 2021 17:52:53 +0100 Subject: printk: Userspace format indexing support We have a number of systems industry-wide that have a subset of their functionality that works as follows: 1. Receive a message from local kmsg, serial console, or netconsole; 2. Apply a set of rules to classify the message; 3. Do something based on this classification (like scheduling a remediation for the machine), rinse, and repeat. As a couple of examples of places we have this implemented just inside Facebook, although this isn't a Facebook-specific problem, we have this inside our netconsole processing (for alarm classification), and as part of our machine health checking. We use these messages to determine fairly important metrics around production health, and it's important that we get them right. While for some kinds of issues we have counters, tracepoints, or metrics with a stable interface which can reliably indicate the issue, in order to react to production issues quickly we need to work with the interface which most kernel developers naturally use when developing: printk. Most production issues come from unexpected phenomena, and as such usually the code in question doesn't have easily usable tracepoints or other counters available for the specific problem being mitigated. We have a number of lines of monitoring defence against problems in production (host metrics, process metrics, service metrics, etc), and where it's not feasible to reliably monitor at another level, this kind of pragmatic netconsole monitoring is essential. As one would expect, monitoring using printk is rather brittle for a number of reasons -- most notably that the message might disappear entirely in a new version of the kernel, or that the message may change in some way that the regex or other classification methods start to silently fail. One factor that makes this even harder is that, under normal operation, many of these messages are never expected to be hit. For example, there may be a rare hardware bug which one wants to detect if it was to ever happen again, but its recurrence is not likely or anticipated. This precludes using something like checking whether the printk in question was printed somewhere fleetwide recently to determine whether the message in question is still present or not, since we don't anticipate that it should be printed anywhere, but still need to monitor for its future presence in the long-term. This class of issue has happened on a number of occasions, causing unhealthy machines with hardware issues to remain in production for longer than ideal. As a recent example, some monitoring around blk_update_request fell out of date and caused semi-broken machines to remain in production for longer than would be desirable. Searching through the codebase to find the message is also extremely fragile, because many of the messages are further constructed beyond their callsite (eg. btrfs_printk and other module-specific wrappers, each with their own functionality). Even if they aren't, guessing the format and formulation of the underlying message based on the aesthetics of the message emitted is not a recipe for success at scale, and our previous issues with fleetwide machine health checking demonstrate as much. This provides a solution to the issue of silently changed or deleted printks: we record pointers to all printk format strings known at compile time into a new .printk_index section, both in vmlinux and modules. At runtime, this can then be iterated by looking at /printk/index/, which emits the following format, both readable by humans and able to be parsed by machines: $ head -1 vmlinux; shuf -n 5 vmlinux # filename:line function "format" <5> block/blk-settings.c:661 disk_stack_limits "%s: Warning: Device %s is misaligned\n" <4> kernel/trace/trace.c:8296 trace_create_file "Could not create tracefs '%s' entry\n" <6> arch/x86/kernel/hpet.c:144 _hpet_print_config "hpet: %s(%d):\n" <6> init/do_mounts.c:605 prepare_namespace "Waiting for root device %s...\n" <6> drivers/acpi/osl.c:1410 acpi_no_auto_serialize_setup "ACPI: auto-serialization disabled\n" This mitigates the majority of cases where we have a highly-specific printk which we want to match on, as we can now enumerate and check whether the format changed or the printk callsite disappeared entirely in userspace. This allows us to catch changes to printks we monitor earlier and decide what to do about it before it becomes problematic. There is no additional runtime cost for printk callers or printk itself, and the assembly generated is exactly the same. Signed-off-by: Chris Down Cc: Petr Mladek Cc: Jessica Yu Cc: Sergey Senozhatsky Cc: John Ogness Cc: Steven Rostedt Cc: Greg Kroah-Hartman Cc: Johannes Weiner Cc: Kees Cook Reviewed-by: Petr Mladek Tested-by: Petr Mladek Reported-by: kernel test robot Acked-by: Andy Shevchenko Acked-by: Jessica Yu # for module.{c,h} Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/e42070983637ac5e384f17fbdbe86d19c7b212a5.1623775748.git.chris@chrisdown.name --- MAINTAINERS | 5 + arch/arm/kernel/entry-v7m.S | 2 +- arch/arm/lib/backtrace-clang.S | 2 +- arch/arm/lib/backtrace.S | 2 +- arch/arm/mach-rpc/io-acorn.S | 2 +- arch/arm/vfp/vfphw.S | 6 +- arch/ia64/include/uapi/asm/cmpxchg.h | 4 +- arch/openrisc/kernel/entry.S | 6 +- arch/powerpc/kernel/head_fsl_booke.S | 2 +- arch/um/include/shared/user.h | 3 +- arch/x86/kernel/head_32.S | 2 +- include/asm-generic/vmlinux.lds.h | 13 +++ include/linux/module.h | 5 + include/linux/printk.h | 95 ++++++++++++++++- init/Kconfig | 14 +++ kernel/module.c | 5 + kernel/printk/Makefile | 1 + kernel/printk/index.c | 195 +++++++++++++++++++++++++++++++++++ kernel/printk/printk.c | 13 ++- 19 files changed, 353 insertions(+), 24 deletions(-) create mode 100644 kernel/printk/index.c diff --git a/MAINTAINERS b/MAINTAINERS index a61f4f3b78a9..a19a104e0cc4 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -14918,6 +14918,11 @@ S: Maintained F: include/linux/printk.h F: kernel/printk/ +PRINTK INDEXING +R: Chris Down +S: Maintained +F: kernel/printk/index.c + PRISM54 WIRELESS DRIVER M: Luis Chamberlain L: linux-wireless@vger.kernel.org diff --git a/arch/arm/kernel/entry-v7m.S b/arch/arm/kernel/entry-v7m.S index d0e898608d30..7bde93c10962 100644 --- a/arch/arm/kernel/entry-v7m.S +++ b/arch/arm/kernel/entry-v7m.S @@ -23,7 +23,7 @@ __invalid_entry: adr r0, strerr mrs r1, ipsr mov r2, lr - bl printk + bl _printk #endif mov r0, sp bl show_regs diff --git a/arch/arm/lib/backtrace-clang.S b/arch/arm/lib/backtrace-clang.S index 6174c45f53a5..5b2cdb1003e3 100644 --- a/arch/arm/lib/backtrace-clang.S +++ b/arch/arm/lib/backtrace-clang.S @@ -202,7 +202,7 @@ finished_setup: 1006: adr r0, .Lbad mov r1, loglvl mov r2, frame - bl printk + bl _printk no_frame: ldmfd sp!, {r4 - r9, fp, pc} ENDPROC(c_backtrace) .pushsection __ex_table,"a" diff --git a/arch/arm/lib/backtrace.S b/arch/arm/lib/backtrace.S index 872f658638d9..e8408f22d4dc 100644 --- a/arch/arm/lib/backtrace.S +++ b/arch/arm/lib/backtrace.S @@ -103,7 +103,7 @@ for_each_frame: tst frame, mask @ Check for address exceptions 1006: adr r0, .Lbad mov r1, loglvl mov r2, frame - bl printk + bl _printk no_frame: ldmfd sp!, {r4 - r9, pc} ENDPROC(c_backtrace) diff --git a/arch/arm/mach-rpc/io-acorn.S b/arch/arm/mach-rpc/io-acorn.S index b9082a2a2a01..aa9bf0d771c0 100644 --- a/arch/arm/mach-rpc/io-acorn.S +++ b/arch/arm/mach-rpc/io-acorn.S @@ -25,4 +25,4 @@ ENTRY(insl) ENTRY(outsl) adr r0, .Liosl_warning mov r1, lr - b printk + b _printk diff --git a/arch/arm/vfp/vfphw.S b/arch/arm/vfp/vfphw.S index d5837bf05a9a..6f7926c9c179 100644 --- a/arch/arm/vfp/vfphw.S +++ b/arch/arm/vfp/vfphw.S @@ -23,7 +23,7 @@ #ifdef DEBUG stmfd sp!, {r0-r3, ip, lr} ldr r0, =1f - bl printk + bl _printk ldmfd sp!, {r0-r3, ip, lr} .pushsection .rodata, "a" @@ -38,7 +38,7 @@ stmfd sp!, {r0-r3, ip, lr} mov r1, \arg ldr r0, =1f - bl printk + bl _printk ldmfd sp!, {r0-r3, ip, lr} .pushsection .rodata, "a" @@ -55,7 +55,7 @@ mov r2, \arg2 mov r1, \arg1 ldr r0, =1f - bl printk + bl _printk ldmfd sp!, {r0-r3, ip, lr} .pushsection .rodata, "a" diff --git a/arch/ia64/include/uapi/asm/cmpxchg.h b/arch/ia64/include/uapi/asm/cmpxchg.h index 926c6cb1e029..2c2f3cfeaa77 100644 --- a/arch/ia64/include/uapi/asm/cmpxchg.h +++ b/arch/ia64/include/uapi/asm/cmpxchg.h @@ -143,9 +143,9 @@ extern long ia64_cmpxchg_called_with_bad_pointer(void); do { \ if (_cmpxchg_bugcheck_count-- <= 0) { \ void *ip; \ - extern int printk(const char *fmt, ...); \ + extern int _printk(const char *fmt, ...); \ ip = (void *) ia64_getreg(_IA64_REG_IP); \ - printk("CMPXCHG_BUGCHECK: stuck at %p on word %p\n", ip, (v));\ + _printk("CMPXCHG_BUGCHECK: stuck at %p on word %p\n", ip, (v));\ break; \ } \ } while (0) diff --git a/arch/openrisc/kernel/entry.S b/arch/openrisc/kernel/entry.S index bc657e55c15f..947613f61d4a 100644 --- a/arch/openrisc/kernel/entry.S +++ b/arch/openrisc/kernel/entry.S @@ -551,7 +551,7 @@ EXCEPTION_ENTRY(_external_irq_handler) l.movhi r3,hi(42f) l.ori r3,r3,lo(42f) l.sw 0x0(r1),r3 - l.jal printk + l.jal _printk l.sw 0x4(r1),r4 l.addi r1,r1,0x8 @@ -681,8 +681,8 @@ _syscall_debug: l.sw -4(r1),r27 l.sw -8(r1),r11 l.addi r1,r1,-8 - l.movhi r27,hi(printk) - l.ori r27,r27,lo(printk) + l.movhi r27,hi(_printk) + l.ori r27,r27,lo(_printk) l.jalr r27 l.nop l.addi r1,r1,8 diff --git a/arch/powerpc/kernel/head_fsl_booke.S b/arch/powerpc/kernel/head_fsl_booke.S index 0f9642f36b49..9a2f4265e6d2 100644 --- a/arch/powerpc/kernel/head_fsl_booke.S +++ b/arch/powerpc/kernel/head_fsl_booke.S @@ -858,7 +858,7 @@ KernelSPE: ori r3,r3,87f@l mr r4,r2 /* current */ lwz r5,_NIP(r1) - bl printk + bl _printk #endif b interrupt_return #ifdef CONFIG_PRINTK diff --git a/arch/um/include/shared/user.h b/arch/um/include/shared/user.h index e793e4212f0a..dd4badffdeb3 100644 --- a/arch/um/include/shared/user.h +++ b/arch/um/include/shared/user.h @@ -38,7 +38,8 @@ extern void panic(const char *fmt, ...) #define UM_KERN_CONT KERN_CONT #ifdef UML_CONFIG_PRINTK -extern int printk(const char *fmt, ...) +#define printk(...) _printk(__VA_ARGS__) +extern int _printk(const char *fmt, ...) __attribute__ ((format (printf, 1, 2))); #else static inline int printk(const char *fmt, ...) diff --git a/arch/x86/kernel/head_32.S b/arch/x86/kernel/head_32.S index 67f590425d90..d8c64dab0efe 100644 --- a/arch/x86/kernel/head_32.S +++ b/arch/x86/kernel/head_32.S @@ -432,7 +432,7 @@ SYM_FUNC_START(early_ignore_irq) pushl 32(%esp) pushl 40(%esp) pushl $int_msg - call printk + call _printk call dump_stack diff --git a/include/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h index 17325416e2de..ddb2ff158321 100644 --- a/include/asm-generic/vmlinux.lds.h +++ b/include/asm-generic/vmlinux.lds.h @@ -483,6 +483,8 @@ \ TRACEDATA \ \ + PRINTK_INDEX \ + \ /* Kernel symbol table: Normal symbols */ \ __ksymtab : AT(ADDR(__ksymtab) - LOAD_OFFSET) { \ __start___ksymtab = .; \ @@ -893,6 +895,17 @@ #define TRACEDATA #endif +#ifdef CONFIG_PRINTK_INDEX +#define PRINTK_INDEX \ + .printk_index : AT(ADDR(.printk_index) - LOAD_OFFSET) { \ + __start_printk_index = .; \ + *(.printk_index) \ + __stop_printk_index = .; \ + } +#else +#define PRINTK_INDEX +#endif + #define NOTES \ .notes : AT(ADDR(.notes) - LOAD_OFFSET) { \ __start_notes = .; \ diff --git a/include/linux/module.h b/include/linux/module.h index 8a298d820dbc..c9f1200b2312 100644 --- a/include/linux/module.h +++ b/include/linux/module.h @@ -511,6 +511,11 @@ struct module { struct klp_modinfo *klp_info; #endif +#ifdef CONFIG_PRINTK_INDEX + unsigned int printk_index_size; + struct pi_entry **printk_index_start; +#endif + #ifdef CONFIG_MODULE_UNLOAD /* What modules depend on me? */ struct list_head source_list; diff --git a/include/linux/printk.h b/include/linux/printk.h index e834d78f0478..2651b82ed352 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -174,12 +174,12 @@ asmlinkage __printf(1, 0) int vprintk(const char *fmt, va_list args); asmlinkage __printf(1, 2) __cold -int printk(const char *fmt, ...); +int _printk(const char *fmt, ...); /* * Special printk facility for scheduler/timekeeping use only, _DO_NOT_USE_ ! */ -__printf(1, 2) __cold int printk_deferred(const char *fmt, ...); +__printf(1, 2) __cold int _printk_deferred(const char *fmt, ...); /* * Please don't use printk_ratelimit(), because it shares ratelimiting state @@ -218,12 +218,12 @@ int vprintk(const char *s, va_list args) return 0; } static inline __printf(1, 2) __cold -int printk(const char *s, ...) +int _printk(const char *s, ...) { return 0; } static inline __printf(1, 2) __cold -int printk_deferred(const char *s, ...) +int _printk_deferred(const char *s, ...) { return 0; } @@ -348,6 +348,93 @@ extern int kptr_restrict; #define pr_fmt(fmt) fmt #endif +struct module; + +#ifdef CONFIG_PRINTK_INDEX +struct pi_entry { + const char *fmt; + const char *func; + const char *file; + unsigned int line; + + /* + * While printk and pr_* have the level stored in the string at compile + * time, some subsystems dynamically add it at runtime through the + * format string. For these dynamic cases, we allow the subsystem to + * tell us the level at compile time. + * + * NULL indicates that the level, if any, is stored in fmt. + */ + const char *level; + + /* + * The format string used by various subsystem specific printk() + * wrappers to prefix the message. + * + * Note that the static prefix defined by the pr_fmt() macro is stored + * directly in the message format (@fmt), not here. + */ + const char *subsys_fmt_prefix; +} __packed; + +#define __printk_index_emit(_fmt, _level, _subsys_fmt_prefix) \ + do { \ + if (__builtin_constant_p(_fmt) && __builtin_constant_p(_level)) { \ + /* + * We check __builtin_constant_p multiple times here + * for the same input because GCC will produce an error + * if we try to assign a static variable to fmt if it + * is not a constant, even with the outer if statement. + */ \ + static const struct pi_entry _entry \ + __used = { \ + .fmt = __builtin_constant_p(_fmt) ? (_fmt) : NULL, \ + .func = __func__, \ + .file = __FILE__, \ + .line = __LINE__, \ + .level = __builtin_constant_p(_level) ? (_level) : NULL, \ + .subsys_fmt_prefix = _subsys_fmt_prefix,\ + }; \ + static const struct pi_entry *_entry_ptr \ + __used __section(".printk_index") = &_entry; \ + } \ + } while (0) + +#else /* !CONFIG_PRINTK_INDEX */ +#define __printk_index_emit(...) do {} while (0) +#endif /* CONFIG_PRINTK_INDEX */ + +/* + * Some subsystems have their own custom printk that applies a va_format to a + * generic format, for example, to include a device number or other metadata + * alongside the format supplied by the caller. + * + * In order to store these in the way they would be emitted by the printk + * infrastructure, the subsystem provides us with the start, fixed string, and + * any subsequent text in the format string. + * + * We take a variable argument list as pr_fmt/dev_fmt/etc are sometimes passed + * as multiple arguments (eg: `"%s: ", "blah"`), and we must only take the + * first one. + * + * subsys_fmt_prefix must be known at compile time, or compilation will fail + * (since this is a mistake). If fmt or level is not known at compile time, no + * index entry will be made (since this can legitimately happen). + */ +#define printk_index_subsys_emit(subsys_fmt_prefix, level, fmt, ...) \ + __printk_index_emit(fmt, level, subsys_fmt_prefix) + +#define printk_index_wrap(_p_func, _fmt, ...) \ + ({ \ + __printk_index_emit(_fmt, NULL, NULL); \ + _p_func(_fmt, ##__VA_ARGS__); \ + }) + + +#define printk(fmt, ...) printk_index_wrap(_printk, fmt, ##__VA_ARGS__) +#define printk_deferred(fmt, ...) \ + printk_index_wrap(_printk_deferred, fmt, ##__VA_ARGS__) + /** * pr_emerg - Print an emergency-level message * @fmt: format string diff --git a/init/Kconfig b/init/Kconfig index bb0d6e6262b1..ccffa7ae5ccc 100644 --- a/init/Kconfig +++ b/init/Kconfig @@ -775,6 +775,20 @@ config PRINTK_SAFE_LOG_BUF_SHIFT 13 => 8 KB for each CPU 12 => 4 KB for each CPU +config PRINTK_INDEX + bool "Printk indexing debugfs interface" + depends on PRINTK && DEBUG_FS + help + Add support for indexing of all printk formats known at compile time + at /printk/index/. + + This can be used as part of maintaining daemons which monitor + /dev/kmsg, as it permits auditing the printk formats present in a + kernel, allowing detection of cases where monitored printks are + changed or no longer present. + + There is no additional runtime cost to printk with this enabled. + # # Architectures with an unreliable sched_clock() should select this: # diff --git a/kernel/module.c b/kernel/module.c index ed13917ea5f3..40ec9a030eec 100644 --- a/kernel/module.c +++ b/kernel/module.c @@ -3355,6 +3355,11 @@ static int find_module_sections(struct module *mod, struct load_info *info) sizeof(unsigned long), &mod->num_kprobe_blacklist); #endif +#ifdef CONFIG_PRINTK_INDEX + mod->printk_index_start = section_objs(info, ".printk_index", + sizeof(*mod->printk_index_start), + &mod->printk_index_size); +#endif #ifdef CONFIG_HAVE_STATIC_CALL_INLINE mod->static_call_sites = section_objs(info, ".static_call_sites", sizeof(*mod->static_call_sites), diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile index eee3dc9b60a9..d118739874c0 100644 --- a/kernel/printk/Makefile +++ b/kernel/printk/Makefile @@ -3,3 +3,4 @@ obj-y = printk.o obj-$(CONFIG_PRINTK) += printk_safe.o obj-$(CONFIG_A11Y_BRAILLE_CONSOLE) += braille.o obj-$(CONFIG_PRINTK) += printk_ringbuffer.o +obj-$(CONFIG_PRINTK_INDEX) += index.o diff --git a/kernel/printk/index.c b/kernel/printk/index.c new file mode 100644 index 000000000000..ca062f5e1779 --- /dev/null +++ b/kernel/printk/index.c @@ -0,0 +1,195 @@ +// SPDX-License-Identifier: GPL-2.0 +/* + * Userspace indexing of printk formats + */ + +#include +#include +#include +#include +#include + +#include "internal.h" + +extern struct pi_entry *__start_printk_index[]; +extern struct pi_entry *__stop_printk_index[]; + +/* The base dir for module formats, typically debugfs/printk/index/ */ +static struct dentry *dfs_index; + +static struct pi_entry *pi_get_entry(const struct module *mod, loff_t pos) +{ + struct pi_entry **entries; + unsigned int nr_entries; + +#ifdef CONFIG_MODULES + if (mod) { + entries = mod->printk_index_start; + nr_entries = mod->printk_index_size; + } +#endif + + if (!mod) { + /* vmlinux, comes from linker symbols */ + entries = __start_printk_index; + nr_entries = __stop_printk_index - __start_printk_index; + } + + if (pos >= nr_entries) + return NULL; + + return entries[pos]; +} + +static void *pi_next(struct seq_file *s, void *v, loff_t *pos) +{ + const struct module *mod = s->file->f_inode->i_private; + struct pi_entry *entry = pi_get_entry(mod, *pos); + + (*pos)++; + + return entry; +} + +static void *pi_start(struct seq_file *s, loff_t *pos) +{ + /* + * Make show() print the header line. Do not update *pos because + * pi_next() still has to return the entry at index 0 later. + */ + if (*pos == 0) + return SEQ_START_TOKEN; + + return pi_next(s, NULL, pos); +} + +/* + * We need both ESCAPE_ANY and explicit characters from ESCAPE_SPECIAL in @only + * because otherwise ESCAPE_NAP will cause double quotes and backslashes to be + * ignored for quoting. + */ +#define seq_escape_printf_format(s, src) \ + seq_escape_str(s, src, ESCAPE_ANY | ESCAPE_NAP | ESCAPE_APPEND, "\"\\") + +static int pi_show(struct seq_file *s, void *v) +{ + const struct pi_entry *entry = v; + int level = LOGLEVEL_DEFAULT; + enum printk_info_flags flags = 0; + u16 prefix_len = 0; + + if (v == SEQ_START_TOKEN) { + seq_puts(s, "# filename:line function \"format\"\n"); + return 0; + } + + if (!entry->fmt) + return 0; + + if (entry->level) + printk_parse_prefix(entry->level, &level, &flags); + else + prefix_len = printk_parse_prefix(entry->fmt, &level, &flags); + + + if (flags & LOG_CONT) { + /* + * LOGLEVEL_DEFAULT here means "use the same level as the + * message we're continuing from", not the default message + * loglevel, so don't display it as such. + */ + if (level == LOGLEVEL_DEFAULT) + seq_puts(s, ""); + else + seq_printf(s, "<%d,c>", level); + } else + seq_printf(s, "<%d>", level); + + seq_printf(s, " %s:%d %s \"", entry->file, entry->line, entry->func); + if (entry->subsys_fmt_prefix) + seq_escape_printf_format(s, entry->subsys_fmt_prefix); + seq_escape_printf_format(s, entry->fmt + prefix_len); + seq_puts(s, "\"\n"); + + return 0; +} + +static void pi_stop(struct seq_file *p, void *v) { } + +static const struct seq_operations dfs_index_sops = { + .start = pi_start, + .next = pi_next, + .show = pi_show, + .stop = pi_stop, +}; + +DEFINE_SEQ_ATTRIBUTE(dfs_index); + +#ifdef CONFIG_MODULES +static const char *pi_get_module_name(struct module *mod) +{ + return mod ? mod->name : "vmlinux"; +} +#else +static const char *pi_get_module_name(struct module *mod) +{ + return "vmlinux"; +} +#endif + +void pi_create_file(struct module *mod) +{ + debugfs_create_file(pi_get_module_name(mod), 0444, dfs_index, + mod, &dfs_index_fops); +} + +void pi_remove_file(struct module *mod) +{ + debugfs_remove(debugfs_lookup(pi_get_module_name(mod), dfs_index)); +} + +#ifdef CONFIG_MODULES +static int pi_module_notify(struct notifier_block *nb, unsigned long op, + void *data) +{ + struct module *mod = data; + + switch (op) { + case MODULE_STATE_COMING: + pi_create_file(mod); + break; + case MODULE_STATE_GOING: + pi_remove_file(mod); + break; + default: /* we don't care about other module states */ + break; + } + + return NOTIFY_OK; +} + +static struct notifier_block module_printk_fmts_nb = { + .notifier_call = pi_module_notify, +}; + +static void __init pi_setup_module_notifier(void) +{ + register_module_notifier(&module_printk_fmts_nb); +} +#else +static inline void __init pi_setup_module_notifier(void) { } +#endif + +static int __init pi_init(void) +{ + struct dentry *dfs_root = debugfs_create_dir("printk", NULL); + + dfs_index = debugfs_create_dir("index", dfs_root); + pi_setup_module_notifier(); + pi_create_file(NULL); + + return 0; +} + +/* debugfs comes up on core and must be initialised first */ +postcore_initcall(pi_init); diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 03956c3eb745..765f7af6ce56 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2184,10 +2184,13 @@ int vprintk_default(const char *fmt, va_list args) EXPORT_SYMBOL_GPL(vprintk_default); /** - * printk - print a kernel message + * _printk - print a kernel message * @fmt: format string * - * This is printk(). It can be called from any context. We want it to work. + * This is _printk(). It can be called from any context. We want it to work. + * + * If printk indexing is enabled, _printk() is called from printk_index_wrap. + * Otherwise, printk is simply #defined to _printk. * * We try to grab the console_lock. If we succeed, it's easy - we log the * output and call the console drivers. If we fail to get the semaphore, we @@ -2204,7 +2207,7 @@ EXPORT_SYMBOL_GPL(vprintk_default); * * See the vsnprintf() documentation for format string extensions over C99. */ -asmlinkage __visible int printk(const char *fmt, ...) +asmlinkage __visible int _printk(const char *fmt, ...) { va_list args; int r; @@ -2215,7 +2218,7 @@ asmlinkage __visible int printk(const char *fmt, ...) return r; } -EXPORT_SYMBOL(printk); +EXPORT_SYMBOL(_printk); #else /* CONFIG_PRINTK */ @@ -3200,7 +3203,7 @@ int vprintk_deferred(const char *fmt, va_list args) return r; } -int printk_deferred(const char *fmt, ...) +int _printk_deferred(const char *fmt, ...) { va_list args; int r; -- cgit From ad7d61f159db73974f1b0352f21afe04b0bbd920 Mon Sep 17 00:00:00 2001 From: Chris Down Date: Tue, 15 Jun 2021 17:52:56 +0100 Subject: printk: index: Add indexing support to dev_printk While for most kinds of issues we have counters, tracepoints, or metrics with a stable interface which can reliably be used to indicate issues, in order to react to production issues quickly we sometimes need to work with the interface which most kernel developers naturally use when developing: printk, and printk-esques like dev_printk. dev_printk is by far the most likely custom subsystem printk to benefit from the printk indexing infrastructure, since niche device issues brought about by production changes, firmware upgrades, and the like are one of the most common things that we need printk infrastructure's assistance to monitor. Often these errors were never expected to practically manifest in reality, and exhibit in code without extensive (or any) metrics present. As such, there are typically very few options for issue detection available to those with large fleets at the time the incident happens, and we thus benefit strongly from monitoring netconsole in these instances. As such, add the infrastructure for dev_printk to be indexed in the printk index. Even on a minimal kernel config, the coverage of the base kernel's printk index is significantly improved: Before: [root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux 4497 /sys/kernel/debug/printk/index/vmlinux After: [root@ktst ~]# wc -l /sys/kernel/debug/printk/index/vmlinux 5573 /sys/kernel/debug/printk/index/vmlinux In terms of implementation, in order to trivially disambiguate them, dev_printk is now a macro which wraps _dev_printk. Signed-off-by: Chris Down Cc: Petr Mladek Cc: Greg Kroah-Hartman Cc: Rasmus Villemoes Reviewed-by: Petr Mladek Tested-by: Petr Mladek Acked-by: Andy Shevchenko Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/959c7aed1017cb2c9de922e0a820d397e29c6a5a.1623775748.git.chris@chrisdown.name --- drivers/base/core.c | 6 ++--- include/linux/dev_printk.h | 66 ++++++++++++++++++++++++++++++++++------------ 2 files changed, 52 insertions(+), 20 deletions(-) diff --git a/drivers/base/core.c b/drivers/base/core.c index cadcade65825..613497f45224 100644 --- a/drivers/base/core.c +++ b/drivers/base/core.c @@ -4579,8 +4579,8 @@ static void __dev_printk(const char *level, const struct device *dev, printk("%s(NULL device *): %pV", level, vaf); } -void dev_printk(const char *level, const struct device *dev, - const char *fmt, ...) +void _dev_printk(const char *level, const struct device *dev, + const char *fmt, ...) { struct va_format vaf; va_list args; @@ -4594,7 +4594,7 @@ void dev_printk(const char *level, const struct device *dev, va_end(args); } -EXPORT_SYMBOL(dev_printk); +EXPORT_SYMBOL(_dev_printk); #define define_dev_printk_level(func, kern_level) \ void func(const struct device *dev, const char *fmt, ...) \ diff --git a/include/linux/dev_printk.h b/include/linux/dev_printk.h index 82d3d46005a1..8904063d4c9f 100644 --- a/include/linux/dev_printk.h +++ b/include/linux/dev_printk.h @@ -38,8 +38,8 @@ __printf(3, 4) __cold int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...); __printf(3, 4) __cold -void dev_printk(const char *level, const struct device *dev, - const char *fmt, ...); +void _dev_printk(const char *level, const struct device *dev, + const char *fmt, ...); __printf(2, 3) __cold void _dev_emerg(const struct device *dev, const char *fmt, ...); __printf(2, 3) __cold @@ -69,7 +69,7 @@ static inline void __dev_printk(const char *level, const struct device *dev, struct va_format *vaf) {} static inline __printf(3, 4) -void dev_printk(const char *level, const struct device *dev, +void _dev_printk(const char *level, const struct device *dev, const char *fmt, ...) {} @@ -97,25 +97,57 @@ void _dev_info(const struct device *dev, const char *fmt, ...) #endif +/* + * Need to take variadic arguments even though we don't use them, as dev_fmt() + * may only just have been expanded and may result in multiple arguments. + */ +#define dev_printk_index_emit(level, fmt, ...) \ + printk_index_subsys_emit("%s %s: ", level, fmt) + +#define dev_printk_index_wrap(_p_func, level, dev, fmt, ...) \ + ({ \ + dev_printk_index_emit(level, fmt); \ + _p_func(dev, fmt, ##__VA_ARGS__); \ + }) + +/* + * Some callsites directly call dev_printk rather than going through the + * dev_ infrastructure, so we need to emit here as well as inside those + * level-specific macros. Only one index entry will be produced, either way, + * since dev_printk's `fmt` isn't known at compile time if going through the + * dev_ macros. + * + * dev_fmt() isn't called for dev_printk when used directly, as it's used by + * the dev_ macros internally which already have dev_fmt() processed. + * + * We also can't use dev_printk_index_wrap directly, because we have a separate + * level to process. + */ +#define dev_printk(level, dev, fmt, ...) \ + ({ \ + dev_printk_index_emit(level, fmt); \ + _dev_printk(level, dev, fmt, ##__VA_ARGS__); \ + }) + /* * #defines for all the dev_ macros to prefix with whatever * possible use of #define dev_fmt(fmt) ... */ -#define dev_emerg(dev, fmt, ...) \ - _dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_crit(dev, fmt, ...) \ - _dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_alert(dev, fmt, ...) \ - _dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_err(dev, fmt, ...) \ - _dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_warn(dev, fmt, ...) \ - _dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_notice(dev, fmt, ...) \ - _dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_info(dev, fmt, ...) \ - _dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_emerg(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_emerg, KERN_EMERG, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_crit(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_crit, KERN_CRIT, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_alert(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_alert, KERN_ALERT, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_err(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_err, KERN_ERR, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_warn(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_warn, KERN_WARNING, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_notice(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_notice, KERN_NOTICE, dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_info(dev, fmt, ...) \ + dev_printk_index_wrap(_dev_info, KERN_INFO, dev, dev_fmt(fmt), ##__VA_ARGS__) #if defined(CONFIG_DYNAMIC_DEBUG) || \ (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) -- cgit From 86ce91d5568de02f92ab9d4fb507683f8429a3e2 Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Fri, 23 Jul 2021 09:25:30 +0200 Subject: MIPS/asm/printk: Fix build failure caused by printk The commit 337015573718b161 ("printk: Userspace format indexing support") caused the following build failure: arch/mips/kernel/genex.o: In function `handle_mcheck_int': (.text+0x190c): undefined reference to `printk' arch/mips/kernel/genex.o: In function `handle_reserved_int': (.text+0x1c8c): undefined reference to `printk' Fixes: 337015573718b161 ("printk: Userspace format indexing support") Reported-by: Stephen Rothwell Suggested-by: Chris Down Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/YPbBfdz9srIpI+bb@chrisdown.name --- arch/mips/include/asm/asm.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/arch/mips/include/asm/asm.h b/arch/mips/include/asm/asm.h index ea4b62ece336..2f8ce94ebaaf 100644 --- a/arch/mips/include/asm/asm.h +++ b/arch/mips/include/asm/asm.h @@ -114,7 +114,7 @@ symbol = value .set push; \ .set reorder; \ PTR_LA a0, 8f; \ - jal printk; \ + jal _printk; \ .set pop; \ TEXT(string) #else -- cgit From 0f0aa84850a4105401723c6c0eeb61c2e67c869a Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Fri, 23 Jul 2021 09:47:07 +0200 Subject: printk/index: Fix warning about missing prototypes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The commit 337015573718b161 ("printk: Userspace format indexing support") triggered the following build failure: kernel/printk/index.c:140:6: warning: no previous prototype for ‘pi_create_file’ [-Wmissing-prototypes] void pi_create_file(struct module *mod) ^~~~~~~~~~~~~~ kernel/printk/index.c:146:6: warning: no previous prototype for ‘pi_remove_file’ [-Wmissing-prototypes] void pi_remove_file(struct module *mod) ^~~~~~~~~~~~~~ Fixes: 337015573718b161 ("printk: Userspace format indexing support") Reported-by: kernel test robot Suggested-by: Chris Down [pmladek@suse.com: Let the compiler decide about inlining.] Signed-off-by: Petr Mladek Link: https://lore.kernel.org/lkml/YPql089IwSpudw%2F1@alley/ --- kernel/printk/index.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/kernel/printk/index.c b/kernel/printk/index.c index ca062f5e1779..58d27272f992 100644 --- a/kernel/printk/index.c +++ b/kernel/printk/index.c @@ -137,13 +137,13 @@ static const char *pi_get_module_name(struct module *mod) } #endif -void pi_create_file(struct module *mod) +static void pi_create_file(struct module *mod) { debugfs_create_file(pi_get_module_name(mod), 0444, dfs_index, mod, &dfs_index_fops); } -void pi_remove_file(struct module *mod) +static void pi_remove_file(struct module *mod) { debugfs_remove(debugfs_lookup(pi_get_module_name(mod), dfs_index)); } -- cgit From 7d9e2661f268585ca24ab4edbc1e2925b08374b2 Mon Sep 17 00:00:00 2001 From: Jonathan Corbet Date: Sun, 25 Jul 2021 15:16:00 -0600 Subject: printk: Move the printk() kerneldoc comment to its new home Commit 337015573718 ("printk: Userspace format indexing support") turned printk() into a macro, but left the kerneldoc comment for it with the (now) _printk() function, resulting in this docs-build warning: kernel/printk/printk.c:1: warning: 'printk' not found Move the kerneldoc comment back next to the (now) macro it's meant to describe and have the docs build find it there. Fixes: 337015573718b161 ("printk: Userspace format indexing support") Signed-off-by: Jonathan Corbet Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/87o8aqt7qn.fsf@meer.lwn.net --- Documentation/core-api/printk-basics.rst | 5 +---- include/linux/printk.h | 24 ++++++++++++++++++++++++ kernel/printk/printk.c | 24 ------------------------ 3 files changed, 25 insertions(+), 28 deletions(-) diff --git a/Documentation/core-api/printk-basics.rst b/Documentation/core-api/printk-basics.rst index 965e4281eddd..2dde24ca7d9f 100644 --- a/Documentation/core-api/printk-basics.rst +++ b/Documentation/core-api/printk-basics.rst @@ -107,9 +107,6 @@ also ``CONFIG_DYNAMIC_DEBUG`` in the case of pr_debug()) is defined. Function reference ================== -.. kernel-doc:: kernel/printk/printk.c - :functions: printk - .. kernel-doc:: include/linux/printk.h - :functions: pr_emerg pr_alert pr_crit pr_err pr_warn pr_notice pr_info + :functions: printk pr_emerg pr_alert pr_crit pr_err pr_warn pr_notice pr_info pr_fmt pr_debug pr_devel pr_cont diff --git a/include/linux/printk.h b/include/linux/printk.h index 2651b82ed352..c1e176403967 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -431,6 +431,30 @@ struct pi_entry { }) +/** + * printk - print a kernel message + * @fmt: format string + * + * This is printk(). It can be called from any context. We want it to work. + * + * If printk indexing is enabled, _printk() is called from printk_index_wrap. + * Otherwise, printk is simply #defined to _printk. + * + * We try to grab the console_lock. If we succeed, it's easy - we log the + * output and call the console drivers. If we fail to get the semaphore, we + * place the output into the log buffer and return. The current holder of + * the console_sem will notice the new output in console_unlock(); and will + * send it to the consoles before releasing the lock. + * + * One effect of this deferred printing is that code which calls printk() and + * then changes console_loglevel may break. This is because console_loglevel + * is inspected when the actual printing occurs. + * + * See also: + * printf(3) + * + * See the vsnprintf() documentation for format string extensions over C99. + */ #define printk(fmt, ...) printk_index_wrap(_printk, fmt, ##__VA_ARGS__) #define printk_deferred(fmt, ...) \ printk_index_wrap(_printk_deferred, fmt, ##__VA_ARGS__) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 765f7af6ce56..8030c670f0bc 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2183,30 +2183,6 @@ int vprintk_default(const char *fmt, va_list args) } EXPORT_SYMBOL_GPL(vprintk_default); -/** - * _printk - print a kernel message - * @fmt: format string - * - * This is _printk(). It can be called from any context. We want it to work. - * - * If printk indexing is enabled, _printk() is called from printk_index_wrap. - * Otherwise, printk is simply #defined to _printk. - * - * We try to grab the console_lock. If we succeed, it's easy - we log the - * output and call the console drivers. If we fail to get the semaphore, we - * place the output into the log buffer and return. The current holder of - * the console_sem will notice the new output in console_unlock(); and will - * send it to the consoles before releasing the lock. - * - * One effect of this deferred printing is that code which calls printk() and - * then changes console_loglevel may break. This is because console_loglevel - * is inspected when the actual printing occurs. - * - * See also: - * printf(3) - * - * See the vsnprintf() documentation for format string extensions over C99. - */ asmlinkage __visible int _printk(const char *fmt, ...) { va_list args; -- cgit From 55d6af1d66885059ffc2ac23083de52d12be63bb Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:54 +0206 Subject: lib/nmi_backtrace: explicitly serialize banner and regs Currently the nmi_backtrace is serialized against other CPUs because the messages are sent to the NMI buffers. Once these buffers are removed, only the dumped stack will be serialized against other CPUs (via the printk_cpu_lock). Also serialize the nmi_backtrace banner and regs using the printk_cpu_lock so that per-CPU serialization will be preserved even after the NMI buffers are removed. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-2-john.ogness@linutronix.de --- lib/nmi_backtrace.c | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c index 8abe1870dba4..dae233c5f597 100644 --- a/lib/nmi_backtrace.c +++ b/lib/nmi_backtrace.c @@ -92,17 +92,24 @@ module_param(backtrace_idle, bool, 0644); bool nmi_cpu_backtrace(struct pt_regs *regs) { int cpu = smp_processor_id(); + unsigned long flags; if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) { if (!READ_ONCE(backtrace_idle) && regs && cpu_in_idle(instruction_pointer(regs))) { pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n", cpu, (void *)instruction_pointer(regs)); } else { + /* + * Allow nested NMI backtraces while serializing + * against other CPUs. + */ + printk_cpu_lock_irqsave(flags); pr_warn("NMI backtrace for cpu %d\n", cpu); if (regs) show_regs(regs); else dump_stack(); + printk_cpu_unlock_irqrestore(flags); } cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask)); return true; -- cgit From 002eb6ad075142e5940122c7fcee71cf1e906e29 Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:55 +0206 Subject: printk: track/limit recursion Currently the printk safe buffers provide a form of recursion protection by redirecting to the safe buffers whenever printk() is recursively called. In preparation for removal of the safe buffers, provide an alternate explicit recursion protection. Recursion is limited to 3 levels per-CPU and per-context. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-3-john.ogness@linutronix.de --- kernel/printk/printk.c | 86 ++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 83 insertions(+), 3 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 142a58d124d9..7fa0b4d91975 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1940,6 +1940,76 @@ static void call_console_drivers(const char *ext_text, size_t ext_len, } } +/* + * Recursion is tracked separately on each CPU. If NMIs are supported, an + * additional NMI context per CPU is also separately tracked. Until per-CPU + * is available, a separate "early tracking" is performed. + */ +static DEFINE_PER_CPU(u8, printk_count); +static u8 printk_count_early; +#ifdef CONFIG_HAVE_NMI +static DEFINE_PER_CPU(u8, printk_count_nmi); +static u8 printk_count_nmi_early; +#endif + +/* + * Recursion is limited to keep the output sane. printk() should not require + * more than 1 level of recursion (allowing, for example, printk() to trigger + * a WARN), but a higher value is used in case some printk-internal errors + * exist, such as the ringbuffer validation checks failing. + */ +#define PRINTK_MAX_RECURSION 3 + +/* + * Return a pointer to the dedicated counter for the CPU+context of the + * caller. + */ +static u8 *__printk_recursion_counter(void) +{ +#ifdef CONFIG_HAVE_NMI + if (in_nmi()) { + if (printk_percpu_data_ready()) + return this_cpu_ptr(&printk_count_nmi); + return &printk_count_nmi_early; + } +#endif + if (printk_percpu_data_ready()) + return this_cpu_ptr(&printk_count); + return &printk_count_early; +} + +/* + * Enter recursion tracking. Interrupts are disabled to simplify tracking. + * The caller must check the boolean return value to see if the recursion is + * allowed. On failure, interrupts are not disabled. + * + * @recursion_ptr must be a variable of type (u8 *) and is the same variable + * that is passed to printk_exit_irqrestore(). + */ +#define printk_enter_irqsave(recursion_ptr, flags) \ +({ \ + bool success = true; \ + \ + typecheck(u8 *, recursion_ptr); \ + local_irq_save(flags); \ + (recursion_ptr) = __printk_recursion_counter(); \ + if (*(recursion_ptr) > PRINTK_MAX_RECURSION) { \ + local_irq_restore(flags); \ + success = false; \ + } else { \ + (*(recursion_ptr))++; \ + } \ + success; \ +}) + +/* Exit recursion tracking, restoring interrupts. */ +#define printk_exit_irqrestore(recursion_ptr, flags) \ + do { \ + typecheck(u8 *, recursion_ptr); \ + (*(recursion_ptr))--; \ + local_irq_restore(flags); \ + } while (0) + int printk_delay_msec __read_mostly; static inline void printk_delay(void) @@ -2040,11 +2110,14 @@ int vprintk_store(int facility, int level, struct prb_reserved_entry e; enum log_flags lflags = 0; struct printk_record r; + unsigned long irqflags; u16 trunc_msg_len = 0; char prefix_buf[8]; + u8 *recursion_ptr; u16 reserve_size; va_list args2; u16 text_len; + int ret = 0; u64 ts_nsec; /* @@ -2055,6 +2128,9 @@ int vprintk_store(int facility, int level, */ ts_nsec = local_clock(); + if (!printk_enter_irqsave(recursion_ptr, irqflags)) + return 0; + /* * The sprintf needs to come first since the syslog prefix might be * passed in as a parameter. An extra byte must be reserved so that @@ -2092,7 +2168,8 @@ int vprintk_store(int facility, int level, prb_commit(&e); } - return text_len; + ret = text_len; + goto out; } } @@ -2108,7 +2185,7 @@ int vprintk_store(int facility, int level, prb_rec_init_wr(&r, reserve_size + trunc_msg_len); if (!prb_reserve(&e, prb, &r)) - return 0; + goto out; } /* fill message */ @@ -2130,7 +2207,10 @@ int vprintk_store(int facility, int level, else prb_final_commit(&e); - return (text_len + trunc_msg_len); + ret = text_len + trunc_msg_len; +out: + printk_exit_irqrestore(recursion_ptr, irqflags); + return ret; } asmlinkage int vprintk_emit(int facility, int level, -- cgit From 93d102f094be9beab28e5afb656c188b16a3793b Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:56 +0206 Subject: printk: remove safe buffers With @logbuf_lock removed, the high level printk functions for storing messages are lockless. Messages can be stored from any context, so there is no need for the NMI and safe buffers anymore. Remove the NMI and safe buffers. Although the safe buffers are removed, the NMI and safe context tracking is still in place. In these contexts, store the message immediately but still use irq_work to defer the console printing. Since printk recursion tracking is in place, safe context tracking for most of printk is not needed. Remove it. Only safe context tracking relating to the console and console_owner locks is left in place. This is because the console and console_owner locks are needed for the actual printing. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-4-john.ogness@linutronix.de --- arch/powerpc/kernel/traps.c | 1 - arch/powerpc/kernel/watchdog.c | 5 - include/linux/printk.h | 10 -- kernel/kexec_core.c | 1 - kernel/panic.c | 3 - kernel/printk/internal.h | 17 --- kernel/printk/printk.c | 120 ++++++--------- kernel/printk/printk_safe.c | 335 +---------------------------------------- lib/nmi_backtrace.c | 6 - 9 files changed, 48 insertions(+), 450 deletions(-) diff --git a/arch/powerpc/kernel/traps.c b/arch/powerpc/kernel/traps.c index b4ab95c9e94a..2522800217d1 100644 --- a/arch/powerpc/kernel/traps.c +++ b/arch/powerpc/kernel/traps.c @@ -170,7 +170,6 @@ extern void panic_flush_kmsg_start(void) extern void panic_flush_kmsg_end(void) { - printk_safe_flush_on_panic(); kmsg_dump(KMSG_DUMP_PANIC); bust_spinlocks(0); debug_locks_off(); diff --git a/arch/powerpc/kernel/watchdog.c b/arch/powerpc/kernel/watchdog.c index c9a8f4781a10..dc17d8903d4f 100644 --- a/arch/powerpc/kernel/watchdog.c +++ b/arch/powerpc/kernel/watchdog.c @@ -183,11 +183,6 @@ static void watchdog_smp_panic(int cpu, u64 tb) wd_smp_unlock(&flags); - printk_safe_flush(); - /* - * printk_safe_flush() seems to require another print - * before anything actually goes out to console. - */ if (sysctl_hardlockup_all_cpu_backtrace) trigger_allbutself_cpu_backtrace(); diff --git a/include/linux/printk.h b/include/linux/printk.h index d796183f26c9..719d919f9b67 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -208,8 +208,6 @@ void dump_stack_print_info(const char *log_lvl); void show_regs_print_info(const char *log_lvl); extern asmlinkage void dump_stack_lvl(const char *log_lvl) __cold; extern asmlinkage void dump_stack(void) __cold; -extern void printk_safe_flush(void); -extern void printk_safe_flush_on_panic(void); #else static inline __printf(1, 0) int vprintk(const char *s, va_list args) @@ -277,14 +275,6 @@ static inline void dump_stack_lvl(const char *log_lvl) static inline void dump_stack(void) { } - -static inline void printk_safe_flush(void) -{ -} - -static inline void printk_safe_flush_on_panic(void) -{ -} #endif #ifdef CONFIG_SMP diff --git a/kernel/kexec_core.c b/kernel/kexec_core.c index f099baee3578..69c6e9b7761c 100644 --- a/kernel/kexec_core.c +++ b/kernel/kexec_core.c @@ -978,7 +978,6 @@ void crash_kexec(struct pt_regs *regs) old_cpu = atomic_cmpxchg(&panic_cpu, PANIC_CPU_INVALID, this_cpu); if (old_cpu == PANIC_CPU_INVALID) { /* This is the 1st CPU which comes here, so go ahead. */ - printk_safe_flush_on_panic(); __crash_kexec(regs); /* diff --git a/kernel/panic.c b/kernel/panic.c index 332736a72a58..1f0df42f8d0c 100644 --- a/kernel/panic.c +++ b/kernel/panic.c @@ -247,7 +247,6 @@ void panic(const char *fmt, ...) * Bypass the panic_cpu check and call __crash_kexec directly. */ if (!_crash_kexec_post_notifiers) { - printk_safe_flush_on_panic(); __crash_kexec(NULL); /* @@ -271,8 +270,6 @@ void panic(const char *fmt, ...) */ atomic_notifier_call_chain(&panic_notifier_list, 0, buf); - /* Call flush even twice. It tries harder with a single online CPU */ - printk_safe_flush_on_panic(); kmsg_dump(KMSG_DUMP_PANIC); /* diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 51615c909b2f..6cc35c5de890 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -22,7 +22,6 @@ __printf(1, 0) int vprintk_deferred(const char *fmt, va_list args); void __printk_safe_enter(void); void __printk_safe_exit(void); -void printk_safe_init(void); bool printk_percpu_data_ready(void); #define printk_safe_enter_irqsave(flags) \ @@ -37,18 +36,6 @@ bool printk_percpu_data_ready(void); local_irq_restore(flags); \ } while (0) -#define printk_safe_enter_irq() \ - do { \ - local_irq_disable(); \ - __printk_safe_enter(); \ - } while (0) - -#define printk_safe_exit_irq() \ - do { \ - __printk_safe_exit(); \ - local_irq_enable(); \ - } while (0) - void defer_console_output(void); #else @@ -61,9 +48,5 @@ void defer_console_output(void); #define printk_safe_enter_irqsave(flags) local_irq_save(flags) #define printk_safe_exit_irqrestore(flags) local_irq_restore(flags) -#define printk_safe_enter_irq() local_irq_disable() -#define printk_safe_exit_irq() local_irq_enable() - -static inline void printk_safe_init(void) { } static inline bool printk_percpu_data_ready(void) { return false; } #endif /* CONFIG_PRINTK */ diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 7fa0b4d91975..219ad710a9e8 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -732,27 +732,22 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, if (ret) return ret; - printk_safe_enter_irq(); if (!prb_read_valid(prb, atomic64_read(&user->seq), r)) { if (file->f_flags & O_NONBLOCK) { ret = -EAGAIN; - printk_safe_exit_irq(); goto out; } - printk_safe_exit_irq(); ret = wait_event_interruptible(log_wait, prb_read_valid(prb, atomic64_read(&user->seq), r)); if (ret) goto out; - printk_safe_enter_irq(); } if (r->info->seq != atomic64_read(&user->seq)) { /* our last seen message is gone, return error and reset */ atomic64_set(&user->seq, r->info->seq); ret = -EPIPE; - printk_safe_exit_irq(); goto out; } @@ -762,7 +757,6 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, &r->info->dev_info); atomic64_set(&user->seq, r->info->seq + 1); - printk_safe_exit_irq(); if (len > count) { ret = -EINVAL; @@ -797,7 +791,6 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence) if (offset) return -ESPIPE; - printk_safe_enter_irq(); switch (whence) { case SEEK_SET: /* the first record */ @@ -818,7 +811,6 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence) default: ret = -EINVAL; } - printk_safe_exit_irq(); return ret; } @@ -833,7 +825,6 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait) poll_wait(file, &log_wait, wait); - printk_safe_enter_irq(); if (prb_read_valid_info(prb, atomic64_read(&user->seq), &info, NULL)) { /* return error when data has vanished underneath us */ if (info.seq != atomic64_read(&user->seq)) @@ -841,7 +832,6 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait) else ret = EPOLLIN|EPOLLRDNORM; } - printk_safe_exit_irq(); return ret; } @@ -874,9 +864,7 @@ static int devkmsg_open(struct inode *inode, struct file *file) prb_rec_init_rd(&user->record, &user->info, &user->text_buf[0], sizeof(user->text_buf)); - printk_safe_enter_irq(); atomic64_set(&user->seq, prb_first_valid_seq(prb)); - printk_safe_exit_irq(); file->private_data = user; return 0; @@ -1042,9 +1030,6 @@ static inline void log_buf_add_cpu(void) {} static void __init set_percpu_data_ready(void) { - printk_safe_init(); - /* Make sure we set this flag only after printk_safe() init is done */ - barrier(); __printk_percpu_data_ready = true; } @@ -1082,6 +1067,7 @@ void __init setup_log_buf(int early) struct prb_desc *new_descs; struct printk_info info; struct printk_record r; + unsigned int text_size; size_t new_descs_size; size_t new_infos_size; unsigned long flags; @@ -1142,24 +1128,37 @@ void __init setup_log_buf(int early) new_descs, ilog2(new_descs_count), new_infos); - printk_safe_enter_irqsave(flags); + local_irq_save(flags); log_buf_len = new_log_buf_len; log_buf = new_log_buf; new_log_buf_len = 0; free = __LOG_BUF_LEN; - prb_for_each_record(0, &printk_rb_static, seq, &r) - free -= add_to_rb(&printk_rb_dynamic, &r); + prb_for_each_record(0, &printk_rb_static, seq, &r) { + text_size = add_to_rb(&printk_rb_dynamic, &r); + if (text_size > free) + free = 0; + else + free -= text_size; + } - /* - * This is early enough that everything is still running on the - * boot CPU and interrupts are disabled. So no new messages will - * appear during the transition to the dynamic buffer. - */ prb = &printk_rb_dynamic; - printk_safe_exit_irqrestore(flags); + local_irq_restore(flags); + + /* + * Copy any remaining messages that might have appeared from + * NMI context after copying but before switching to the + * dynamic buffer. + */ + prb_for_each_record(seq, &printk_rb_static, seq, &r) { + text_size = add_to_rb(&printk_rb_dynamic, &r); + if (text_size > free) + free = 0; + else + free -= text_size; + } if (seq != prb_next_seq(&printk_rb_static)) { pr_err("dropped %llu messages\n", @@ -1498,11 +1497,9 @@ static int syslog_print(char __user *buf, int size) size_t n; size_t skip; - printk_safe_enter_irq(); - raw_spin_lock(&syslog_lock); + raw_spin_lock_irq(&syslog_lock); if (!prb_read_valid(prb, syslog_seq, &r)) { - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + raw_spin_unlock_irq(&syslog_lock); break; } if (r.info->seq != syslog_seq) { @@ -1531,8 +1528,7 @@ static int syslog_print(char __user *buf, int size) syslog_partial += n; } else n = 0; - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + raw_spin_unlock_irq(&syslog_lock); if (!n) break; @@ -1566,7 +1562,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear) return -ENOMEM; time = printk_time; - printk_safe_enter_irq(); /* * Find first record that fits, including all following records, * into the user-provided buffer for this dump. @@ -1587,23 +1582,20 @@ static int syslog_print_all(char __user *buf, int size, bool clear) break; } - printk_safe_exit_irq(); if (copy_to_user(buf + len, text, textlen)) len = -EFAULT; else len += textlen; - printk_safe_enter_irq(); if (len < 0) break; } if (clear) { - raw_spin_lock(&syslog_lock); + raw_spin_lock_irq(&syslog_lock); latched_seq_write(&clear_seq, seq); - raw_spin_unlock(&syslog_lock); + raw_spin_unlock_irq(&syslog_lock); } - printk_safe_exit_irq(); kfree(text); return len; @@ -1611,11 +1603,9 @@ static int syslog_print_all(char __user *buf, int size, bool clear) static void syslog_clear(void) { - printk_safe_enter_irq(); - raw_spin_lock(&syslog_lock); + raw_spin_lock_irq(&syslog_lock); latched_seq_write(&clear_seq, prb_next_seq(prb)); - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + raw_spin_unlock_irq(&syslog_lock); } /* Return a consistent copy of @syslog_seq. */ @@ -1703,12 +1693,10 @@ int do_syslog(int type, char __user *buf, int len, int source) break; /* Number of chars in the log buffer */ case SYSLOG_ACTION_SIZE_UNREAD: - printk_safe_enter_irq(); - raw_spin_lock(&syslog_lock); + raw_spin_lock_irq(&syslog_lock); if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) { /* No unread messages. */ - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + raw_spin_unlock_irq(&syslog_lock); return 0; } if (info.seq != syslog_seq) { @@ -1736,8 +1724,7 @@ int do_syslog(int type, char __user *buf, int len, int source) } error -= syslog_partial; } - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + raw_spin_unlock_irq(&syslog_lock); break; /* Size of the log buffer */ case SYSLOG_ACTION_SIZE_BUFFER: @@ -2219,7 +2206,6 @@ asmlinkage int vprintk_emit(int facility, int level, { int printed_len; bool in_sched = false; - unsigned long flags; /* Suppress unimportant messages after panic happens */ if (unlikely(suppress_printk)) @@ -2233,9 +2219,7 @@ asmlinkage int vprintk_emit(int facility, int level, boot_delay_msec(level); printk_delay(); - printk_safe_enter_irqsave(flags); printed_len = vprintk_store(facility, level, dev_info, fmt, args); - printk_safe_exit_irqrestore(flags); /* If called from the scheduler, we can not call up(). */ if (!in_sched) { @@ -2664,9 +2648,9 @@ again: for (;;) { size_t ext_len = 0; + int handover; size_t len; - printk_safe_enter_irqsave(flags); skip: if (!prb_read_valid(prb, console_seq, &r)) break; @@ -2716,19 +2700,22 @@ skip: * were to occur on another CPU, it may wait for this one to * finish. This task can not be preempted if there is a * waiter waiting to take over. + * + * Interrupts are disabled because the hand over to a waiter + * must not be interrupted until the hand over is completed + * (@console_waiter is cleared). */ + printk_safe_enter_irqsave(flags); console_lock_spinning_enable(); stop_critical_timings(); /* don't trace print latency */ call_console_drivers(ext_text, ext_len, text, len); start_critical_timings(); - if (console_lock_spinning_disable_and_check()) { - printk_safe_exit_irqrestore(flags); - return; - } - + handover = console_lock_spinning_disable_and_check(); printk_safe_exit_irqrestore(flags); + if (handover) + return; if (do_cond_resched) cond_resched(); @@ -2745,8 +2732,6 @@ skip: * flush, no worries. */ retry = prb_read_valid(prb, console_seq, NULL); - printk_safe_exit_irqrestore(flags); - if (retry && console_trylock()) goto again; } @@ -2808,13 +2793,8 @@ void console_flush_on_panic(enum con_flush_mode mode) console_trylock(); console_may_schedule = 0; - if (mode == CONSOLE_REPLAY_ALL) { - unsigned long flags; - - printk_safe_enter_irqsave(flags); + if (mode == CONSOLE_REPLAY_ALL) console_seq = prb_first_valid_seq(prb); - printk_safe_exit_irqrestore(flags); - } console_unlock(); } @@ -3466,14 +3446,12 @@ bool kmsg_dump_get_line(struct kmsg_dump_iter *iter, bool syslog, struct printk_info info; unsigned int line_count; struct printk_record r; - unsigned long flags; size_t l = 0; bool ret = false; if (iter->cur_seq < min_seq) iter->cur_seq = min_seq; - printk_safe_enter_irqsave(flags); prb_rec_init_rd(&r, &info, line, size); /* Read text or count text lines? */ @@ -3494,7 +3472,6 @@ bool kmsg_dump_get_line(struct kmsg_dump_iter *iter, bool syslog, iter->cur_seq = r.info->seq + 1; ret = true; out: - printk_safe_exit_irqrestore(flags); if (len) *len = l; return ret; @@ -3526,7 +3503,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dump_iter *iter, bool syslog, u64 min_seq = latched_seq_read_nolock(&clear_seq); struct printk_info info; struct printk_record r; - unsigned long flags; u64 seq; u64 next_seq; size_t len = 0; @@ -3539,7 +3515,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dump_iter *iter, bool syslog, if (iter->cur_seq < min_seq) iter->cur_seq = min_seq; - printk_safe_enter_irqsave(flags); if (prb_read_valid_info(prb, iter->cur_seq, &info, NULL)) { if (info.seq != iter->cur_seq) { /* messages are gone, move to first available one */ @@ -3548,10 +3523,8 @@ bool kmsg_dump_get_buffer(struct kmsg_dump_iter *iter, bool syslog, } /* last entry */ - if (iter->cur_seq >= iter->next_seq) { - printk_safe_exit_irqrestore(flags); + if (iter->cur_seq >= iter->next_seq) goto out; - } /* * Find first record that fits, including all following records, @@ -3583,7 +3556,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dump_iter *iter, bool syslog, iter->next_seq = next_seq; ret = true; - printk_safe_exit_irqrestore(flags); out: if (len_out) *len_out = len; @@ -3601,12 +3573,8 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer); */ void kmsg_dump_rewind(struct kmsg_dump_iter *iter) { - unsigned long flags; - - printk_safe_enter_irqsave(flags); iter->cur_seq = latched_seq_read_nolock(&clear_seq); iter->next_seq = prb_next_seq(prb); - printk_safe_exit_irqrestore(flags); } EXPORT_SYMBOL_GPL(kmsg_dump_rewind); diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c index 94232186fccb..29c580dac93d 100644 --- a/kernel/printk/printk_safe.c +++ b/kernel/printk/printk_safe.c @@ -15,286 +15,9 @@ #include "internal.h" -/* - * In NMI and safe mode, printk() avoids taking locks. Instead, - * it uses an alternative implementation that temporary stores - * the strings into a per-CPU buffer. The content of the buffer - * is later flushed into the main ring buffer via IRQ work. - * - * The alternative implementation is chosen transparently - * by examining current printk() context mask stored in @printk_context - * per-CPU variable. - * - * The implementation allows to flush the strings also from another CPU. - * There are situations when we want to make sure that all buffers - * were handled or when IRQs are blocked. - */ - -#define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) - \ - sizeof(atomic_t) - \ - sizeof(atomic_t) - \ - sizeof(struct irq_work)) - -struct printk_safe_seq_buf { - atomic_t len; /* length of written data */ - atomic_t message_lost; - struct irq_work work; /* IRQ work that flushes the buffer */ - unsigned char buffer[SAFE_LOG_BUF_LEN]; -}; - -static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq); static DEFINE_PER_CPU(int, printk_context); -static DEFINE_RAW_SPINLOCK(safe_read_lock); - -#ifdef CONFIG_PRINTK_NMI -static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq); -#endif - -/* Get flushed in a more safe context. */ -static void queue_flush_work(struct printk_safe_seq_buf *s) -{ - if (printk_percpu_data_ready()) - irq_work_queue(&s->work); -} - -/* - * Add a message to per-CPU context-dependent buffer. NMI and printk-safe - * have dedicated buffers, because otherwise printk-safe preempted by - * NMI-printk would have overwritten the NMI messages. - * - * The messages are flushed from irq work (or from panic()), possibly, - * from other CPU, concurrently with printk_safe_log_store(). Should this - * happen, printk_safe_log_store() will notice the buffer->len mismatch - * and repeat the write. - */ -static __printf(2, 0) int printk_safe_log_store(struct printk_safe_seq_buf *s, - const char *fmt, va_list args) -{ - int add; - size_t len; - va_list ap; - -again: - len = atomic_read(&s->len); - - /* The trailing '\0' is not counted into len. */ - if (len >= sizeof(s->buffer) - 1) { - atomic_inc(&s->message_lost); - queue_flush_work(s); - return 0; - } - - /* - * Make sure that all old data have been read before the buffer - * was reset. This is not needed when we just append data. - */ - if (!len) - smp_rmb(); - - va_copy(ap, args); - add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, ap); - va_end(ap); - if (!add) - return 0; - - /* - * Do it once again if the buffer has been flushed in the meantime. - * Note that atomic_cmpxchg() is an implicit memory barrier that - * makes sure that the data were written before updating s->len. - */ - if (atomic_cmpxchg(&s->len, len, len + add) != len) - goto again; - - queue_flush_work(s); - return add; -} - -static inline void printk_safe_flush_line(const char *text, int len) -{ - /* - * Avoid any console drivers calls from here, because we may be - * in NMI or printk_safe context (when in panic). The messages - * must go only into the ring buffer at this stage. Consoles will - * get explicitly called later when a crashdump is not generated. - */ - printk_deferred("%.*s", len, text); -} - -/* printk part of the temporary buffer line by line */ -static int printk_safe_flush_buffer(const char *start, size_t len) -{ - const char *c, *end; - bool header; - - c = start; - end = start + len; - header = true; - - /* Print line by line. */ - while (c < end) { - if (*c == '\n') { - printk_safe_flush_line(start, c - start + 1); - start = ++c; - header = true; - continue; - } - - /* Handle continuous lines or missing new line. */ - if ((c + 1 < end) && printk_get_level(c)) { - if (header) { - c = printk_skip_level(c); - continue; - } - - printk_safe_flush_line(start, c - start); - start = c++; - header = true; - continue; - } - - header = false; - c++; - } - - /* Check if there was a partial line. Ignore pure header. */ - if (start < end && !header) { - static const char newline[] = KERN_CONT "\n"; - - printk_safe_flush_line(start, end - start); - printk_safe_flush_line(newline, strlen(newline)); - } - - return len; -} - -static void report_message_lost(struct printk_safe_seq_buf *s) -{ - int lost = atomic_xchg(&s->message_lost, 0); - - if (lost) - printk_deferred("Lost %d message(s)!\n", lost); -} - -/* - * Flush data from the associated per-CPU buffer. The function - * can be called either via IRQ work or independently. - */ -static void __printk_safe_flush(struct irq_work *work) -{ - struct printk_safe_seq_buf *s = - container_of(work, struct printk_safe_seq_buf, work); - unsigned long flags; - size_t len; - int i; - - /* - * The lock has two functions. First, one reader has to flush all - * available message to make the lockless synchronization with - * writers easier. Second, we do not want to mix messages from - * different CPUs. This is especially important when printing - * a backtrace. - */ - raw_spin_lock_irqsave(&safe_read_lock, flags); - - i = 0; -more: - len = atomic_read(&s->len); - - /* - * This is just a paranoid check that nobody has manipulated - * the buffer an unexpected way. If we printed something then - * @len must only increase. Also it should never overflow the - * buffer size. - */ - if ((i && i >= len) || len > sizeof(s->buffer)) { - const char *msg = "printk_safe_flush: internal error\n"; - - printk_safe_flush_line(msg, strlen(msg)); - len = 0; - } - - if (!len) - goto out; /* Someone else has already flushed the buffer. */ - - /* Make sure that data has been written up to the @len */ - smp_rmb(); - i += printk_safe_flush_buffer(s->buffer + i, len - i); - - /* - * Check that nothing has got added in the meantime and truncate - * the buffer. Note that atomic_cmpxchg() is an implicit memory - * barrier that makes sure that the data were copied before - * updating s->len. - */ - if (atomic_cmpxchg(&s->len, len, 0) != len) - goto more; - -out: - report_message_lost(s); - raw_spin_unlock_irqrestore(&safe_read_lock, flags); -} - -/** - * printk_safe_flush - flush all per-cpu nmi buffers. - * - * The buffers are flushed automatically via IRQ work. This function - * is useful only when someone wants to be sure that all buffers have - * been flushed at some point. - */ -void printk_safe_flush(void) -{ - int cpu; - - for_each_possible_cpu(cpu) { -#ifdef CONFIG_PRINTK_NMI - __printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work); -#endif - __printk_safe_flush(&per_cpu(safe_print_seq, cpu).work); - } -} - -/** - * printk_safe_flush_on_panic - flush all per-cpu nmi buffers when the system - * goes down. - * - * Similar to printk_safe_flush() but it can be called even in NMI context when - * the system goes down. It does the best effort to get NMI messages into - * the main ring buffer. - * - * Note that it could try harder when there is only one CPU online. - */ -void printk_safe_flush_on_panic(void) -{ - /* - * Make sure that we could access the safe buffers. - * Do not risk a double release when more CPUs are up. - */ - if (raw_spin_is_locked(&safe_read_lock)) { - if (num_online_cpus() > 1) - return; - - debug_locks_off(); - raw_spin_lock_init(&safe_read_lock); - } - - printk_safe_flush(); -} - #ifdef CONFIG_PRINTK_NMI -/* - * Safe printk() for NMI context. It uses a per-CPU buffer to - * store the message. NMIs are not nested, so there is always only - * one writer running. But the buffer might get flushed from another - * CPU, so we need to be careful. - */ -static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args) -{ - struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq); - - return printk_safe_log_store(s, fmt, args); -} - void noinstr printk_nmi_enter(void) { this_cpu_add(printk_context, PRINTK_NMI_CONTEXT_OFFSET); @@ -309,9 +32,6 @@ void noinstr printk_nmi_exit(void) * Marks a code that might produce many messages in NMI context * and the risk of losing them is more critical than eventual * reordering. - * - * It has effect only when called in NMI context. Then printk() - * will store the messages into the main logbuf directly. */ void printk_nmi_direct_enter(void) { @@ -324,27 +44,8 @@ void printk_nmi_direct_exit(void) this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK); } -#else - -static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args) -{ - return 0; -} - #endif /* CONFIG_PRINTK_NMI */ -/* - * Lock-less printk(), to avoid deadlocks should the printk() recurse - * into itself. It uses a per-CPU buffer to store the message, just like - * NMI. - */ -static __printf(1, 0) int vprintk_safe(const char *fmt, va_list args) -{ - struct printk_safe_seq_buf *s = this_cpu_ptr(&safe_print_seq); - - return printk_safe_log_store(s, fmt, args); -} - /* Can be preempted by NMI. */ void __printk_safe_enter(void) { @@ -369,46 +70,18 @@ asmlinkage int vprintk(const char *fmt, va_list args) * Use the main logbuf even in NMI. But avoid calling console * drivers that might have their own locks. */ - if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK)) { - unsigned long flags; + if (this_cpu_read(printk_context) & + (PRINTK_NMI_DIRECT_CONTEXT_MASK | + PRINTK_NMI_CONTEXT_MASK | + PRINTK_SAFE_CONTEXT_MASK)) { int len; - printk_safe_enter_irqsave(flags); len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args); - printk_safe_exit_irqrestore(flags); defer_console_output(); return len; } - /* Use extra buffer in NMI. */ - if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK) - return vprintk_nmi(fmt, args); - - /* Use extra buffer to prevent a recursion deadlock in safe mode. */ - if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) - return vprintk_safe(fmt, args); - /* No obstacles. */ return vprintk_default(fmt, args); } EXPORT_SYMBOL(vprintk); - -void __init printk_safe_init(void) -{ - int cpu; - - for_each_possible_cpu(cpu) { - struct printk_safe_seq_buf *s; - - s = &per_cpu(safe_print_seq, cpu); - init_irq_work(&s->work, __printk_safe_flush); - -#ifdef CONFIG_PRINTK_NMI - s = &per_cpu(nmi_print_seq, cpu); - init_irq_work(&s->work, __printk_safe_flush); -#endif - } - - /* Flush pending messages that did not have scheduled IRQ works. */ - printk_safe_flush(); -} diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c index dae233c5f597..9813a983d024 100644 --- a/lib/nmi_backtrace.c +++ b/lib/nmi_backtrace.c @@ -75,12 +75,6 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask, touch_softlockup_watchdog(); } - /* - * Force flush any remote buffers that might be stuck in IRQ context - * and therefore could not run their irq_work. - */ - printk_safe_flush(); - clear_bit_unlock(0, &backtrace_flag); put_cpu(); } -- cgit From 85e3e7fbbb720b9897fba9a99659e31cbd1c082e Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:57 +0206 Subject: printk: remove NMI tracking All NMI contexts are handled the same as the safe context: store the message and defer printing. There is no need to have special NMI context tracking for this. Using in_nmi() is enough. There are several parts of the kernel that are manually calling into the printk NMI context tracking in order to cause general printk deferred printing: arch/arm/kernel/smp.c arch/powerpc/kexec/crash.c kernel/trace/trace.c For arm/kernel/smp.c and powerpc/kexec/crash.c, provide a new function pair printk_deferred_enter/exit that explicitly achieves the same objective. For ftrace, remove the printk context manipulation completely. It was added in commit 03fc7f9c99c1 ("printk/nmi: Prevent deadlock when accessing the main log buffer in NMI"). The purpose was to enforce storing messages directly into the ring buffer even in NMI context. It really should have only modified the behavior in NMI context. There is no need for a special behavior any longer. All messages are always stored directly now. The console deferring is handled transparently in vprintk(). Signed-off-by: John Ogness [pmladek@suse.com: Remove special handling in ftrace.c completely. Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-5-john.ogness@linutronix.de --- arch/arm/kernel/smp.c | 4 ++-- arch/powerpc/kexec/crash.c | 2 +- include/linux/hardirq.h | 2 -- include/linux/printk.h | 31 +++++++++++++++++++------------ init/Kconfig | 5 ----- kernel/printk/internal.h | 8 -------- kernel/printk/printk_safe.c | 37 +------------------------------------ kernel/trace/trace.c | 2 -- 8 files changed, 23 insertions(+), 68 deletions(-) diff --git a/arch/arm/kernel/smp.c b/arch/arm/kernel/smp.c index c7bb168b0d97..842427ff2b3c 100644 --- a/arch/arm/kernel/smp.c +++ b/arch/arm/kernel/smp.c @@ -667,9 +667,9 @@ static void do_handle_IPI(int ipinr) break; case IPI_CPU_BACKTRACE: - printk_nmi_enter(); + printk_deferred_enter(); nmi_cpu_backtrace(get_irq_regs()); - printk_nmi_exit(); + printk_deferred_exit(); break; default: diff --git a/arch/powerpc/kexec/crash.c b/arch/powerpc/kexec/crash.c index 0196d0c211ac..1070378c8e35 100644 --- a/arch/powerpc/kexec/crash.c +++ b/arch/powerpc/kexec/crash.c @@ -313,7 +313,7 @@ void default_machine_crash_shutdown(struct pt_regs *regs) int (*old_handler)(struct pt_regs *regs); /* Avoid hardlocking with irresponsive CPU holding logbuf_lock */ - printk_nmi_enter(); + printk_deferred_enter(); /* * This function is only called after the system diff --git a/include/linux/hardirq.h b/include/linux/hardirq.h index 69bc86ea382c..76878b357ffa 100644 --- a/include/linux/hardirq.h +++ b/include/linux/hardirq.h @@ -116,7 +116,6 @@ extern void rcu_nmi_exit(void); do { \ lockdep_off(); \ arch_nmi_enter(); \ - printk_nmi_enter(); \ BUG_ON(in_nmi() == NMI_MASK); \ __preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET); \ } while (0) @@ -135,7 +134,6 @@ extern void rcu_nmi_exit(void); do { \ BUG_ON(!in_nmi()); \ __preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET); \ - printk_nmi_exit(); \ arch_nmi_exit(); \ lockdep_on(); \ } while (0) diff --git a/include/linux/printk.h b/include/linux/printk.h index 719d919f9b67..a1379df43251 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -149,18 +149,6 @@ static inline __printf(1, 2) __cold void early_printk(const char *s, ...) { } #endif -#ifdef CONFIG_PRINTK_NMI -extern void printk_nmi_enter(void); -extern void printk_nmi_exit(void); -extern void printk_nmi_direct_enter(void); -extern void printk_nmi_direct_exit(void); -#else -static inline void printk_nmi_enter(void) { } -static inline void printk_nmi_exit(void) { } -static inline void printk_nmi_direct_enter(void) { } -static inline void printk_nmi_direct_exit(void) { } -#endif /* PRINTK_NMI */ - struct dev_printk_info; #ifdef CONFIG_PRINTK @@ -180,6 +168,16 @@ int printk(const char *fmt, ...); */ __printf(1, 2) __cold int printk_deferred(const char *fmt, ...); +extern void __printk_safe_enter(void); +extern void __printk_safe_exit(void); +/* + * The printk_deferred_enter/exit macros are available only as a hack for + * some code paths that need to defer all printk console printing. Interrupts + * must be disabled for the deferred duration. + */ +#define printk_deferred_enter __printk_safe_enter +#define printk_deferred_exit __printk_safe_exit + /* * Please don't use printk_ratelimit(), because it shares ratelimiting state * with all other unrelated printk_ratelimit() callsites. Instead use @@ -224,6 +222,15 @@ int printk_deferred(const char *s, ...) { return 0; } + +static inline void printk_deferred_enter(void) +{ +} + +static inline void printk_deferred_exit(void) +{ +} + static inline int printk_ratelimit(void) { return 0; diff --git a/init/Kconfig b/init/Kconfig index a61c92066c2e..9c0510693543 100644 --- a/init/Kconfig +++ b/init/Kconfig @@ -1506,11 +1506,6 @@ config PRINTK very difficult to diagnose system problems, saying N here is strongly discouraged. -config PRINTK_NMI - def_bool y - depends on PRINTK - depends on HAVE_NMI - config BUG bool "BUG() support" if EXPERT default y diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h index 6cc35c5de890..b6d310c72fc9 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -6,12 +6,6 @@ #ifdef CONFIG_PRINTK -#define PRINTK_SAFE_CONTEXT_MASK 0x007ffffff -#define PRINTK_NMI_DIRECT_CONTEXT_MASK 0x008000000 -#define PRINTK_NMI_CONTEXT_MASK 0xff0000000 - -#define PRINTK_NMI_CONTEXT_OFFSET 0x010000000 - __printf(4, 0) int vprintk_store(int facility, int level, const struct dev_printk_info *dev_info, @@ -19,8 +13,6 @@ int vprintk_store(int facility, int level, __printf(1, 0) int vprintk_default(const char *fmt, va_list args); __printf(1, 0) int vprintk_deferred(const char *fmt, va_list args); -void __printk_safe_enter(void); -void __printk_safe_exit(void); bool printk_percpu_data_ready(void); diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c index 29c580dac93d..ef0f9a2044da 100644 --- a/kernel/printk/printk_safe.c +++ b/kernel/printk/printk_safe.c @@ -4,12 +4,9 @@ */ #include -#include -#include #include #include #include -#include #include #include @@ -17,35 +14,6 @@ static DEFINE_PER_CPU(int, printk_context); -#ifdef CONFIG_PRINTK_NMI -void noinstr printk_nmi_enter(void) -{ - this_cpu_add(printk_context, PRINTK_NMI_CONTEXT_OFFSET); -} - -void noinstr printk_nmi_exit(void) -{ - this_cpu_sub(printk_context, PRINTK_NMI_CONTEXT_OFFSET); -} - -/* - * Marks a code that might produce many messages in NMI context - * and the risk of losing them is more critical than eventual - * reordering. - */ -void printk_nmi_direct_enter(void) -{ - if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK) - this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK); -} - -void printk_nmi_direct_exit(void) -{ - this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK); -} - -#endif /* CONFIG_PRINTK_NMI */ - /* Can be preempted by NMI. */ void __printk_safe_enter(void) { @@ -70,10 +38,7 @@ asmlinkage int vprintk(const char *fmt, va_list args) * Use the main logbuf even in NMI. But avoid calling console * drivers that might have their own locks. */ - if (this_cpu_read(printk_context) & - (PRINTK_NMI_DIRECT_CONTEXT_MASK | - PRINTK_NMI_CONTEXT_MASK | - PRINTK_SAFE_CONTEXT_MASK)) { + if (this_cpu_read(printk_context) || in_nmi()) { int len; len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args); diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index d23a09d3eb37..2f41311c61d7 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -9647,7 +9647,6 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode) tracing_off(); local_irq_save(flags); - printk_nmi_direct_enter(); /* Simulate the iterator */ trace_init_global_iter(&iter); @@ -9729,7 +9728,6 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode) atomic_dec(&per_cpu_ptr(iter.array_buffer->data, cpu)->disabled); } atomic_dec(&dump_running); - printk_nmi_direct_exit(); local_irq_restore(flags); } EXPORT_SYMBOL_GPL(ftrace_dump); -- cgit From b371cbb584d843bc4194d0cd4ce5ecd19b0cf55f Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:58 +0206 Subject: printk: convert @syslog_lock to mutex @syslog_lock was a raw_spin_lock to simplify the transition of removing @logbuf_lock and the safe buffers. With that transition complete, and since all uses of @syslog_lock are within sleepable contexts, @syslog_lock can become a mutex. Note that until now register_console() would disable interrupts using irqsave, which implies that it may be called with interrupts disabled. And indeed, there is one possible call chain on parisc where this happens: handle_interruption(code=1) /* High-priority machine check (HPMC) */ pdc_console_restart() pdc_console_init_force() register_console() However, register_console() calls console_lock(), which might sleep. So it has never been allowed to call register_console() from an atomic context and the above call chain is a bug. Note that the removal of read_syslog_seq_irq() is slightly changing the behavior of SYSLOG_ACTION_READ by testing against a possibly outdated @seq value. However, the value of @seq could have changed after the test, so it is not a new window. A follow-up commit closes this window. Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-6-john.ogness@linutronix.de --- kernel/printk/printk.c | 49 ++++++++++++++++++++----------------------------- 1 file changed, 20 insertions(+), 29 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 219ad710a9e8..86f1258d08b0 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -356,7 +356,7 @@ enum log_flags { }; /* syslog_lock protects syslog_* variables and write access to clear_seq. */ -static DEFINE_RAW_SPINLOCK(syslog_lock); +static DEFINE_MUTEX(syslog_lock); #ifdef CONFIG_PRINTK DECLARE_WAIT_QUEUE_HEAD(log_wait); @@ -1497,9 +1497,9 @@ static int syslog_print(char __user *buf, int size) size_t n; size_t skip; - raw_spin_lock_irq(&syslog_lock); + mutex_lock(&syslog_lock); if (!prb_read_valid(prb, syslog_seq, &r)) { - raw_spin_unlock_irq(&syslog_lock); + mutex_unlock(&syslog_lock); break; } if (r.info->seq != syslog_seq) { @@ -1528,7 +1528,7 @@ static int syslog_print(char __user *buf, int size) syslog_partial += n; } else n = 0; - raw_spin_unlock_irq(&syslog_lock); + mutex_unlock(&syslog_lock); if (!n) break; @@ -1592,9 +1592,9 @@ static int syslog_print_all(char __user *buf, int size, bool clear) } if (clear) { - raw_spin_lock_irq(&syslog_lock); + mutex_lock(&syslog_lock); latched_seq_write(&clear_seq, seq); - raw_spin_unlock_irq(&syslog_lock); + mutex_unlock(&syslog_lock); } kfree(text); @@ -1603,21 +1603,9 @@ static int syslog_print_all(char __user *buf, int size, bool clear) static void syslog_clear(void) { - raw_spin_lock_irq(&syslog_lock); + mutex_lock(&syslog_lock); latched_seq_write(&clear_seq, prb_next_seq(prb)); - raw_spin_unlock_irq(&syslog_lock); -} - -/* Return a consistent copy of @syslog_seq. */ -static u64 read_syslog_seq_irq(void) -{ - u64 seq; - - raw_spin_lock_irq(&syslog_lock); - seq = syslog_seq; - raw_spin_unlock_irq(&syslog_lock); - - return seq; + mutex_unlock(&syslog_lock); } int do_syslog(int type, char __user *buf, int len, int source) @@ -1626,6 +1614,7 @@ int do_syslog(int type, char __user *buf, int len, int source) bool clear = false; static int saved_console_loglevel = LOGLEVEL_DEFAULT; int error; + u64 seq; error = check_syslog_permissions(type, source); if (error) @@ -1644,8 +1633,12 @@ int do_syslog(int type, char __user *buf, int len, int source) if (!access_ok(buf, len)) return -EFAULT; - error = wait_event_interruptible(log_wait, - prb_read_valid(prb, read_syslog_seq_irq(), NULL)); + /* Get a consistent copy of @syslog_seq. */ + mutex_lock(&syslog_lock); + seq = syslog_seq; + mutex_unlock(&syslog_lock); + + error = wait_event_interruptible(log_wait, prb_read_valid(prb, seq, NULL)); if (error) return error; error = syslog_print(buf, len); @@ -1693,10 +1686,10 @@ int do_syslog(int type, char __user *buf, int len, int source) break; /* Number of chars in the log buffer */ case SYSLOG_ACTION_SIZE_UNREAD: - raw_spin_lock_irq(&syslog_lock); + mutex_lock(&syslog_lock); if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) { /* No unread messages. */ - raw_spin_unlock_irq(&syslog_lock); + mutex_unlock(&syslog_lock); return 0; } if (info.seq != syslog_seq) { @@ -1714,7 +1707,6 @@ int do_syslog(int type, char __user *buf, int len, int source) } else { bool time = syslog_partial ? syslog_time : printk_time; unsigned int line_count; - u64 seq; prb_for_each_info(syslog_seq, prb, seq, &info, &line_count) { @@ -1724,7 +1716,7 @@ int do_syslog(int type, char __user *buf, int len, int source) } error -= syslog_partial; } - raw_spin_unlock_irq(&syslog_lock); + mutex_unlock(&syslog_lock); break; /* Size of the log buffer */ case SYSLOG_ACTION_SIZE_BUFFER: @@ -2929,7 +2921,6 @@ static int try_enable_new_console(struct console *newcon, bool user_specified) */ void register_console(struct console *newcon) { - unsigned long flags; struct console *bcon = NULL; int err; @@ -3034,9 +3025,9 @@ void register_console(struct console *newcon) exclusive_console_stop_seq = console_seq; /* Get a consistent copy of @syslog_seq. */ - raw_spin_lock_irqsave(&syslog_lock, flags); + mutex_lock(&syslog_lock); console_seq = syslog_seq; - raw_spin_unlock_irqrestore(&syslog_lock, flags); + mutex_unlock(&syslog_lock); } console_unlock(); console_sysfs_notify(); -- cgit From 8d909b2333f37e5da84a9e6a2cbe21f52be5f42a Mon Sep 17 00:00:00 2001 From: John Ogness Date: Thu, 15 Jul 2021 21:39:59 +0206 Subject: printk: syslog: close window between wait and read Syslog's SYSLOG_ACTION_READ is supposed to block until the next syslog record can be read, and then it should read that record. However, because @syslog_lock is not held between waking up and reading the record, another reader could read the record first, thus causing SYSLOG_ACTION_READ to return with a value of 0, never having read _anything_. By holding @syslog_lock between waking up and reading, it can be guaranteed that SYSLOG_ACTION_READ blocks until it successfully reads a syslog record (or a real error occurs). Signed-off-by: John Ogness Reviewed-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210715193359.25946-7-john.ogness@linutronix.de --- kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++----------------- 1 file changed, 36 insertions(+), 19 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 86f1258d08b0..65fffa6368c9 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1480,12 +1480,14 @@ static u64 find_first_fitting_seq(u64 start_seq, u64 max_seq, size_t size, return seq; } +/* The caller is responsible for making sure @size is greater than 0. */ static int syslog_print(char __user *buf, int size) { struct printk_info info; struct printk_record r; char *text; int len = 0; + u64 seq; text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL); if (!text) @@ -1493,15 +1495,35 @@ static int syslog_print(char __user *buf, int size) prb_rec_init_rd(&r, &info, text, CONSOLE_LOG_MAX); - while (size > 0) { + mutex_lock(&syslog_lock); + + /* + * Wait for the @syslog_seq record to be available. @syslog_seq may + * change while waiting. + */ + do { + seq = syslog_seq; + + mutex_unlock(&syslog_lock); + len = wait_event_interruptible(log_wait, prb_read_valid(prb, seq, NULL)); + mutex_lock(&syslog_lock); + + if (len) + goto out; + } while (syslog_seq != seq); + + /* + * Copy records that fit into the buffer. The above cycle makes sure + * that the first record is always available. + */ + do { size_t n; size_t skip; + int err; - mutex_lock(&syslog_lock); - if (!prb_read_valid(prb, syslog_seq, &r)) { - mutex_unlock(&syslog_lock); + if (!prb_read_valid(prb, syslog_seq, &r)) break; - } + if (r.info->seq != syslog_seq) { /* message is gone, move to next valid one */ syslog_seq = r.info->seq; @@ -1528,12 +1550,15 @@ static int syslog_print(char __user *buf, int size) syslog_partial += n; } else n = 0; - mutex_unlock(&syslog_lock); if (!n) break; - if (copy_to_user(buf, text + skip, n)) { + mutex_unlock(&syslog_lock); + err = copy_to_user(buf, text + skip, n); + mutex_lock(&syslog_lock); + + if (err) { if (!len) len = -EFAULT; break; @@ -1542,8 +1567,9 @@ static int syslog_print(char __user *buf, int size) len += n; size -= n; buf += n; - } - + } while (size); +out: + mutex_unlock(&syslog_lock); kfree(text); return len; } @@ -1614,7 +1640,6 @@ int do_syslog(int type, char __user *buf, int len, int source) bool clear = false; static int saved_console_loglevel = LOGLEVEL_DEFAULT; int error; - u64 seq; error = check_syslog_permissions(type, source); if (error) @@ -1632,15 +1657,6 @@ int do_syslog(int type, char __user *buf, int len, int source) return 0; if (!access_ok(buf, len)) return -EFAULT; - - /* Get a consistent copy of @syslog_seq. */ - mutex_lock(&syslog_lock); - seq = syslog_seq; - mutex_unlock(&syslog_lock); - - error = wait_event_interruptible(log_wait, prb_read_valid(prb, seq, NULL)); - if (error) - return error; error = syslog_print(buf, len); break; /* Read/clear last kernel messages */ @@ -1707,6 +1723,7 @@ int do_syslog(int type, char __user *buf, int len, int source) } else { bool time = syslog_partial ? syslog_time : printk_time; unsigned int line_count; + u64 seq; prb_for_each_info(syslog_seq, prb, seq, &info, &line_count) { -- cgit From fe8e3ee0d588566c1f44f28a555042ef50eba491 Mon Sep 17 00:00:00 2001 From: Andy Shevchenko Date: Tue, 27 Jul 2021 18:01:32 +0300 Subject: lib/test_scanf: Handle n_bits == 0 in random tests UBSAN reported (via LKP) [ 11.021349][ T1] UBSAN: shift-out-of-bounds in lib/test_scanf.c:275:51 [ 11.022782][ T1] shift exponent 32 is too large for 32-bit type 'unsigned int' When n_bits == 0, the shift is out of range. Switch code to use GENMASK to handle this case. Fixes: 50f530e176ea ("lib: test_scanf: Add tests for sscanf number conversion") Reported-by: kernel test robot Signed-off-by: Andy Shevchenko Reviewed-by: Richard Fitzgerald Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210727150132.28920-1-andriy.shevchenko@linux.intel.com --- lib/test_scanf.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/test_scanf.c b/lib/test_scanf.c index 48ff5747a4da..6a828dfc8ea1 100644 --- a/lib/test_scanf.c +++ b/lib/test_scanf.c @@ -271,7 +271,7 @@ static u32 __init next_test_random(u32 max_bits) { u32 n_bits = hweight32(prandom_u32_state(&rnd_state)) % (max_bits + 1); - return prandom_u32_state(&rnd_state) & (UINT_MAX >> (32 - n_bits)); + return prandom_u32_state(&rnd_state) & GENMASK(n_bits, 0); } static unsigned long long __init next_test_random_ull(void) @@ -280,7 +280,7 @@ static unsigned long long __init next_test_random_ull(void) u32 n_bits = (hweight32(rand1) * 3) % 64; u64 val = (u64)prandom_u32_state(&rnd_state) * rand1; - return val & (ULLONG_MAX >> (64 - n_bits)); + return val & GENMASK_ULL(n_bits, 0); } #define random_for_type(T) \ -- cgit From c9110dfcfccb3f31eda47a36ed0a022e390d1417 Mon Sep 17 00:00:00 2001 From: Dmitry Safonov Date: Tue, 27 Jul 2021 14:06:34 +0100 Subject: printk: Remove console_silent() It' unused since removal of mn10300: commit 739d875dd698 ("mn10300: Remove the architecture") x86 stopped using it in v2.6.12 (see history git): commit 7574828b3dbb ("[PATCH] x86_64: add nmi button support") Let's clean it up from the header. Signed-off-by: Dmitry Safonov Reviewed-by: Petr Mladek Reviewed-by: Sergey Senozhatsky Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210727130635.675184-2-dima@arista.com --- include/linux/printk.h | 5 ----- 1 file changed, 5 deletions(-) diff --git a/include/linux/printk.h b/include/linux/printk.h index 1790a5521fd9..f3f1a1eb19bd 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -69,11 +69,6 @@ extern int console_printk[]; #define minimum_console_loglevel (console_printk[2]) #define default_console_loglevel (console_printk[3]) -static inline void console_silent(void) -{ - console_loglevel = CONSOLE_LOGLEVEL_SILENT; -} - static inline void console_verbose(void) { if (console_loglevel) -- cgit From 10102a890b543a8a08457dc69fa55bc032403c7d Mon Sep 17 00:00:00 2001 From: Dmitry Safonov Date: Tue, 27 Jul 2021 14:06:35 +0100 Subject: printk: Add printk.console_no_auto_verbose boot parameter console_verbose() increases console loglevel to CONSOLE_LOGLEVEL_MOTORMOUTH, which provides more information to debug a panic/oops. Unfortunately, in Arista we maintain some DUTs (Device Under Test) that are configured to have 9600 baud rate. While verbose console messages have their value to post-analyze crashes, on such setup they: - may prevent panic/oops messages being printed - take too long to flush on console resulting in watchdog reboot In all our setups we use kdump which saves dmesg buffer after panic, so in reality those extra messages on console provide no additional value, but rather add risk of not getting to __crash_kexec(). Provide printk.console_no_auto_verbose boot parameter, which allows to switch off printk being verbose on oops/panic/lockdep. Cc: Andrew Morton Cc: John Ogness Cc: Petr Mladek Cc: Sergey Senozhatsky Cc: Steven Rostedt Signed-off-by: Dmitry Safonov Suggested-by: Petr Mladek Reviewed-by: Sergey Senozhatsky Reviewed-by: Petr Mladek Tested-by: Petr Mladek Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210727130635.675184-3-dima@arista.com --- Documentation/admin-guide/kernel-parameters.txt | 9 +++++++++ include/linux/printk.h | 6 +----- kernel/printk/printk.c | 12 ++++++++++++ 3 files changed, 22 insertions(+), 5 deletions(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 26453f250683..fdd80888217a 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -4101,6 +4101,15 @@ Format: (1/Y/y=enable, 0/N/n=disable) default: disabled + printk.console_no_auto_verbose= + Disable console loglevel raise on oops, panic + or lockdep-detected issues (only if lock debug is on). + With an exception to setups with low baudrate on + serial console, keeping this 0 is a good choice + in order to provide more debug information. + Format: + default: 0 (auto_verbose is enabled) + printk.devkmsg={on,off,ratelimit} Control writing to /dev/kmsg. on - unlimited logging to /dev/kmsg from userspace diff --git a/include/linux/printk.h b/include/linux/printk.h index f3f1a1eb19bd..a5e1c5adfc3f 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -69,11 +69,7 @@ extern int console_printk[]; #define minimum_console_loglevel (console_printk[2]) #define default_console_loglevel (console_printk[3]) -static inline void console_verbose(void) -{ - if (console_loglevel) - console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH; -} +extern void console_verbose(void); /* strlen("ratelimit") + 1 */ #define DEVKMSG_STR_MAX_SIZE 10 diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 142a58d124d9..a6b94c3c5ac5 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2404,6 +2404,18 @@ module_param_named(console_suspend, console_suspend_enabled, MODULE_PARM_DESC(console_suspend, "suspend console during suspend" " and hibernate operations"); +static bool printk_console_no_auto_verbose; + +void console_verbose(void) +{ + if (console_loglevel && !printk_console_no_auto_verbose) + console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH; +} +EXPORT_SYMBOL_GPL(console_verbose); + +module_param_named(console_no_auto_verbose, printk_console_no_auto_verbose, bool, 0644); +MODULE_PARM_DESC(console_no_auto_verbose, "Disable console loglevel raise to highest on oops/panic/etc"); + /** * suspend_console - suspend the console subsystem * -- cgit From 26d1982fd17c2cac77f9cf764255362ccb28fe49 Mon Sep 17 00:00:00 2001 From: Petr Mladek Date: Tue, 27 Jul 2021 10:09:39 +0200 Subject: lib/nmi_backtrace: Serialize even messages about idle CPUs The commit 55d6af1d66885059ffc2a ("lib/nmi_backtrace: explicitly serialize banner and regs") serialized backtraces from more CPUs using the re-entrant printk_printk_cpu lock. It was a preparation step for removing the obsolete nmi_safe buffers. The single-line messages about idle CPUs were not serialized against other CPUs and might appear in the middle of backtrace from another CPU, for example: [56394.590068] NMI backtrace for cpu 2 [56394.590069] CPU: 2 PID: 444 Comm: systemd-journal Not tainted 5.14.0-rc1-default+ #268 [56394.590071] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-59-gc9ba527-rebuilt.opensuse.org 04/01/2014 [56394.590072] RIP: 0010:lock_is_held_type+0x0/0x120 [56394.590071] NMI backtrace for cpu 0 skipped: idling at native_safe_halt+0xb/0x10 [56394.590076] Code: a2 38 ff 0f 0b 8b 44 24 04 eb bd 48 8d ... [56394.590077] RSP: 0018:ffffab02c07c7e68 EFLAGS: 00000246 [56394.590079] RAX: 0000000000000000 RBX: ffff9a7bc0ec8a40 RCX: ffffffffaab8eb40 It might cause confusion what CPU the following lines belongs to and whether the backtraces are really serialized. Prevent the confusion and serialize also the single line message against other CPUs. Fixes: 55d6af1d66885059ffc2a ("lib/nmi_backtrace: explicitly serialize banner and regs") Reviewed-by: John Ogness Reviewed-by: Sergey Senozhatsky Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210727080939.27193-1-pmladek@suse.com --- lib/nmi_backtrace.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c index 9813a983d024..f9e89001b52e 100644 --- a/lib/nmi_backtrace.c +++ b/lib/nmi_backtrace.c @@ -89,22 +89,22 @@ bool nmi_cpu_backtrace(struct pt_regs *regs) unsigned long flags; if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) { + /* + * Allow nested NMI backtraces while serializing + * against other CPUs. + */ + printk_cpu_lock_irqsave(flags); if (!READ_ONCE(backtrace_idle) && regs && cpu_in_idle(instruction_pointer(regs))) { pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n", cpu, (void *)instruction_pointer(regs)); } else { - /* - * Allow nested NMI backtraces while serializing - * against other CPUs. - */ - printk_cpu_lock_irqsave(flags); pr_warn("NMI backtrace for cpu %d\n", cpu); if (regs) show_regs(regs); else dump_stack(); - printk_cpu_unlock_irqrestore(flags); } + printk_cpu_unlock_irqrestore(flags); cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask)); return true; } -- cgit From bc17bed5fd73ef1a9aed39f3b0ea26936dad60b8 Mon Sep 17 00:00:00 2001 From: YueHaibing Date: Wed, 4 Aug 2021 21:01:05 +0800 Subject: printk/index: Fix -Wunused-function warning MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit If CONFIG_MODULES is n, we got this: kernel/printk/index.c:146:13: warning: ‘pi_remove_file’ defined but not used [-Wunused-function] Move it inside #ifdef block to fix this warning. Reported-by: Hulk Robot Signed-off-by: YueHaibing Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20210804130105.18732-1-yuehaibing@huawei.com --- kernel/printk/index.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/kernel/printk/index.c b/kernel/printk/index.c index 58d27272f992..d3709408debe 100644 --- a/kernel/printk/index.c +++ b/kernel/printk/index.c @@ -143,12 +143,12 @@ static void pi_create_file(struct module *mod) mod, &dfs_index_fops); } +#ifdef CONFIG_MODULES static void pi_remove_file(struct module *mod) { debugfs_remove(debugfs_lookup(pi_get_module_name(mod), dfs_index)); } -#ifdef CONFIG_MODULES static int pi_module_notify(struct notifier_block *nb, unsigned long op, void *data) { -- cgit