linux-kernel - Re: [PATCH v2] printk: Make console tracepoint safe in NMI() context

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-ID: <20220718160601.GF1790663@paulmck-ThinkPad-P17-Gen-1>
Date:   Mon, 18 Jul 2022 09:06:01 -0700
From:   "Paul E. McKenney" <paulmck@...nel.org>
To:     Petr Mladek <pmladek@...e.com>
Cc:     Steven Rostedt <rostedt@...dmis.org>,
        John Ogness <john.ogness@...utronix.de>,
        Sergey Senozhatsky <senozhatsky@...omium.org>,
        Marco Elver <elver@...gle.com>, kasan-dev@...glegroups.com,
        Thomas Gleixner <tglx@...utronix.de>,
        Johannes Berg <johannes.berg@...el.com>,
        Alexander Potapenko <glider@...gle.com>,
        Dmitry Vyukov <dvyukov@...gle.com>,
        Naresh Kamboju <naresh.kamboju@...aro.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Linux Kernel Functional Testing <lkft@...aro.org>,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2] printk: Make console tracepoint safe in NMI() context

On Mon, Jul 18, 2022 at 05:11:43PM +0200, Petr Mladek wrote:
> The commit 701850dc0c31bfadf75a0 ("printk, tracing: fix console
> tracepoint") moved the tracepoint from console_unlock() to
> vprintk_store(). As a result, it might be called in any
> context and triggered the following warning:
> 
>   WARNING: CPU: 1 PID: 16462 at include/trace/events/printk.h:10 printk_sprint+0x81/0xda
>   Modules linked in: ppdev parport_pc parport
>   CPU: 1 PID: 16462 Comm: event_benchmark Not tainted 5.19.0-rc5-test+ #5
>   Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
>   EIP: printk_sprint+0x81/0xda
>   Code: 89 d8 e8 88 fc 33 00 e9 02 00 00 00 eb 6b 64 a1 a4 b8 91 c1 e8 fd d6 ff ff 84 c0 74 5c 64 a1 14 08 92 c1 a9 00 00 f0 00 74 02 <0f> 0b 64 ff 05 14 08 92 c1 b8 e0 c4 6b c1 e8 a5 dc 00 00 89 c7 e8
>   EAX: 80110001 EBX: c20a52f8 ECX: 0000000c EDX: 6d203036
>   ESI: 3df6004c EDI: 00000000 EBP: c61fbd7c ESP: c61fbd70
>   DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010006
>   CR0: 80050033 CR2: b7efc000 CR3: 05b80000 CR4: 001506f0
>   Call Trace:
>    vprintk_store+0x24b/0x2ff
>    vprintk+0x37/0x4d
>    _printk+0x14/0x16
>    nmi_handle+0x1ef/0x24e
>    ? find_next_bit.part.0+0x13/0x13
>    ? find_next_bit.part.0+0x13/0x13
>    ? function_trace_call+0xd8/0xd9
>    default_do_nmi+0x57/0x1af
>    ? trace_hardirqs_off_finish+0x2a/0xd9
>    ? to_kthread+0xf/0xf
>    exc_nmi+0x9b/0xf4
>    asm_exc_nmi+0xae/0x29c
> 
> It comes from:
> 
>   #define __DO_TRACE(name, args, cond, rcuidle) \
>   [...]
> 		/* srcu can't be used from NMI */	\
> 		WARN_ON_ONCE(rcuidle && in_nmi());	\
> 
> It might be possible to make srcu working in NMI. But it
> would be slower on some architectures. It is not worth
> doing it just because of this tracepoint.
> 
> It would be possible to disable this tracepoint in NMI
> or in rcuidle context. Where the rcuidle context looks
> more rare and thus more acceptable to be ignored.
> 
> Alternative solution would be to move the tracepoint
> back to console code. But the location is less reliable
> by definition. Also the synchronization against other
> tracing messages is much worse.
> 
> Let's ignore the tracepoint in rcuidle context as the least
> evil solution.
> 
> Link: https://lore.kernel.org/r/20220712151655.GU1790663@paulmck-ThinkPad-P17-Gen-1
> 
> Suggested-by: Steven Rostedt <rostedt@...dmis.org>
> Signed-off-by: Petr Mladek <pmladek@...e.com>

>From an RCU viewpoint:

Acked-by: Paul E. McKenney <paulmck@...nel.org>

> ---
> Changes against v1:
> 
>   + use rcu_is_watching() instead of rcu_is_idle_cpu()
> 
> 
>  include/trace/events/printk.h | 9 ++++++++-
>  kernel/printk/printk.c        | 2 +-
>  2 files changed, 9 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/events/printk.h b/include/trace/events/printk.h
> index 13d405b2fd8b..5485513d8838 100644
> --- a/include/trace/events/printk.h
> +++ b/include/trace/events/printk.h
> @@ -7,11 +7,18 @@
>  
>  #include <linux/tracepoint.h>
>  
> -TRACE_EVENT(console,
> +TRACE_EVENT_CONDITION(console,
>  	TP_PROTO(const char *text, size_t len),
>  
>  	TP_ARGS(text, len),
>  
> +	/*
> +	 * trace_console_rcuidle() is not working in NMI. printk()
> +	 * is used more often in NMI than in rcuidle context.
> +	 * Choose the less evil solution here.
> +	 */
> +	TP_CONDITION(rcu_is_watching()),
> +
>  	TP_STRUCT__entry(
>  		__dynamic_array(char, msg, len + 1)
>  	),
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b49c6ff6dca0..bd76a45ecc7f 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2108,7 +2108,7 @@ static u16 printk_sprint(char *text, u16 size, int facility,
>  		}
>  	}
>  
> -	trace_console_rcuidle(text, text_len);
> +	trace_console(text, text_len);
>  
>  	return text_len;
>  }
> -- 
> 2.35.3
>