printk changes for 5.15

-----BEGIN PGP SIGNATURE-----
 
 iQIzBAABCAAdFiEESH4wyp42V4tXvYsjUqAMR0iAlPIFAmEt+hwACgkQUqAMR0iA
 lPLppBAAiyrUNVmqqtdww+IJajEs1uD/4FqPsysHRwroHBFymJeQG1XCwUpDZ7jj
 6gXT0chxyjQE18gT/W9nf+PSmA9XvIVA1WSR+WCECTNW3YoZXqtgwiHfgnitXYku
 HlmoZLthYeuoXWw2wn+hVLfTRh6VcPHYEaC21jXrs6B1pOXHbvjJ5eTLHlX9oCfL
 UKSK+jFTHAJcn/GskRzviBe0Hpe8fqnkRol2XX13ltxqtQ73MjaGNu7imEH6/Pa7
 /MHXWtuWJtOvuYz17aztQP4Qwh1xy+kakMy3aHucdlxRBTP4PTzzTuQI3L/RYi6l
 +ttD7OHdRwqFAauBLY3bq3uJjYb5v/64ofd8DNnT2CJvtznY8wrPbTdFoSdPcL2Q
 69/opRWHcUwbU/Gt4WLtyQf3Mk0vepgMbbVg1B5SSy55atRZaXMrA2QJ/JeawZTB
 KK6D/mE7ccze/YFzsySunCUVKCm0veoNxEAcakCCZKXSbsvd1MYcIRC0e+2cv6e5
 2NEH7gL4dD+5tqu5nzvIuKDn3NrDQpbi28iUBoFbkxRgcVyvHJ9AGSa62wtb5h3D
 OgkqQMdVKBbjYNeUodPlQPzmXZDasytavyd0/BC/KENOcBvU/8gW++2UZTfsh/1A
 dLjgwFBdyJncQcCS9Abn20/EKntbIMEX8NLa97XWkA3fuzMKtak=
 =yEVq
 -----END PGP SIGNATURE-----

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()
This commit is contained in:
Linus Torvalds 2021-09-01 18:41:13 -07:00
commit df43d90382
38 changed files with 687 additions and 657 deletions

View File

@ -4198,6 +4198,15 @@
Format: <bool> (1/Y/y=enable, 0/N/n=disable) Format: <bool> (1/Y/y=enable, 0/N/n=disable)
default: disabled 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} printk.devkmsg={on,off,ratelimit}
Control writing to /dev/kmsg. Control writing to /dev/kmsg.
on - unlimited logging to /dev/kmsg from userspace on - unlimited logging to /dev/kmsg from userspace

View File

@ -107,9 +107,6 @@ also ``CONFIG_DYNAMIC_DEBUG`` in the case of pr_debug()) is defined.
Function reference Function reference
================== ==================
.. kernel-doc:: kernel/printk/printk.c
:functions: printk
.. kernel-doc:: include/linux/printk.h .. 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 pr_fmt pr_debug pr_devel pr_cont

View File

@ -15021,6 +15021,11 @@ S: Maintained
F: include/linux/printk.h F: include/linux/printk.h
F: kernel/printk/ F: kernel/printk/
PRINTK INDEXING
R: Chris Down <chris@chrisdown.name>
S: Maintained
F: kernel/printk/index.c
PROC FILESYSTEM PROC FILESYSTEM
L: linux-kernel@vger.kernel.org L: linux-kernel@vger.kernel.org
L: linux-fsdevel@vger.kernel.org L: linux-fsdevel@vger.kernel.org

View File

@ -23,7 +23,7 @@ __invalid_entry:
adr r0, strerr adr r0, strerr
mrs r1, ipsr mrs r1, ipsr
mov r2, lr mov r2, lr
bl printk bl _printk
#endif #endif
mov r0, sp mov r0, sp
bl show_regs bl show_regs

View File

@ -667,9 +667,9 @@ static void do_handle_IPI(int ipinr)
break; break;
case IPI_CPU_BACKTRACE: case IPI_CPU_BACKTRACE:
printk_nmi_enter(); printk_deferred_enter();
nmi_cpu_backtrace(get_irq_regs()); nmi_cpu_backtrace(get_irq_regs());
printk_nmi_exit(); printk_deferred_exit();
break; break;
default: default:

View File

@ -202,7 +202,7 @@ finished_setup:
1006: adr r0, .Lbad 1006: adr r0, .Lbad
mov r1, loglvl mov r1, loglvl
mov r2, frame mov r2, frame
bl printk bl _printk
no_frame: ldmfd sp!, {r4 - r9, fp, pc} no_frame: ldmfd sp!, {r4 - r9, fp, pc}
ENDPROC(c_backtrace) ENDPROC(c_backtrace)
.pushsection __ex_table,"a" .pushsection __ex_table,"a"

View File

@ -103,7 +103,7 @@ for_each_frame: tst frame, mask @ Check for address exceptions
1006: adr r0, .Lbad 1006: adr r0, .Lbad
mov r1, loglvl mov r1, loglvl
mov r2, frame mov r2, frame
bl printk bl _printk
no_frame: ldmfd sp!, {r4 - r9, pc} no_frame: ldmfd sp!, {r4 - r9, pc}
ENDPROC(c_backtrace) ENDPROC(c_backtrace)

View File

@ -25,4 +25,4 @@ ENTRY(insl)
ENTRY(outsl) ENTRY(outsl)
adr r0, .Liosl_warning adr r0, .Liosl_warning
mov r1, lr mov r1, lr
b printk b _printk

View File

@ -23,7 +23,7 @@
#ifdef DEBUG #ifdef DEBUG
stmfd sp!, {r0-r3, ip, lr} stmfd sp!, {r0-r3, ip, lr}
ldr r0, =1f ldr r0, =1f
bl printk bl _printk
ldmfd sp!, {r0-r3, ip, lr} ldmfd sp!, {r0-r3, ip, lr}
.pushsection .rodata, "a" .pushsection .rodata, "a"
@ -38,7 +38,7 @@
stmfd sp!, {r0-r3, ip, lr} stmfd sp!, {r0-r3, ip, lr}
mov r1, \arg mov r1, \arg
ldr r0, =1f ldr r0, =1f
bl printk bl _printk
ldmfd sp!, {r0-r3, ip, lr} ldmfd sp!, {r0-r3, ip, lr}
.pushsection .rodata, "a" .pushsection .rodata, "a"
@ -55,7 +55,7 @@
mov r2, \arg2 mov r2, \arg2
mov r1, \arg1 mov r1, \arg1
ldr r0, =1f ldr r0, =1f
bl printk bl _printk
ldmfd sp!, {r0-r3, ip, lr} ldmfd sp!, {r0-r3, ip, lr}
.pushsection .rodata, "a" .pushsection .rodata, "a"

