diff options
| author | Linus Torvalds | 2021-09-01 18:41:13 -0700 |
|---|---|---|
| committer | Linus Torvalds | 2021-09-01 18:41:13 -0700 |
| commit | df43d903828c59afb9e93b59835127a02e1f8144 (patch) | |
| tree | 39be64267622b2efe8e2fc39298a4245d76f2337 | |
| parent | 9e5f3ffcf1cb34e7c7beb3f79a96f58536730924 (diff) | |
| parent | c985aafb60e972c0a6b8d0bd65e03af5890b748a (diff) | |
Merge tag 'printk-for-5.15' of git://git.kernel.org/pub/scm/linux/kernel/git/printk/linux
Pull printk updates from Petr Mladek:
- Optionally, provide an index of possible printk messages via
<debugfs>/printk/index/. It can be used when monitoring important
kernel messages on a farm of various hosts. The monitor has to be
updated when some messages has changed or are not longer available by
a newly deployed kernel.
- Add printk.console_no_auto_verbose boot parameter. It allows to
generate crash dump even with slow consoles in a reasonable time
frame.
- Remove printk_safe buffers. The messages are always stored directly
to the main logbuffer, even in NMI or recursive context. Also it
allows to serialize syslog operations by a mutex instead of a spin
lock.
- Misc clean up and build fixes.
* tag 'printk-for-5.15' of git://git.kernel.org/pub/scm/linux/kernel/git/printk/linux:
printk/index: Fix -Wunused-function warning
lib/nmi_backtrace: Serialize even messages about idle CPUs
printk: Add printk.console_no_auto_verbose boot parameter
printk: Remove console_silent()
lib/test_scanf: Handle n_bits == 0 in random tests
printk: syslog: close window between wait and read
printk: convert @syslog_lock to mutex
printk: remove NMI tracking
printk: remove safe buffers
printk: track/limit recursion
lib/nmi_backtrace: explicitly serialize banner and regs
printk: Move the printk() kerneldoc comment to its new home
printk/index: Fix warning about missing prototypes
MIPS/asm/printk: Fix build failure caused by printk
printk: index: Add indexing support to dev_printk
printk: Userspace format indexing support
printk: Rework parse_prefix into printk_parse_prefix
printk: Straighten out log_flags into printk_info_flags
string_helpers: Escape double quotes in escape_special
printk/console: Check consistent sequence number when handling race in console_unlock()
38 files changed, 687 insertions, 657 deletions
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 82c932105d31..84dc5790741b 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -4198,6 +4198,15 @@ Format: <bool> (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: <bool> + 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/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/MAINTAINERS b/MAINTAINERS index 63bddf7b6bf2..0d4b8963f17b 100644 --- a/MAINTAINERS +++ b/MAINTAINERS @@ -15021,6 +15021,11 @@ S: Maintained F: include/linux/printk.h F: kernel/printk/ +PRINTK INDEXING +R: Chris Down <chris@chrisdown.name> +S: Maintained +F: kernel/printk/index.c + PROC FILESYSTEM L: linux-kernel@vger.kernel.org L: linux-fsdevel@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/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/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/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 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/powerpc/kernel/traps.c b/arch/powerpc/kernel/traps.c index d56254f05e17..cd5f633c9b1b 100644 --- a/arch/powerpc/kernel/traps.c +++ b/arch/powerpc/kernel/traps.c @@ -171,7 +171,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 a165635fd214..f9ea0e5357f9 100644 --- a/arch/powerpc/kernel/watchdog.c +++ b/arch/powerpc/kernel/watchdog.c @@ -184,11 +184,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/arch/powerpc/kexec/crash.c b/arch/powerpc/kexec/crash.c index 10f997e6bb95..22ceeeb705ab 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/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/drivers/base/core.c b/drivers/base/core.c index 3a72241b87c6..280425409b40 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/asm-generic/vmlinux.lds.h b/include/asm-generic/vmlinux.lds.h index 62669b36a772..aa50bf2959fe 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 = .; \ @@ -894,6 +896,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/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, ...) {} @@ -98,24 +98,56 @@ 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_<level> infrastructure, so we need to emit here as well as inside those + * level-specific macros. Only one index entry will be produced, either way, + * since dev_printk's `fmt` isn't known at compile time if going through the + * dev_<level> macros. + * + * dev_fmt() isn't called for dev_printk when used directly, as it's used by + * the dev_<level> 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_<level> macros to prefix with whatever * possible use of #define dev_fmt(fmt) ... */ -#define dev_emerg(dev, fmt, ...) \ - _dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_crit(dev, fmt, ...) \ - _dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_alert(dev, fmt, ...) \ - _dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_err(dev, fmt, ...) \ - _dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_warn(dev, fmt, ...) \ - _dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_notice(dev, fmt, ...) \ - _dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__) -#define dev_info(dev, fmt, ...) \ - _dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__) +#define dev_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)) 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/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..259af4f97f50 100644 --- a/include/linux/printk.h +++ b/include/linux/printk.h @@ -70,16 +70,7 @@ 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) - console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH; -} +extern void console_verbose(void); /* strlen("ratelimit") + 1 */ #define DEVKMSG_STR_MAX_SIZE 10 @@ -150,18 +141,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 @@ -174,12 +153,22 @@ 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, ...); + +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 @@ -209,8 +198,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) @@ -218,15 +205,24 @@ 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; } + +static inline void printk_deferred_enter(void) +{ +} + +static inline void printk_deferred_exit(void) +{ +} + static inline int printk_ratelimit(void) { return 0; @@ -278,14 +274,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 @@ -348,6 +336,117 @@ 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__); \ + }) + + +/** + * 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__) + /** * pr_emerg - Print an emergency-level message * @fmt: format string diff --git a/init/Kconfig b/init/Kconfig index 55f9f7738ebb..e708180e9a59 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 <debugfs>/printk/index/<module>. + + This can be used as part of maintaining daemons which monitor + /dev/kmsg, as it permits auditing the printk formats present in a + kernel, allowing detection of cases where monitored printks are + changed or no longer present. + + There is no additional runtime cost to printk with this enabled. + # # Architectures with an unreliable sched_clock() should select this: # @@ -1509,11 +1523,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/kexec_core.c b/kernel/kexec_core.c index 4b34a9aa32bc..5a5d192a89ac 100644 --- a/kernel/kexec_core.c +++ b/kernel/kexec_core.c @@ -979,7 +979,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/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/panic.c b/kernel/panic.c index edad89660a2b..cefd7d82366f 100644 --- a/kernel/panic.c +++ b/kernel/panic.c @@ -248,7 +248,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); /* @@ -272,8 +271,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/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..d3709408debe --- /dev/null +++ b/kernel/printk/index.c @@ -0,0 +1,195 @@ +// SPDX-License-Identifier: GPL-2.0 +/* + * Userspace indexing of printk formats + */ + +#include <linux/debugfs.h> +#include <linux/module.h> +#include <linux/printk.h> +#include <linux/slab.h> +#include <linux/string_helpers.h> + +#include "internal.h" + +extern struct pi_entry *__start_printk_index[]; +extern struct pi_entry *__stop_printk_index[]; + +/* The base dir for module formats, typically debugfs/printk/index/ */ +static struct dentry *dfs_index; + +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, "# <level/flags> filename:line function \"format\"\n"); + return 0; + } + + if (!entry->fmt) + return 0; + + if (entry->level) + printk_parse_prefix(entry->level, &level, &flags); + else + prefix_len = printk_parse_prefix(entry->fmt, &level, &flags); + + + 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, "<c>"); + 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 + +static void pi_create_file(struct module *mod) +{ + debugfs_create_file(pi_get_module_name(mod), 0444, dfs_index, + 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)); +} + +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/internal.h b/kernel/printk/internal.h index 51615c909b2f..9f3ed2fdb721 100644 --- a/kernel/printk/internal.h +++ b/kernel/printk/internal.h @@ -6,11 +6,11 @@ #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 +/* 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, @@ -19,10 +19,7 @@ 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); -void printk_safe_init(void); bool printk_percpu_data_ready(void); #define printk_safe_enter_irqsave(flags) \ @@ -37,20 +34,10 @@ 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); +u16 printk_parse_prefix(const char *text, int *level, + enum printk_info_flags *flags); #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 142a58d124d9..825277e1e742 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -350,13 +350,8 @@ 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); +static DEFINE_MUTEX(syslog_lock); #ifdef CONFIG_PRINTK DECLARE_WAIT_QUEUE_HEAD(log_wait); @@ -732,27 +727,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 +752,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 +786,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 +806,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 +820,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 +827,6 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait) else ret = EPOLLIN|EPOLLRDNORM; } - printk_safe_exit_irq(); return ret; } @@ -874,9 +859,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 +1025,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 +1062,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 +1123,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", @@ -1481,12 +1475,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) @@ -1494,17 +1490,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; - printk_safe_enter_irq(); - raw_spin_lock(&syslog_lock); - if (!prb_read_valid(prb, syslog_seq, &r)) { - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + 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; @@ -1531,13 +1545,15 @@ static int syslog_print(char __user *buf, int size) syslog_partial += n; } else n = 0; - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); 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; @@ -1546,8 +1562,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; } @@ -1566,7 +1583,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 +1603,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); + mutex_lock(&syslog_lock); latched_seq_write(&clear_seq, seq); - raw_spin_unlock(&syslog_lock); + mutex_unlock(&syslog_lock); } - printk_safe_exit_irq(); kfree(text); return len; @@ -1611,23 +1624,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); + mutex_lock(&syslog_lock); latched_seq_write(&clear_seq, prb_next_seq(prb)); - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); -} - -/* 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) @@ -1653,11 +1652,6 @@ int do_syslog(int type, char __user *buf, int len, int source) return 0; if (!access_ok(buf, len)) return -EFAULT; - - error = wait_event_interruptible(log_wait, - prb_read_valid(prb, read_syslog_seq_irq(), NULL)); - if (error) - return error; error = syslog_print(buf, len); break; /* Read/clear last kernel messages */ @@ -1703,12 +1697,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); + mutex_lock(&syslog_lock); if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) { /* No unread messages. */ - raw_spin_unlock(&syslog_lock); - printk_safe_exit_irq(); + mutex_unlock(&syslog_lock); return 0; } if (info.seq != syslog_seq) { @@ -1736,8 +1728,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(); + mutex_unlock(&syslog_lock); break; /* Size of the log buffer */ case SYSLOG_ACTION_SIZE_BUFFER: @@ -1940,6 +1931,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) @@ -1961,23 +2022,24 @@ 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. - * @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) +u16 printk_parse_prefix(const char *text, int *level, + enum printk_info_flags *flags) { u16 prefix_len = 0; int kern_level; @@ -1993,8 +2055,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 +2066,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,14 +2077,14 @@ 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. */ 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); @@ -2038,13 +2101,16 @@ 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; + 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 +2121,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 @@ -2070,29 +2139,30 @@ int vprintk_store(int facility, int level, /* Extract log level or control flags. */ if (facility == 0) - parse_prefix(&prefix_buf[0], &level, &lflags); + printk_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 { prb_commit(&e); } - return text_len; + ret = text_len; + goto out; } } @@ -2108,29 +2178,32 @@ 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 */ - 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); - 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, @@ -2139,7 +2212,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)) @@ -2153,9 +2225,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) { @@ -2186,28 +2256,7 @@ 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. - * - * 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, ...) +asmlinkage __visible int _printk(const char *fmt, ...) { va_list args; int r; @@ -2218,7 +2267,7 @@ asmlinkage __visible int printk(const char *fmt, ...) return r; } -EXPORT_SYMBOL(printk); +EXPORT_SYMBOL(_printk); #else /* CONFIG_PRINTK */ @@ -2404,6 +2453,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 * @@ -2545,6 +2606,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(); @@ -2584,9 +2646,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; @@ -2636,26 +2698,31 @@ 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(); } - 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,9 +2731,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); - printk_safe_exit_irqrestore(flags); - + retry = prb_read_valid(prb, next_seq, NULL); if (retry && console_trylock()) goto again; } @@ -2728,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(); } @@ -2869,7 +2929,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; @@ -2974,9 +3033,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(); @@ -3203,7 +3262,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; @@ -3386,14 +3445,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? */ @@ -3414,7 +3471,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; @@ -3446,7 +3502,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; @@ -3459,7 +3514,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 */ @@ -3468,10 +3522,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, @@ -3503,7 +3555,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; @@ -3521,12 +3572,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..ef0f9a2044da 100644 --- a/kernel/printk/printk_safe.c +++ b/kernel/printk/printk_safe.c @@ -4,347 +4,16 @@ */ #include <linux/preempt.h> -#include <linux/spinlock.h> -#include <linux/debug_locks.h> #include <linux/kdb.h> #include <linux/smp.h> #include <linux/cpumask.h> -#include <linux/irq_work.h> #include <linux/printk.h> #include <linux/kprobes.h> #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); -} - -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. - * - * 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) -{ - 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); -} - -#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 +38,15 @@ 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) || in_nmi()) { 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/kernel/trace/trace.c b/kernel/trace/trace.c index a1adb29ef5c1..2755534b0737 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -9815,7 +9815,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); @@ -9897,7 +9896,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); diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c index 8abe1870dba4..f9e89001b52e 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(); } @@ -92,8 +86,14 @@ 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))) { + /* + * 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)); @@ -104,6 +104,7 @@ bool nmi_cpu_backtrace(struct pt_regs *regs) else dump_stack(); } + printk_cpu_unlock_irqrestore(flags); cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask)); return true; } 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]", diff --git a/lib/test_scanf.c b/lib/test_scanf.c index 84fe09eaf55e..abae88848972 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) \ |