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

From: Steven Rostedt
Date: Fri Mar 01 2019 - 16:57:58 EST


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;