View File

@ -143,9 +143,9 @@ extern long ia64_cmpxchg_called_with_bad_pointer(void);
do { \ do { \
if (_cmpxchg_bugcheck_count-- <= 0) { \ if (_cmpxchg_bugcheck_count-- <= 0) { \
void *ip; \ void *ip; \
extern int printk(const char *fmt, ...); \ extern int _printk(const char *fmt, ...); \
ip = (void *) ia64_getreg(_IA64_REG_IP); \ 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; \ break; \
} \ } \
} while (0) } while (0)

View File

@ -114,7 +114,7 @@ symbol = value
.set push; \ .set push; \
.set reorder; \ .set reorder; \
PTR_LA a0, 8f; \ PTR_LA a0, 8f; \
jal printk; \ jal _printk; \
.set pop; \ .set pop; \
TEXT(string) TEXT(string)
#else #else

View File

@ -551,7 +551,7 @@ EXCEPTION_ENTRY(_external_irq_handler)
l.movhi r3,hi(42f) l.movhi r3,hi(42f)
l.ori r3,r3,lo(42f) l.ori r3,r3,lo(42f)
l.sw 0x0(r1),r3 l.sw 0x0(r1),r3
l.jal printk l.jal _printk
l.sw 0x4(r1),r4 l.sw 0x4(r1),r4
l.addi r1,r1,0x8 l.addi r1,r1,0x8
@ -681,8 +681,8 @@ _syscall_debug:
l.sw -4(r1),r27 l.sw -4(r1),r27
l.sw -8(r1),r11 l.sw -8(r1),r11
l.addi r1,r1,-8 l.addi r1,r1,-8
l.movhi r27,hi(printk) l.movhi r27,hi(_printk)
l.ori r27,r27,lo(printk) l.ori r27,r27,lo(_printk)
l.jalr r27 l.jalr r27
l.nop l.nop
l.addi r1,r1,8 l.addi r1,r1,8

View File

@ -858,7 +858,7 @@ KernelSPE:
ori r3,r3,87f@l ori r3,r3,87f@l
mr r4,r2 /* current */ mr r4,r2 /* current */
lwz r5,_NIP(r1) lwz r5,_NIP(r1)
bl printk bl _printk
#endif #endif
b interrupt_return b interrupt_return
#ifdef CONFIG_PRINTK #ifdef CONFIG_PRINTK

View File

