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 --- 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 +- 10 files changed, 16 insertions(+), 15 deletions(-) (limited to 'arch') 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 -- cgit v1.2.3 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(-) (limited to 'arch') 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 v1.2.3 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 ----- 2 files changed, 6 deletions(-) (limited to 'arch') 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(); -- cgit v1.2.3 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 +- 2 files changed, 3 insertions(+), 3 deletions(-) (limited to 'arch') 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 -- cgit v1.2.3