Re: [PATCH v6] panic: Avoid the extra noise dmesg

[Steven Rostedt]

On Fri,  1 Mar 2019 16:49:46 +0800
Feng Tang <feng.tang@xxxxxxxxx> wrote:

> When kernel panic happens, it will first print the panic call stack,
> then the ending msg like:
> 
> [   35.743249] ---[ end Kernel panic - not syncing: Fatal exception
> [   35.749975] ------------[ cut here ]------------
> 
> The above message are very useful for debugging.
> 
> But if system is configured to not reboot on panic, say the "panic_timeout"
> parameter equals 0, it will likely print out many noisy message like
> WARN() call stack for each and every CPU except the panic one, messages
> like below:
> 
> 	WARNING: CPU: 1 PID: 280 at kernel/sched/core.c:1198 set_task_cpu+0x183/0x190
> 	Call Trace:
> 	<IRQ>
> 	try_to_wake_up
> 	default_wake_function
> 	autoremove_wake_function
> 	__wake_up_common
> 	__wake_up_common_lock
> 	__wake_up
> 	wake_up_klogd_work_func
> 	irq_work_run_list
> 	irq_work_tick
> 	update_process_times
> 	tick_sched_timer
> 	__hrtimer_run_queues
> 	hrtimer_interrupt
> 	smp_apic_timer_interrupt
> 	apic_timer_interrupt
> 
> For people working in console mode, the screen will first show the panic
> call stack, but immediately overridden by these noisy extra messages, which
> makes debugging much more difficult, as the original context gets lost on
> screen.
> 
> Also these noisy messages will confuse some users, as I have seen many bug
> reporters posted the noisy message into bugzilla, instead of the real panic
> call stack and context.
> 
> Adding a flag "suppress_printk" which gets set in panic() to avoid those
> noisy messages, without changing current kernel behavior that both panic
> blinking and sysrq magic key can work as is, suggested by Petr Mladek.
> 
> To verify this, make sure kernel is not configured to reboot on panic and
> in console
>  # echo c > /proc/sysrq-trigger
> to see if console only prints out the panic call stack.
> 

Looks good to me.

Acked-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx>

Andrew, you want to take this patch?

-- Steve

> Suggested-by: Petr Mladek <pmladek@xxxxxxxx>
> Signed-off-by: Feng Tang <feng.tang@xxxxxxxxx>
> Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> Cc: Kees Cook <keescook@xxxxxxxxxxxx>
> Cc: Borislav Petkov <bp@xxxxxxx>
> Cc: Sergey Senozhatsky <sergey.senozhatsky.work@xxxxxxxxx>
> Cc: Petr Mladek <pmladek@xxxxxxxx>
> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
> Cc: Andi Kleen <ak@xxxxxxxxxxxxxxx>
> Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
> Cc: Greg Kroah-Hartman <gregkh@xxxxxxxxxxxxxxxxxxx>
> Cc: Jiri Slaby <jslaby@xxxxxxxx>
> Cc: Sasha Levin <sashal@xxxxxxxxxx>
> ---
> Change log:
> 
>   v6:
>     - change the flag name from "panic_suppress_printk" to
>       suppress_printk, as suggested by Andrew Morton
> 
>   v5:
>     - use a flag to notify printk not to print unimportant
>       messages, while keeping panic blinking and sysrq working,
>       as suggested by Petr Mladek
> 
>   v4:
>     - make the local_irq_enable conditional and default off
>     to cover possible use of interrupt/scheduling, as
>     mentioned by Sergey and Petr
> 
>   v3:
>     - Make the change log clearer as suggested by Andrew Morton
> 
>   v2:
>     - Move the solution from hacking arch/scheduler code back
>     to panic.c
> 
>  drivers/tty/sysrq.c    |  6 ++++++
>  include/linux/printk.h |  2 ++
>  kernel/panic.c         |  3 +++
>  kernel/printk/printk.c | 10 ++++++++++
>  4 files changed, 21 insertions(+)
> 
> diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
> index 1f03078..ddc2d8a 100644
> --- a/drivers/tty/sysrq.c
> +++ b/drivers/tty/sysrq.c
> @@ -527,8 +527,12 @@ void __handle_sysrq(int key, bool check_mask)
>  {
>  	struct sysrq_key_op *op_p;
>  	int orig_log_level;
> +	int orig_suppress_printk;
>  	int i;
>  
> +	orig_suppress_printk = suppress_printk;
> +	suppress_printk = 0;
> +
>  	rcu_sysrq_start();
>  	rcu_read_lock();
>  	/*
> @@ -574,6 +578,8 @@ void __handle_sysrq(int key, bool check_mask)
>  	}
>  	rcu_read_unlock();
>  	rcu_sysrq_end();
> +
> +	suppress_printk = orig_suppress_printk;
>  }
>  
>  void handle_sysrq(int key)
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 77740a5..a010cdf 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -83,6 +83,8 @@ static inline void console_verbose(void)
>  extern char devkmsg_log_str[];
>  struct ctl_table;
>  
> +extern int suppress_printk;
> +
>  struct va_format {
>  	const char *fmt;
>  	va_list *va;
> diff --git a/kernel/panic.c b/kernel/panic.c
> index f121e6b..960fdfa 100644
> --- a/kernel/panic.c
> +++ b/kernel/panic.c
> @@ -326,6 +326,9 @@ void panic(const char *fmt, ...)
>  	}
>  #endif
>  	pr_emerg("---[ end Kernel panic - not syncing: %s ]---\n", buf);
> +
> +	/* Do not scroll important messages printed above */
> +	suppress_printk = 1;
>  	local_irq_enable();
>  	for (i = 0; ; i += PANIC_TIMER_STEP) {
>  		touch_softlockup_watchdog();
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index d3d1703..8f1c19f 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -85,6 +85,12 @@ static DEFINE_SEMAPHORE(console_sem);
>  struct console *console_drivers;
>  EXPORT_SYMBOL_GPL(console_drivers);
>  
> +/*
> + * System may need to suppress printk message under certain
> + * circumstances, like after kernel panic happens.
> + */
> +int __read_mostly suppress_printk;
> +
>  #ifdef CONFIG_LOCKDEP
>  static struct lockdep_map console_lock_dep_map = {
>  	.name = "console_lock"
> @@ -1899,6 +1905,10 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	unsigned long flags;
>  	u64 curr_log_seq;
>  
> +	/* Suppress unimportant messages after panic happens */
> +	if (unlikely(suppress_printk))
> +		return 0;
> +
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
>  		in_sched = true;