@ -171,7 +171,6 @@ extern void panic_flush_kmsg_start(void)
extern void panic_flush_kmsg_end(void) extern void panic_flush_kmsg_end(void)
{ {
printk_safe_flush_on_panic();
kmsg_dump(KMSG_DUMP_PANIC); kmsg_dump(KMSG_DUMP_PANIC);
bust_spinlocks(0); bust_spinlocks(0);
debug_locks_off(); debug_locks_off();

View File

@ -184,11 +184,6 @@ static void watchdog_smp_panic(int cpu, u64 tb)
wd_smp_unlock(&flags); 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) if (sysctl_hardlockup_all_cpu_backtrace)
trigger_allbutself_cpu_backtrace(); trigger_allbutself_cpu_backtrace();

View File

@ -313,7 +313,7 @@ void default_machine_crash_shutdown(struct pt_regs *regs)
int (*old_handler)(struct pt_regs *regs); int (*old_handler)(struct pt_regs *regs);
/* Avoid hardlocking with irresponsive CPU holding logbuf_lock */ /* Avoid hardlocking with irresponsive CPU holding logbuf_lock */
printk_nmi_enter(); printk_deferred_enter();
/* /*
* This function is only called after the system * This function is only called after the system

View File

@ -38,7 +38,8 @@ extern void panic(const char *fmt, ...)
#define UM_KERN_CONT KERN_CONT #define UM_KERN_CONT KERN_CONT
#ifdef UML_CONFIG_PRINTK #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))); __attribute__ ((format (printf, 1, 2)));
#else #else
static inline int printk(const char *fmt, ...) static inline int printk(const char *fmt, ...)

View File

@ -432,7 +432,7 @@ SYM_FUNC_START(early_ignore_irq)
pushl 32(%esp) pushl 32(%esp)
pushl 40(%esp) pushl 40(%esp)
pushl $int_msg pushl $int_msg
call printk call _printk
call dump_stack call dump_stack

View File

@ -4579,7 +4579,7 @@ static void __dev_printk(const char *level, const struct device *dev,
printk("%s(NULL device *): %pV", level, vaf); printk("%s(NULL device *): %pV", level, vaf);
} }
void dev_printk(const char *level, const struct device *dev, void _dev_printk(const char *level, const struct device *dev,
const char *fmt, ...) const char *fmt, ...)
{ {
struct va_format vaf; struct va_format vaf;
@ -4594,7 +4594,7 @@ void dev_printk(const char *level, const struct device *dev,
va_end(args); va_end(args);
} }
EXPORT_SYMBOL(dev_printk); EXPORT_SYMBOL(_dev_printk);
#define define_dev_printk_level(func, kern_level) \ #define define_dev_printk_level(func, kern_level) \
void func(const struct device *dev, const char *fmt, ...) \ void func(const struct device *dev, const char *fmt, ...) \

View File

@ -483,6 +483,8 @@
\ \
TRACEDATA \ TRACEDATA \
\ \
PRINTK_INDEX \
\
/* Kernel symbol table: Normal symbols */ \ /* Kernel symbol table: Normal symbols */ \
__ksymtab : AT(ADDR(__ksymtab) - LOAD_OFFSET) { \ __ksymtab : AT(ADDR(__ksymtab) - LOAD_OFFSET) { \
__start___ksymtab = .; \ __start___ksymtab = .; \
@ -894,6 +896,17 @@
#define TRACEDATA #define TRACEDATA
#endif #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 \ #define NOTES \
.notes : AT(ADDR(.notes) - LOAD_OFFSET) { \ .notes : AT(ADDR(.notes) - LOAD_OFFSET) { \
__start_notes = .; \ __start_notes = .; \

View File

@ -38,7 +38,7 @@ __printf(3, 4) __cold
int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...); int dev_printk_emit(int level, const struct device *dev, const char *fmt, ...);
__printf(3, 4) __cold __printf(3, 4) __cold
void dev_printk(const char *level, const struct device *dev, void _dev_printk(const char *level, const struct device *dev,
const char *fmt, ...); const char *fmt, ...);
__printf(2, 3) __cold __printf(2, 3) __cold
void _dev_emerg(const struct device *dev, const char *fmt, ...); void _dev_emerg(const struct device *dev, const char *fmt, ...);
@ -69,7 +69,7 @@ static inline void __dev_printk(const char *level, const struct device *dev,
struct va_format *vaf) struct va_format *vaf)
{} {}
static inline __printf(3, 4) 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, ...) const char *fmt, ...)
{} {}
@ -97,25 +97,57 @@ void _dev_info(const struct device *dev, const char *fmt, ...)
#endif #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 * #defines for all the dev_<level> macros to prefix with whatever
* possible use of #define dev_fmt(fmt) ... * possible use of #define dev_fmt(fmt) ...
*/ */
#define dev_emerg(dev, fmt, ...) \ #define dev_emerg(dev, fmt, ...) \
_dev_emerg(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_emerg, KERN_EMERG, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_crit(dev, fmt, ...) \ #define dev_crit(dev, fmt, ...) \
_dev_crit(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_crit, KERN_CRIT, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_alert(dev, fmt, ...) \ #define dev_alert(dev, fmt, ...) \
_dev_alert(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_alert, KERN_ALERT, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_err(dev, fmt, ...) \ #define dev_err(dev, fmt, ...) \
_dev_err(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_err, KERN_ERR, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_warn(dev, fmt, ...) \ #define dev_warn(dev, fmt, ...) \
_dev_warn(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_warn, KERN_WARNING, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_notice(dev, fmt, ...) \ #define dev_notice(dev, fmt, ...) \
_dev_notice(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_notice, KERN_NOTICE, dev, dev_fmt(fmt), ##__VA_ARGS__)
#define dev_info(dev, fmt, ...) \ #define dev_info(dev, fmt, ...) \
_dev_info(dev, dev_fmt(fmt), ##__VA_ARGS__) dev_printk_index_wrap(_dev_info, KERN_INFO, dev, dev_fmt(fmt), ##__VA_ARGS__)
#if defined(CONFIG_DYNAMIC_DEBUG) || \ #if defined(CONFIG_DYNAMIC_DEBUG) || \
(defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE))

View File

@ -116,7 +116,6 @@ extern void rcu_nmi_exit(void);
do { \ do { \
lockdep_off(); \ lockdep_off(); \
arch_nmi_enter(); \ arch_nmi_enter(); \
printk_nmi_enter(); \
BUG_ON(in_nmi() == NMI_MASK); \ BUG_ON(in_nmi() == NMI_MASK); \
__preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET); \ __preempt_count_add(NMI_OFFSET + HARDIRQ_OFFSET); \
} while (0) } while (0)
@ -135,7 +134,6 @@ extern void rcu_nmi_exit(void);
do { \ do { \
BUG_ON(!in_nmi()); \ BUG_ON(!in_nmi()); \
__preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET); \ __preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET); \
printk_nmi_exit(); \
arch_nmi_exit(); \ arch_nmi_exit(); \
lockdep_on(); \ lockdep_on(); \
} while (0) } while (0)

View File

@ -511,6 +511,11 @@ struct module {
struct klp_modinfo *klp_info; struct klp_modinfo *klp_info;
#endif #endif
#ifdef CONFIG_PRINTK_INDEX
unsigned int printk_index_size;
struct pi_entry **printk_index_start;
#endif
#ifdef CONFIG_MODULE_UNLOAD #ifdef CONFIG_MODULE_UNLOAD
/* What modules depend on me? */ /* What modules depend on me? */
struct list_head source_list; struct list_head source_list;

View File

@ -70,16 +70,7 @@ extern int console_printk[];
#define minimum_console_loglevel (console_printk[2]) #define minimum_console_loglevel (console_printk[2])
#define default_console_loglevel (console_printk[3]) #define default_console_loglevel (console_printk[3])
static inline void console_silent(void) extern void console_verbose(void);
{
console_loglevel = CONSOLE_LOGLEVEL_SILENT;
}
static inline void console_verbose(void)
{
if (console_loglevel)
console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH;
}
/* strlen("ratelimit") + 1 */ /* strlen("ratelimit") + 1 */
#define DEVKMSG_STR_MAX_SIZE 10 #define DEVKMSG_STR_MAX_SIZE 10
@ -150,18 +141,6 @@ static inline __printf(1, 2) __cold
void early_printk(const char *s, ...) { } void early_printk(const char *s, ...) { }
#endif #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; struct dev_printk_info;
#ifdef CONFIG_PRINTK #ifdef CONFIG_PRINTK
@ -174,12 +153,22 @@ asmlinkage __printf(1, 0)
int vprintk(const char *fmt, va_list args); int vprintk(const char *fmt, va_list args);
asmlinkage __printf(1, 2) __cold 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_ ! * 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 * 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); 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_lvl(const char *log_lvl) __cold;
extern asmlinkage void dump_stack(void) __cold; extern asmlinkage void dump_stack(void) __cold;
extern void printk_safe_flush(void);
extern void printk_safe_flush_on_panic(void);
#else #else
static inline __printf(1, 0) static inline __printf(1, 0)
int vprintk(const char *s, va_list args) int vprintk(const char *s, va_list args)
@ -218,15 +205,24 @@ int vprintk(const char *s, va_list args)
return 0; return 0;
} }
static inline __printf(1, 2) __cold static inline __printf(1, 2) __cold
int printk(const char *s, ...) int _printk(const char *s, ...)
{ {
return 0; return 0;
} }
static inline __printf(1, 2) __cold static inline __printf(1, 2) __cold
int printk_deferred(const char *s, ...) int _printk_deferred(const char *s, ...)
{ {
return 0; return 0;
} }
static inline void printk_deferred_enter(void)
{
}
static inline void printk_deferred_exit(void)
{
}
static inline int printk_ratelimit(void) static inline int printk_ratelimit(void)
{ {
return 0; 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 dump_stack(void)
{ {
} }
static inline void printk_safe_flush(void)
{
}
static inline void printk_safe_flush_on_panic(void)
{
}
#endif #endif
#ifdef CONFIG_SMP #ifdef CONFIG_SMP
@ -348,6 +336,117 @@ extern int kptr_restrict;
#define pr_fmt(fmt) fmt #define pr_fmt(fmt) fmt
#endif #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 * pr_emerg - Print an emergency-level message
* @fmt: format string * @fmt: format string

View File

@ -775,6 +775,20 @@ config PRINTK_SAFE_LOG_BUF_SHIFT
13 => 8 KB for each CPU 13 => 8 KB for each CPU
12 => 4 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: # 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 very difficult to diagnose system problems, saying N here is
strongly discouraged. strongly discouraged.
config PRINTK_NMI
def_bool y
depends on PRINTK
depends on HAVE_NMI
config BUG config BUG
bool "BUG() support" if EXPERT bool "BUG() support" if EXPERT
default y default y

View File

@ -979,7 +979,6 @@ void crash_kexec(struct pt_regs *regs)
old_cpu = atomic_cmpxchg(&panic_cpu, PANIC_CPU_INVALID, this_cpu); old_cpu = atomic_cmpxchg(&panic_cpu, PANIC_CPU_INVALID, this_cpu);
if (old_cpu == PANIC_CPU_INVALID) { if (old_cpu == PANIC_CPU_INVALID) {
/* This is the 1st CPU which comes here, so go ahead. */ /* This is the 1st CPU which comes here, so go ahead. */
printk_safe_flush_on_panic();
__crash_kexec(regs); __crash_kexec(regs);
/* /*

View File

@ -3355,6 +3355,11 @@ static int find_module_sections(struct module *mod, struct load_info *info)
sizeof(unsigned long), sizeof(unsigned long),
&mod->num_kprobe_blacklist); &mod->num_kprobe_blacklist);
#endif #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 #ifdef CONFIG_HAVE_STATIC_CALL_INLINE
mod->static_call_sites = section_objs(info, ".static_call_sites", mod->static_call_sites = section_objs(info, ".static_call_sites",
sizeof(*mod->static_call_sites), sizeof(*mod->static_call_sites),

View File

@ -248,7 +248,6 @@ void panic(const char *fmt, ...)
* Bypass the panic_cpu check and call __crash_kexec directly. * Bypass the panic_cpu check and call __crash_kexec directly.
*/ */
if (!_crash_kexec_post_notifiers) { if (!_crash_kexec_post_notifiers) {
printk_safe_flush_on_panic();
__crash_kexec(NULL); __crash_kexec(NULL);
/* /*
@ -272,8 +271,6 @@ void panic(const char *fmt, ...)
*/ */
atomic_notifier_call_chain(&panic_notifier_list, 0, buf); 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); kmsg_dump(KMSG_DUMP_PANIC);
/* /*

View File

@ -3,3 +3,4 @@ obj-y = printk.o
obj-$(CONFIG_PRINTK) += printk_safe.o obj-$(CONFIG_PRINTK) += printk_safe.o
obj-$(CONFIG_A11Y_BRAILLE_CONSOLE) += braille.o obj-$(CONFIG_A11Y_BRAILLE_CONSOLE) += braille.o
obj-$(CONFIG_PRINTK) += printk_ringbuffer.o obj-$(CONFIG_PRINTK) += printk_ringbuffer.o
obj-$(CONFIG_PRINTK_INDEX) += index.o

195
kernel/printk/index.c Normal file
View File

@ -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);

View File

@ -6,11 +6,11 @@
#ifdef CONFIG_PRINTK #ifdef CONFIG_PRINTK
#define PRINTK_SAFE_CONTEXT_MASK 0x007ffffff /* Flags for a single printk record. */
#define PRINTK_NMI_DIRECT_CONTEXT_MASK 0x008000000 enum printk_info_flags {
#define PRINTK_NMI_CONTEXT_MASK 0xff0000000 LOG_NEWLINE = 2, /* text ended with a newline */
LOG_CONT = 8, /* text is a fragment of a continuation line */
#define PRINTK_NMI_CONTEXT_OFFSET 0x010000000 };
__printf(4, 0) __printf(4, 0)
int vprintk_store(int facility, int level, 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_default(const char *fmt, va_list args);
__printf(1, 0) int vprintk_deferred(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); bool printk_percpu_data_ready(void);
#define printk_safe_enter_irqsave(flags) \ #define printk_safe_enter_irqsave(flags) \
@ -37,20 +34,10 @@ bool printk_percpu_data_ready(void);
local_irq_restore(flags); \ local_irq_restore(flags); \
} while (0) } 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); void defer_console_output(void);
u16 printk_parse_prefix(const char *text, int *level,
enum printk_info_flags *flags);
#else #else
/* /*
@ -61,9 +48,5 @@ void defer_console_output(void);
#define printk_safe_enter_irqsave(flags) local_irq_save(flags) #define printk_safe_enter_irqsave(flags) local_irq_save(flags)
#define printk_safe_exit_irqrestore(flags) local_irq_restore(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; } static inline bool printk_percpu_data_ready(void) { return false; }
#endif /* CONFIG_PRINTK */ #endif /* CONFIG_PRINTK */

View File

@ -350,13 +350,8 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
* non-prinatable characters are escaped in the "\xff" notation. * 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. */ /* 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 #ifdef CONFIG_PRINTK
DECLARE_WAIT_QUEUE_HEAD(log_wait); DECLARE_WAIT_QUEUE_HEAD(log_wait);
@ -732,27 +727,22 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
if (ret) if (ret)
return ret; return ret;
printk_safe_enter_irq();
if (!prb_read_valid(prb, atomic64_read(&user->seq), r)) { if (!prb_read_valid(prb, atomic64_read(&user->seq), r)) {
if (file->f_flags & O_NONBLOCK) { if (file->f_flags & O_NONBLOCK) {
ret = -EAGAIN; ret = -EAGAIN;
printk_safe_exit_irq();
goto out; goto out;
} }
printk_safe_exit_irq();
ret = wait_event_interruptible(log_wait, ret = wait_event_interruptible(log_wait,
prb_read_valid(prb, atomic64_read(&user->seq), r)); prb_read_valid(prb, atomic64_read(&user->seq), r));
if (ret) if (ret)
goto out; goto out;
printk_safe_enter_irq();
} }
if (r->info->seq != atomic64_read(&user->seq)) { if (r->info->seq != atomic64_read(&user->seq)) {
/* our last seen message is gone, return error and reset */ /* our last seen message is gone, return error and reset */
atomic64_set(&user->seq, r->info->seq); atomic64_set(&user->seq, r->info->seq);
ret = -EPIPE; ret = -EPIPE;
printk_safe_exit_irq();
goto out; goto out;
} }
@ -762,7 +752,6 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
&r->info->dev_info); &r->info->dev_info);
atomic64_set(&user->seq, r->info->seq + 1); atomic64_set(&user->seq, r->info->seq + 1);
printk_safe_exit_irq();
if (len > count) { if (len > count) {
ret = -EINVAL; ret = -EINVAL;
@ -797,7 +786,6 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
if (offset) if (offset)
return -ESPIPE; return -ESPIPE;
printk_safe_enter_irq();
switch (whence) { switch (whence) {
case SEEK_SET: case SEEK_SET:
/* the first record */ /* the first record */
@ -818,7 +806,6 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
default: default:
ret = -EINVAL; ret = -EINVAL;
} }
printk_safe_exit_irq();
return ret; return ret;
} }
@ -833,7 +820,6 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait)
poll_wait(file, &log_wait, wait); poll_wait(file, &log_wait, wait);
printk_safe_enter_irq();
if (prb_read_valid_info(prb, atomic64_read(&user->seq), &info, NULL)) { if (prb_read_valid_info(prb, atomic64_read(&user->seq), &info, NULL)) {
/* return error when data has vanished underneath us */ /* return error when data has vanished underneath us */
if (info.seq != atomic64_read(&user->seq)) if (info.seq != atomic64_read(&user->seq))
@ -841,7 +827,6 @@ static __poll_t devkmsg_poll(struct file *file, poll_table *wait)
else else
ret = EPOLLIN|EPOLLRDNORM; ret = EPOLLIN|EPOLLRDNORM;
} }
printk_safe_exit_irq();
return ret; return ret;
} }
@ -874,9 +859,7 @@ static int devkmsg_open(struct inode *inode, struct file *file)
prb_rec_init_rd(&user->record, &user->info, prb_rec_init_rd(&user->record, &user->info,
&user->text_buf[0], sizeof(user->text_buf)); &user->text_buf[0], sizeof(user->text_buf));
printk_safe_enter_irq();
atomic64_set(&user->seq, prb_first_valid_seq(prb)); atomic64_set(&user->seq, prb_first_valid_seq(prb));
printk_safe_exit_irq();
file->private_data = user; file->private_data = user;
return 0; return 0;
@ -1042,9 +1025,6 @@ static inline void log_buf_add_cpu(void) {}
static void __init set_percpu_data_ready(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; __printk_percpu_data_ready = true;
} }
@ -1082,6 +1062,7 @@ void __init setup_log_buf(int early)
struct prb_desc *new_descs; struct prb_desc *new_descs;
struct printk_info info; struct printk_info info;
struct printk_record r; struct printk_record r;
unsigned int text_size;
size_t new_descs_size; size_t new_descs_size;
size_t new_infos_size; size_t new_infos_size;
unsigned long flags; unsigned long flags;
@ -1142,24 +1123,37 @@ void __init setup_log_buf(int early)
new_descs, ilog2(new_descs_count), new_descs, ilog2(new_descs_count),
new_infos); new_infos);
printk_safe_enter_irqsave(flags); local_irq_save(flags);
log_buf_len = new_log_buf_len; log_buf_len = new_log_buf_len;
log_buf = new_log_buf; log_buf = new_log_buf;
new_log_buf_len = 0; new_log_buf_len = 0;
free = __LOG_BUF_LEN; free = __LOG_BUF_LEN;
prb_for_each_record(0, &printk_rb_static, seq, &r) prb_for_each_record(0, &printk_rb_static, seq, &r) {
free -= add_to_rb(&printk_rb_dynamic, &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; 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)) { if (seq != prb_next_seq(&printk_rb_static)) {
pr_err("dropped %llu messages\n", 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; return seq;
} }
/* The caller is responsible for making sure @size is greater than 0. */
static int syslog_print(char __user *buf, int size) static int syslog_print(char __user *buf, int size)
{ {
struct printk_info info; struct printk_info info;
struct printk_record r; struct printk_record r;
char *text; char *text;
int len = 0; int len = 0;
u64 seq;
text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL); text = kmalloc(CONSOLE_LOG_MAX, GFP_KERNEL);
if (!text) 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); 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 n;
size_t skip; size_t skip;
int err;
printk_safe_enter_irq(); if (!prb_read_valid(prb, syslog_seq, &r))
raw_spin_lock(&syslog_lock);
if (!prb_read_valid(prb, syslog_seq, &r)) {
raw_spin_unlock(&syslog_lock);
printk_safe_exit_irq();
break; break;
}
if (r.info->seq != syslog_seq) { if (r.info->seq != syslog_seq) {
/* message is gone, move to next valid one */ /* message is gone, move to next valid one */
syslog_seq = r.info->seq; syslog_seq = r.info->seq;
@ -1531,13 +1545,15 @@ static int syslog_print(char __user *buf, int size)
syslog_partial += n; syslog_partial += n;
} else } else
n = 0; n = 0;
raw_spin_unlock(&syslog_lock);
printk_safe_exit_irq();
if (!n) if (!n)
break; 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) if (!len)
len = -EFAULT; len = -EFAULT;
break; break;
@ -1546,8 +1562,9 @@ static int syslog_print(char __user *buf, int size)
len += n; len += n;
size -= n; size -= n;
buf += n; buf += n;
} } while (size);
out:
mutex_unlock(&syslog_lock);
kfree(text); kfree(text);
return len; return len;
} }
@ -1566,7 +1583,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
return -ENOMEM; return -ENOMEM;
time = printk_time; time = printk_time;
printk_safe_enter_irq();
/* /*
* Find first record that fits, including all following records, * Find first record that fits, including all following records,
* into the user-provided buffer for this dump. * 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; break;
} }
printk_safe_exit_irq();
if (copy_to_user(buf + len, text, textlen)) if (copy_to_user(buf + len, text, textlen))
len = -EFAULT; len = -EFAULT;
else else
len += textlen; len += textlen;
printk_safe_enter_irq();
if (len < 0) if (len < 0)
break; break;
} }
if (clear) { if (clear) {
raw_spin_lock(&syslog_lock); mutex_lock(&syslog_lock);
latched_seq_write(&clear_seq, seq); latched_seq_write(&clear_seq, seq);
raw_spin_unlock(&syslog_lock); mutex_unlock(&syslog_lock);
} }
printk_safe_exit_irq();
kfree(text); kfree(text);
return len; return len;
@ -1611,23 +1624,9 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
static void syslog_clear(void) static void syslog_clear(void)
{ {
printk_safe_enter_irq(); mutex_lock(&syslog_lock);
raw_spin_lock(&syslog_lock);
latched_seq_write(&clear_seq, prb_next_seq(prb)); latched_seq_write(&clear_seq, prb_next_seq(prb));
raw_spin_unlock(&syslog_lock); mutex_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;
} }
int do_syslog(int type, char __user *buf, int len, int source) 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; return 0;
if (!access_ok(buf, len)) if (!access_ok(buf, len))
return -EFAULT; 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); error = syslog_print(buf, len);
break; break;
/* Read/clear last kernel messages */ /* Read/clear last kernel messages */
@ -1703,12 +1697,10 @@ int do_syslog(int type, char __user *buf, int len, int source)
break; break;
/* Number of chars in the log buffer */ /* Number of chars in the log buffer */
case SYSLOG_ACTION_SIZE_UNREAD: case SYSLOG_ACTION_SIZE_UNREAD:
printk_safe_enter_irq(); mutex_lock(&syslog_lock);
raw_spin_lock(&syslog_lock);
if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) { if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) {
/* No unread messages. */ /* No unread messages. */
raw_spin_unlock(&syslog_lock); mutex_unlock(&syslog_lock);
printk_safe_exit_irq();
return 0; return 0;
} }
if (info.seq != syslog_seq) { if (info.seq != syslog_seq) {
@ -1736,8 +1728,7 @@ int do_syslog(int type, char __user *buf, int len, int source)
} }
error -= syslog_partial; error -= syslog_partial;
} }
raw_spin_unlock(&syslog_lock); mutex_unlock(&syslog_lock);
printk_safe_exit_irq();
break; break;
/* Size of the log buffer */ /* Size of the log buffer */
case SYSLOG_ACTION_SIZE_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; int printk_delay_msec __read_mostly;
static inline void printk_delay(void) 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. * @text: The terminated text message.
* @level: A pointer to the current level value, will be updated. * @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. * @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 * Otherwise the variable pointed to by @level must be set to
* LOGLEVEL_DEFAULT in order to be updated with the parsed value. * 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. * @flags 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 * Otherwise the variable pointed to by @flags will be OR'd with the parsed
* value. * value.
* *
* Return: The length of the parsed level and control flags. * 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; u16 prefix_len = 0;
int kern_level; int kern_level;
@ -1993,8 +2055,8 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
*level = kern_level - '0'; *level = kern_level - '0';
break; break;
case 'c': /* KERN_CONT */ case 'c': /* KERN_CONT */
if (lflags) if (flags)
*lflags |= LOG_CONT; *flags |= LOG_CONT;
} }
prefix_len += 2; prefix_len += 2;
@ -2004,8 +2066,9 @@ static u16 parse_prefix(char *text, int *level, enum log_flags *lflags)
return prefix_len; return prefix_len;
} }
static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags, static u16 printk_sprint(char *text, u16 size, int facility,
const char *fmt, va_list args) enum printk_info_flags *flags, const char *fmt,
va_list args)
{ {
u16 text_len; 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. */ /* Mark and strip a trailing newline. */
if (text_len && text[text_len - 1] == '\n') { if (text_len && text[text_len - 1] == '\n') {
text_len--; text_len--;
*lflags |= LOG_NEWLINE; *flags |= LOG_NEWLINE;
} }
/* Strip log level and control flags. */ /* Strip log level and control flags. */
if (facility == 0) { if (facility == 0) {
u16 prefix_len; u16 prefix_len;
prefix_len = parse_prefix(text, NULL, NULL); prefix_len = printk_parse_prefix(text, NULL, NULL);
if (prefix_len) { if (prefix_len) {
text_len -= prefix_len; text_len -= prefix_len;
memmove(text, text + prefix_len, text_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(); const u32 caller_id = printk_caller_id();
struct prb_reserved_entry e; struct prb_reserved_entry e;
enum log_flags lflags = 0; enum printk_info_flags flags = 0;
struct printk_record r; struct printk_record r;
unsigned long irqflags;
u16 trunc_msg_len = 0; u16 trunc_msg_len = 0;
char prefix_buf[8]; char prefix_buf[8];
u8 *recursion_ptr;
u16 reserve_size; u16 reserve_size;
va_list args2; va_list args2;
u16 text_len; u16 text_len;
int ret = 0;
u64 ts_nsec; u64 ts_nsec;
/* /*
@ -2055,6 +2121,9 @@ int vprintk_store(int facility, int level,
*/ */
ts_nsec = local_clock(); 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 * 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 * 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. */ /* Extract log level or control flags. */
if (facility == 0) if (facility == 0)
parse_prefix(&prefix_buf[0], &level, &lflags); printk_parse_prefix(&prefix_buf[0], &level, &flags);
if (level == LOGLEVEL_DEFAULT) if (level == LOGLEVEL_DEFAULT)
level = default_message_loglevel; level = default_message_loglevel;
if (dev_info) if (dev_info)
lflags |= LOG_NEWLINE; flags |= LOG_NEWLINE;
if (lflags & LOG_CONT) { if (flags & LOG_CONT) {
prb_rec_init_wr(&r, reserve_size); prb_rec_init_wr(&r, reserve_size);
if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) { 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, 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; r.info->text_len += text_len;
if (lflags & LOG_NEWLINE) { if (flags & LOG_NEWLINE) {
r.info->flags |= LOG_NEWLINE; r.info->flags |= LOG_NEWLINE;
prb_final_commit(&e); prb_final_commit(&e);
} else { } else {
prb_commit(&e); 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); prb_rec_init_wr(&r, reserve_size + trunc_msg_len);
if (!prb_reserve(&e, prb, &r)) if (!prb_reserve(&e, prb, &r))
return 0; goto out;
} }
/* fill message */ /* 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) if (trunc_msg_len)
memcpy(&r.text_buf[text_len], trunc_msg, 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->text_len = text_len + trunc_msg_len;
r.info->facility = facility; r.info->facility = facility;
r.info->level = level & 7; r.info->level = level & 7;
r.info->flags = lflags & 0x1f; r.info->flags = flags & 0x1f;
r.info->ts_nsec = ts_nsec; r.info->ts_nsec = ts_nsec;
r.info->caller_id = caller_id; r.info->caller_id = caller_id;
if (dev_info) if (dev_info)
memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info)); memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
/* A message without a trailing newline can be continued. */ /* A message without a trailing newline can be continued. */
if (!(lflags & LOG_NEWLINE)) if (!(flags & LOG_NEWLINE))
prb_commit(&e); prb_commit(&e);
else else
prb_final_commit(&e); 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, asmlinkage int vprintk_emit(int facility, int level,
@ -2139,7 +2212,6 @@ asmlinkage int vprintk_emit(int facility, int level,
{ {
int printed_len; int printed_len;
bool in_sched = false; bool in_sched = false;
unsigned long flags;
/* Suppress unimportant messages after panic happens */ /* Suppress unimportant messages after panic happens */
if (unlikely(suppress_printk)) if (unlikely(suppress_printk))
@ -2153,9 +2225,7 @@ asmlinkage int vprintk_emit(int facility, int level,
boot_delay_msec(level); boot_delay_msec(level);
printk_delay(); printk_delay();
printk_safe_enter_irqsave(flags);
printed_len = vprintk_store(facility, level, dev_info, fmt, args); 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 called from the scheduler, we can not call up(). */
if (!in_sched) { if (!in_sched) {
@ -2186,28 +2256,7 @@ int vprintk_default(const char *fmt, va_list args)
} }
EXPORT_SYMBOL_GPL(vprintk_default); EXPORT_SYMBOL_GPL(vprintk_default);
/** asmlinkage __visible int _printk(const char *fmt, ...)
* 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, ...)
{ {
va_list args; va_list args;
int r; int r;
@ -2218,7 +2267,7 @@ asmlinkage __visible int printk(const char *fmt, ...)
return r; return r;
} }
EXPORT_SYMBOL(printk); EXPORT_SYMBOL(_printk);
#else /* CONFIG_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" MODULE_PARM_DESC(console_suspend, "suspend console during suspend"
" and hibernate operations"); " 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 * suspend_console - suspend the console subsystem
* *
@ -2545,6 +2606,7 @@ void console_unlock(void)
bool do_cond_resched, retry; bool do_cond_resched, retry;
struct printk_info info; struct printk_info info;
struct printk_record r; struct printk_record r;
u64 __maybe_unused next_seq;
if (console_suspended) { if (console_suspended) {
up_console_sem(); up_console_sem();
@ -2584,9 +2646,9 @@ again:
for (;;) { for (;;) {
size_t ext_len = 0; size_t ext_len = 0;
int handover;
size_t len; size_t len;
printk_safe_enter_irqsave(flags);
skip: skip:
if (!prb_read_valid(prb, console_seq, &r)) if (!prb_read_valid(prb, console_seq, &r))
break; break;
@ -2636,26 +2698,31 @@ skip:
* were to occur on another CPU, it may wait for this one to * were to occur on another CPU, it may wait for this one to
* finish. This task can not be preempted if there is a * finish. This task can not be preempted if there is a
* waiter waiting to take over. * 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(); console_lock_spinning_enable();
stop_critical_timings(); /* don't trace print latency */ stop_critical_timings(); /* don't trace print latency */
call_console_drivers(ext_text, ext_len, text, len); call_console_drivers(ext_text, ext_len, text, len);
start_critical_timings(); start_critical_timings();
if (console_lock_spinning_disable_and_check()) { handover = console_lock_spinning_disable_and_check();
printk_safe_exit_irqrestore(flags); printk_safe_exit_irqrestore(flags);
if (handover)
return; return;
}
printk_safe_exit_irqrestore(flags);
if (do_cond_resched) if (do_cond_resched)
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(); up_console_sem();
/* /*
@ -2664,9 +2731,7 @@ skip:
* there's a new owner and the console_unlock() from them will do the * there's a new owner and the console_unlock() from them will do the
* flush, no worries. * 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()) if (retry && console_trylock())
goto again; goto again;
} }
@ -2728,13 +2793,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
console_trylock(); console_trylock();
console_may_schedule = 0; console_may_schedule = 0;
if (mode == CONSOLE_REPLAY_ALL) { if (mode == CONSOLE_REPLAY_ALL)
unsigned long flags;
printk_safe_enter_irqsave(flags);
console_seq = prb_first_valid_seq(prb); console_seq = prb_first_valid_seq(prb);
printk_safe_exit_irqrestore(flags);
}
console_unlock(); console_unlock();
} }
@ -2869,7 +2929,6 @@ static int try_enable_new_console(struct console *newcon, bool user_specified)
*/ */
void register_console(struct console *newcon) void register_console(struct console *newcon)
{ {
unsigned long flags;
struct console *bcon = NULL; struct console *bcon = NULL;
int err; int err;
@ -2974,9 +3033,9 @@ void register_console(struct console *newcon)
exclusive_console_stop_seq = console_seq; exclusive_console_stop_seq = console_seq;
/* Get a consistent copy of @syslog_seq. */ /* Get a consistent copy of @syslog_seq. */
raw_spin_lock_irqsave(&syslog_lock, flags); mutex_lock(&syslog_lock);
console_seq = syslog_seq; console_seq = syslog_seq;
raw_spin_unlock_irqrestore(&syslog_lock, flags); mutex_unlock(&syslog_lock);
} }
console_unlock(); console_unlock();
console_sysfs_notify(); console_sysfs_notify();
@ -3203,7 +3262,7 @@ int vprintk_deferred(const char *fmt, va_list args)
return r; return r;
} }
int printk_deferred(const char *fmt, ...) int _printk_deferred(const char *fmt, ...)
{ {
va_list args; va_list args;
int r; int r;
@ -3386,14 +3445,12 @@ bool kmsg_dump_get_line(struct kmsg_dump_iter *iter, bool syslog,
struct printk_info info; struct printk_info info;
unsigned int line_count; unsigned int line_count;
struct printk_record r; struct printk_record r;
unsigned long flags;
size_t l = 0; size_t l = 0;
bool ret = false; bool ret = false;
if (iter->cur_seq < min_seq) if (iter->cur_seq < min_seq)
iter->cur_seq = min_seq; iter->cur_seq = min_seq;
printk_safe_enter_irqsave(flags);
prb_rec_init_rd(&r, &info, line, size); prb_rec_init_rd(&r, &info, line, size);
/* Read text or count text lines? */ /* 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; iter->cur_seq = r.info->seq + 1;
ret = true; ret = true;
out: out:
printk_safe_exit_irqrestore(flags);
if (len) if (len)
*len = l; *len = l;
return ret; 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); u64 min_seq = latched_seq_read_nolock(&clear_seq);
struct printk_info info; struct printk_info info;
struct printk_record r; struct printk_record r;
unsigned long flags;
u64 seq; u64 seq;
u64 next_seq; u64 next_seq;
size_t len = 0; 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) if (iter->cur_seq < min_seq)
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 (prb_read_valid_info(prb, iter->cur_seq, &info, NULL)) {
if (info.seq != iter->cur_seq) { if (info.seq != iter->cur_seq) {
/* messages are gone, move to first available one */ /* 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 */ /* last entry */
if (iter->cur_seq >= iter->next_seq) { if (iter->cur_seq >= iter->next_seq)
printk_safe_exit_irqrestore(flags);
goto out; goto out;
}
/* /*
* Find first record that fits, including all following records, * 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; iter->next_seq = next_seq;
ret = true; ret = true;
printk_safe_exit_irqrestore(flags);
out: out:
if (len_out) if (len_out)
*len_out = len; *len_out = len;
@ -3521,12 +3572,8 @@ EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
*/ */
void kmsg_dump_rewind(struct kmsg_dump_iter *iter) 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->cur_seq = latched_seq_read_nolock(&clear_seq);
iter->next_seq = prb_next_seq(prb); iter->next_seq = prb_next_seq(prb);
printk_safe_exit_irqrestore(flags);
} }
EXPORT_SYMBOL_GPL(kmsg_dump_rewind); EXPORT_SYMBOL_GPL(kmsg_dump_rewind);

View File

@ -4,347 +4,16 @@
*/ */
#include <linux/preempt.h> #include <linux/preempt.h>
#include <linux/spinlock.h>
#include <linux/debug_locks.h>
#include <linux/kdb.h> #include <linux/kdb.h>
#include <linux/smp.h> #include <linux/smp.h>
#include <linux/cpumask.h> #include <linux/cpumask.h>
#include <linux/irq_work.h>
#include <linux/printk.h> #include <linux/printk.h>
#include <linux/kprobes.h> #include <linux/kprobes.h>
#include "internal.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_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. */ /* Can be preempted by NMI. */
void __printk_safe_enter(void) 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 * Use the main logbuf even in NMI. But avoid calling console
* drivers that might have their own locks. * drivers that might have their own locks.
*/ */
if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK)) { if (this_cpu_read(printk_context) || in_nmi()) {
unsigned long flags;
int len; int len;
printk_safe_enter_irqsave(flags);
len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args); len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
printk_safe_exit_irqrestore(flags);
defer_console_output(); defer_console_output();
return len; 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. */ /* No obstacles. */
return vprintk_default(fmt, args); return vprintk_default(fmt, args);
} }
EXPORT_SYMBOL(vprintk); 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();
}

View File

@ -9815,7 +9815,6 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
tracing_off(); tracing_off();
local_irq_save(flags); local_irq_save(flags);
printk_nmi_direct_enter();
/* Simulate the iterator */ /* Simulate the iterator */
trace_init_global_iter(&iter); 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(&per_cpu_ptr(iter.array_buffer->data, cpu)->disabled);
} }
atomic_dec(&dump_running); atomic_dec(&dump_running);
printk_nmi_direct_exit();
local_irq_restore(flags); local_irq_restore(flags);
} }
EXPORT_SYMBOL_GPL(ftrace_dump); EXPORT_SYMBOL_GPL(ftrace_dump);

View File

@ -75,12 +75,6 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask,
touch_softlockup_watchdog(); 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); clear_bit_unlock(0, &backtrace_flag);
put_cpu(); put_cpu();
} }
@ -92,8 +86,14 @@ module_param(backtrace_idle, bool, 0644);
bool nmi_cpu_backtrace(struct pt_regs *regs) bool nmi_cpu_backtrace(struct pt_regs *regs)
{ {
int cpu = smp_processor_id(); int cpu = smp_processor_id();
unsigned long flags;
if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) { 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))) { if (!READ_ONCE(backtrace_idle) && regs && cpu_in_idle(instruction_pointer(regs))) {
pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n", pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n",
cpu, (void *)instruction_pointer(regs)); cpu, (void *)instruction_pointer(regs));
@ -104,6 +104,7 @@ bool nmi_cpu_backtrace(struct pt_regs *regs)
else else
dump_stack(); dump_stack();
} }
printk_cpu_unlock_irqrestore(flags);
cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask)); cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
return true; return true;
} }

View File

@ -361,6 +361,9 @@ static bool escape_special(unsigned char c, char **dst, char *end)
case '\e': case '\e':
to = 'e'; to = 'e';
break; break;
case '"':
to = '"';
break;
default: default:
return false; return false;
} }
@ -474,6 +477,7 @@ static bool escape_hex(unsigned char c, char **dst, char *end)
* '\t' - horizontal tab * '\t' - horizontal tab
* '\v' - vertical tab * '\v' - vertical tab
* %ESCAPE_SPECIAL: * %ESCAPE_SPECIAL:
* '\"' - double quote
* '\\' - backslash * '\\' - backslash
* '\a' - alert (BEL) * '\a' - alert (BEL)
* '\e' - escape * '\e' - escape

View File

@ -140,13 +140,13 @@ static const struct test_string_2 escape0[] __initconst = {{
},{ },{
.in = "\\h\\\"\a\e\\", .in = "\\h\\\"\a\e\\",
.s1 = {{ .s1 = {{
.out = "\\\\h\\\\\"\\a\\e\\\\", .out = "\\\\h\\\\\\\"\\a\\e\\\\",
.flags = ESCAPE_SPECIAL, .flags = ESCAPE_SPECIAL,
},{ },{
.out = "\\\\\\150\\\\\\042\\a\\e\\\\", .out = "\\\\\\150\\\\\\\"\\a\\e\\\\",
.flags = ESCAPE_SPECIAL | ESCAPE_OCTAL, .flags = ESCAPE_SPECIAL | ESCAPE_OCTAL,
},{ },{
.out = "\\\\\\x68\\\\\\x22\\a\\e\\\\", .out = "\\\\\\x68\\\\\\\"\\a\\e\\\\",
.flags = ESCAPE_SPECIAL | ESCAPE_HEX, .flags = ESCAPE_SPECIAL | ESCAPE_HEX,
},{ },{
/* terminator */ /* terminator */
@ -157,10 +157,10 @@ static const struct test_string_2 escape0[] __initconst = {{
.out = "\eb \\C\007\"\x90\\r]", .out = "\eb \\C\007\"\x90\\r]",
.flags = ESCAPE_SPACE, .flags = ESCAPE_SPACE,
},{ },{
.out = "\\eb \\\\C\\a\"\x90\r]", .out = "\\eb \\\\C\\a\\\"\x90\r]",
.flags = ESCAPE_SPECIAL, .flags = ESCAPE_SPECIAL,
},{ },{
.out = "\\eb \\\\C\\a\"\x90\\r]", .out = "\\eb \\\\C\\a\\\"\x90\\r]",
.flags = ESCAPE_SPACE | ESCAPE_SPECIAL, .flags = ESCAPE_SPACE | ESCAPE_SPECIAL,
},{ },{
.out = "\\033\\142\\040\\134\\103\\007\\042\\220\\015\\135", .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", .out = "\\033\\142\\040\\134\\103\\007\\042\\220\\r\\135",
.flags = ESCAPE_SPACE | ESCAPE_OCTAL, .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, .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, .flags = ESCAPE_SPACE | ESCAPE_SPECIAL | ESCAPE_OCTAL,
},{ },{
.out = "\eb \\C\007\"\x90\r]", .out = "\eb \\C\007\"\x90\r]",

View File

@ -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); 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) 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; u32 n_bits = (hweight32(rand1) * 3) % 64;
u64 val = (u64)prandom_u32_state(&rnd_state) * rand1; 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) \ #define random_for_type(T) \