linux-serial.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 0/2] printk: Add loud_console printk flag to not suppress sysrq header msgs
@ 2024-10-16 17:03 Marcos Paulo de Souza
  2024-10-16 17:03 ` [PATCH 1/2] printk: Introduce LOUD_CON flag Marcos Paulo de Souza
  2024-10-16 17:03 ` [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq Marcos Paulo de Souza
  0 siblings, 2 replies; 14+ messages in thread
From: Marcos Paulo de Souza @ 2024-10-16 17:03 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby
  Cc: linux-kernel, linux-serial, Marcos Paulo de Souza

Hello,

These two patches will change printk_context to store a new context,
called loud console. By using this context it would be possible to have
printk messages that are never suppressed by loglevel filtering.

This is useful on __handle_sysrq that currently uses a workaround to
make sure that sysrq header message are not suppressed.

Please review!

Signed-off-by: Marcos Paulo de Souza <mpdesouza@suse.com>
---
Marcos Paulo de Souza (2):
      printk: Introduce LOUD_CON flag
      tty: sysrq: Use printk_loud_console context on __handle_sysrq

 drivers/tty/sysrq.c         | 18 ++++++++----------
 include/linux/printk.h      |  3 +++
 kernel/printk/internal.h    |  3 +++
 kernel/printk/printk.c      |  8 +++++++-
 kernel/printk/printk_safe.c | 27 +++++++++++++++++++++++++--
 5 files changed, 46 insertions(+), 13 deletions(-)
---
base-commit: 1d227fcc72223cbdd34d0ce13541cbaab5e0d72f
change-id: 20241016-printk-loud-con-03b393d5f6fb

Best regards,
-- 
Marcos Paulo de Souza <mpdesouza@suse.com>


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-16 17:03 [PATCH 0/2] printk: Add loud_console printk flag to not suppress sysrq header msgs Marcos Paulo de Souza
@ 2024-10-16 17:03 ` Marcos Paulo de Souza
  2024-10-16 18:11   ` John Ogness
  2024-10-19  1:28   ` kernel test robot
  2024-10-16 17:03 ` [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq Marcos Paulo de Souza
  1 sibling, 2 replies; 14+ messages in thread
From: Marcos Paulo de Souza @ 2024-10-16 17:03 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby
  Cc: linux-kernel, linux-serial, Marcos Paulo de Souza

Introduce LOUD_CON flag to printk. The new flag will make it possible to
create a context where printk messages will never be suppressed. This
new context information will be stored in the already existing
printk_context per-CPU variable. This variable was changed from 'int' to
'unsigned int' to avoid issues with automatic casting.

This mechanism will be used in the next patch to create a loud_console
context on sysrq handling, removing an existing workaround on the
loglevel global variable. The workaround existed to make sure that sysrq
header messages were sent to all consoles.

Signed-off-by: Marcos Paulo de Souza <mpdesouza@suse.com>
---
 include/linux/printk.h      |  3 +++
 kernel/printk/internal.h    |  3 +++
 kernel/printk/printk.c      |  8 +++++++-
 kernel/printk/printk_safe.c | 27 +++++++++++++++++++++++++--
 4 files changed, 38 insertions(+), 3 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index eca9bb2ee637..0ac9879d94ac 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -166,6 +166,9 @@ __printf(1, 2) __cold int _printk_deferred(const char *fmt, ...);
 extern void __printk_deferred_enter(void);
 extern void __printk_deferred_exit(void);
 
+extern void printk_loud_console_enter(void);
+extern void printk_loud_console_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
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 3fcb48502adb..2649e8a66cef 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -53,6 +53,8 @@ int devkmsg_sysctl_set_loglvl(const struct ctl_table *table, int write,
 
 /* Flags for a single printk record. */
 enum printk_info_flags {
+	/* always show on console, ignore console_loglevel */
+	LOG_LOUD_CON	= 1,
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
 };
@@ -90,6 +92,7 @@ bool printk_percpu_data_ready(void);
 
 void defer_console_output(void);
 bool is_printk_legacy_deferred(void);
+bool is_printk_console_loud(void);
 
 u16 printk_parse_prefix(const char *text, int *level,
 			enum printk_info_flags *flags);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index beb808f4c367..b893825fe21d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1321,6 +1321,7 @@ static void boot_delay_msec(int level)
 	unsigned long timeout;
 
 	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
+		|| is_printk_console_loud()
 		|| suppress_message_printing(level)) {
 		return;
 	}
@@ -2273,6 +2274,9 @@ int vprintk_store(int facility, int level,
 	if (dev_info)
 		flags |= LOG_NEWLINE;
 
+	if (is_printk_console_loud())
+		flags |= LOG_LOUD_CON;
+
 	if (flags & LOG_CONT) {
 		prb_rec_init_wr(&r, reserve_size);
 		if (prb_reserve_in_last(&e, prb, &r, caller_id, PRINTKRB_RECORD_MAX)) {
@@ -2947,6 +2951,7 @@ bool printk_get_next_message(struct printk_message *pmsg, u64 seq,
 	struct printk_info info;
 	struct printk_record r;
 	size_t len = 0;
+	bool loud_con;
 
 	/*
 	 * Formatting extended messages requires a separate buffer, so use the
@@ -2965,9 +2970,10 @@ bool printk_get_next_message(struct printk_message *pmsg, u64 seq,
 
 	pmsg->seq = r.info->seq;
 	pmsg->dropped = r.info->seq - seq;
+	loud_con = r.info->flags & LOG_LOUD_CON;
 
 	/* Skip record that has level above the console loglevel. */
-	if (may_suppress && suppress_message_printing(r.info->level))
+	if (!loud_con && may_suppress && suppress_message_printing(r.info->level))
 		goto out;
 
 	if (is_extended) {
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 2b35a9d3919d..4618988baeea 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -12,7 +12,30 @@
 
 #include "internal.h"
 
-static DEFINE_PER_CPU(int, printk_context);
+static DEFINE_PER_CPU(unsigned int, printk_context);
+
+#define PRINTK_SAFE_CONTEXT_MASK		0x0000ffffU
+#define PRINTK_LOUD_CONSOLE_CONTEXT_MASK	0xffff0000U
+#define PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET	0x00010000U
+
+void noinstr printk_loud_console_enter(void)
+{
+	cant_migrate();
+	this_cpu_add(printk_context, PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET);
+}
+
+void noinstr printk_loud_console_exit(void)
+{
+	cant_migrate();
+	this_cpu_sub(printk_context, PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET);
+}
+
+/* Safe in any context. CPU migration is always disabled when set. */
+bool is_printk_console_loud(void)
+{
+	return !!(this_cpu_read(printk_context) &
+			PRINTK_LOUD_CONSOLE_CONTEXT_MASK);
+}
 
 /* Can be preempted by NMI. */
 void __printk_safe_enter(void)
@@ -45,7 +68,7 @@ bool is_printk_legacy_deferred(void)
 	 * context. CPU migration is always disabled when set.
 	 */
 	return (force_legacy_kthread() ||
-		this_cpu_read(printk_context) ||
+		!!(this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) ||
 		in_nmi());
 }
 

-- 
2.46.1


^ permalink raw reply related	[flat|nested] 14+ messages in thread

* [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq
  2024-10-16 17:03 [PATCH 0/2] printk: Add loud_console printk flag to not suppress sysrq header msgs Marcos Paulo de Souza
  2024-10-16 17:03 ` [PATCH 1/2] printk: Introduce LOUD_CON flag Marcos Paulo de Souza
@ 2024-10-16 17:03 ` Marcos Paulo de Souza
  2024-10-18  3:43   ` kernel test robot
  2024-10-18  4:36   ` kernel test robot
  1 sibling, 2 replies; 14+ messages in thread
From: Marcos Paulo de Souza @ 2024-10-16 17:03 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, John Ogness, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby
  Cc: linux-kernel, linux-serial, Marcos Paulo de Souza

By using the printk_loud_console the loglevel workaround can be removed.
The workaround existed to always send the sysrq header message to all
consoles not matter what was the current loglevel.

Signed-off-by: Marcos Paulo de Souza <mpdesouza@suse.com>
---
 drivers/tty/sysrq.c | 18 ++++++++----------
 1 file changed, 8 insertions(+), 10 deletions(-)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 930b04e3d148..1ff11cf6275a 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -583,7 +583,6 @@ static void __sysrq_put_key_op(u8 key, const struct sysrq_key_op *op_p)
 void __handle_sysrq(u8 key, bool check_mask)
 {
 	const struct sysrq_key_op *op_p;
-	int orig_log_level;
 	int orig_suppress_printk;
 	int i;
 
@@ -593,13 +592,12 @@ void __handle_sysrq(u8 key, bool check_mask)
 	rcu_sysrq_start();
 	rcu_read_lock();
 	/*
-	 * Raise the apparent loglevel to maximum so that the sysrq header
-	 * is shown to provide the user with positive feedback.  We do not
-	 * simply emit this at KERN_EMERG as that would change message
-	 * routing in the consumers of /proc/kmsg.
+	 * Enter in the console_loud context so that sysrq header is shown to
+	 * provide the user with positive feedback.  We do not simply emit this
+	 * at KERN_EMERG as that would change message routing in the consumers
+	 * of /proc/kmsg.
 	 */
-	orig_log_level = console_loglevel;
-	console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
+	printk_loud_console_enter();
 
 	op_p = __sysrq_get_key_op(key);
 	if (op_p) {
@@ -609,11 +607,11 @@ void __handle_sysrq(u8 key, bool check_mask)
 		 */
 		if (!check_mask || sysrq_on_mask(op_p->enable_mask)) {
 			pr_info("%s\n", op_p->action_msg);
-			console_loglevel = orig_log_level;
+			printk_loud_console_exit();
 			op_p->handler(key);
 		} else {
 			pr_info("This sysrq operation is disabled.\n");
-			console_loglevel = orig_log_level;
+			printk_loud_console_exit();
 		}
 	} else {
 		pr_info("HELP : ");
@@ -631,7 +629,7 @@ void __handle_sysrq(u8 key, bool check_mask)
 			}
 		}
 		pr_cont("\n");
-		console_loglevel = orig_log_level;
+		printk_loud_console_exit();
 	}
 	rcu_read_unlock();
 	rcu_sysrq_end();

-- 
2.46.1


^ permalink raw reply related	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-16 17:03 ` [PATCH 1/2] printk: Introduce LOUD_CON flag Marcos Paulo de Souza
@ 2024-10-16 18:11   ` John Ogness
  2024-10-17 10:24     ` Petr Mladek
  2024-10-18 12:11     ` Marcos Paulo de Souza
  2024-10-19  1:28   ` kernel test robot
  1 sibling, 2 replies; 14+ messages in thread
From: John Ogness @ 2024-10-16 18:11 UTC (permalink / raw)
  To: Marcos Paulo de Souza, Petr Mladek, Steven Rostedt,
	Sergey Senozhatsky, Greg Kroah-Hartman, Jiri Slaby
  Cc: linux-kernel, linux-serial, Marcos Paulo de Souza

Hi Marcus,

On 2024-10-16, Marcos Paulo de Souza <mpdesouza@suse.com> wrote:
> Introduce LOUD_CON flag to printk.

Generally speaking, I do not like the name "LOUD_CON". The flag is
related to records, not consoles. Something like "NO_SUPPRESS" or
"FORCE_PRINT" might be more appropriate. Note that naming is not my
strength.

> The new flag will make it possible to
> create a context where printk messages will never be suppressed. This
> new context information will be stored in the already existing
> printk_context per-CPU variable. This variable was changed from 'int' to
> 'unsigned int' to avoid issues with automatic casting.
>
> This mechanism will be used in the next patch to create a loud_console
> context on sysrq handling, removing an existing workaround on the
> loglevel global variable. The workaround existed to make sure that sysrq
> header messages were sent to all consoles.

IMO the more interesting aspect is that the "loud" flag is stored in the
ringbuffer so that the message is not suppressed, even if printed later
(for example because it was deferred). This actually even fixes a bug
since the current workaround will not perform as expected if the sysrq
records are deferred (for example due to threaded printing or consoles
that are registered later).

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index beb808f4c367..b893825fe21d 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1321,6 +1321,7 @@ static void boot_delay_msec(int level)
>  	unsigned long timeout;
>  
>  	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
> +		|| is_printk_console_loud()
>  		|| suppress_message_printing(level)) {

I do not think "loud" should be a reason to skip the delays. The delays
are there to slow down printing. I would think that for "loud" messages,
this is even more important. I suppose this function (as well as
printk_delay()) would need a new boolean parameter whether it is a
"loud" message. Then:

	|| (!loud_con && suppress_message_printing(level))

> @@ -2273,6 +2274,9 @@ int vprintk_store(int facility, int level,
>  	if (dev_info)
>  		flags |= LOG_NEWLINE;
>  
> +	if (is_printk_console_loud())
> +		flags |= LOG_LOUD_CON;
> +
>  	if (flags & LOG_CONT) {
>  		prb_rec_init_wr(&r, reserve_size);
>  		if (prb_reserve_in_last(&e, prb, &r, caller_id, PRINTKRB_RECORD_MAX)) {

I guess LOG_LOUD_CON should also be set in the LOG_CONT case (like
LOG_NEWLINE does).

> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index 2b35a9d3919d..4618988baeea 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -12,7 +12,30 @@
>  
>  #include "internal.h"
>  
> -static DEFINE_PER_CPU(int, printk_context);
> +static DEFINE_PER_CPU(unsigned int, printk_context);
> +
> +#define PRINTK_SAFE_CONTEXT_MASK		0x0000ffffU
> +#define PRINTK_LOUD_CONSOLE_CONTEXT_MASK	0xffff0000U
> +#define PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET	0x00010000U
> +
> +void noinstr printk_loud_console_enter(void)
> +{
> +	cant_migrate();
> +	this_cpu_add(printk_context, PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET);
> +}

Have you tested this with lockdep? AFAICT, the write_sysrq_trigger()
path can migrate since it is only using rcu_read_lock() in
__handle_sysrq().

John Ogness

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-16 18:11   ` John Ogness
@ 2024-10-17 10:24     ` Petr Mladek
  2024-10-18  7:14       ` John Ogness
  2024-10-18 12:11     ` Marcos Paulo de Souza
  1 sibling, 1 reply; 14+ messages in thread
From: Petr Mladek @ 2024-10-17 10:24 UTC (permalink / raw)
  To: John Ogness
  Cc: Marcos Paulo de Souza, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby, linux-kernel, linux-serial

On Wed 2024-10-16 20:17:48, John Ogness wrote:
> Hi Marcus,
> 
> On 2024-10-16, Marcos Paulo de Souza <mpdesouza@suse.com> wrote:
> > Introduce LOUD_CON flag to printk.
> 
> Generally speaking, I do not like the name "LOUD_CON". The flag is
> related to records, not consoles. Something like "NO_SUPPRESS" or
> "FORCE_PRINT" might be more appropriate. Note that naming is not my
> strength.

I see. I would prefer to avoid names with double negatives.
So I prefer the "FORCE_PRINT" variant.

That said, I think that "FORCE_CON" might also be good.
Aka, the message forces consoles to show it.

> > The new flag will make it possible to
> > create a context where printk messages will never be suppressed. This
> > new context information will be stored in the already existing
> > printk_context per-CPU variable. This variable was changed from 'int' to
> > 'unsigned int' to avoid issues with automatic casting.
> >
> > This mechanism will be used in the next patch to create a loud_console
> > context on sysrq handling, removing an existing workaround on the
> > loglevel global variable. The workaround existed to make sure that sysrq
> > header messages were sent to all consoles.
> 
> IMO the more interesting aspect is that the "loud" flag is stored in the
> ringbuffer so that the message is not suppressed, even if printed later
> (for example because it was deferred). This actually even fixes a bug
> since the current workaround will not perform as expected if the sysrq
> records are deferred (for example due to threaded printing or consoles
> that are registered later).

Yeah. I think that the fix of this race is the main motivation for
the change. We should make it more clear in the commit message.

> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index beb808f4c367..b893825fe21d 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1321,6 +1321,7 @@ static void boot_delay_msec(int level)
> >  	unsigned long timeout;
> >  
> >  	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
> > +		|| is_printk_console_loud()
> >  		|| suppress_message_printing(level)) {
> 
> I do not think "loud" should be a reason to skip the delays. The delays
> are there to slow down printing. I would think that for "loud" messages,
> this is even more important. I suppose this function (as well as
> printk_delay()) would need a new boolean parameter whether it is a
> "loud" message. Then:
> 
> 	|| (!loud_con && suppress_message_printing(level))

Yes, this makes more sense.

> > @@ -2273,6 +2274,9 @@ int vprintk_store(int facility, int level,
> >  	if (dev_info)
> >  		flags |= LOG_NEWLINE;
> >  
> > +	if (is_printk_console_loud())
> > +		flags |= LOG_LOUD_CON;
> > +
> >  	if (flags & LOG_CONT) {
> >  		prb_rec_init_wr(&r, reserve_size);
> >  		if (prb_reserve_in_last(&e, prb, &r, caller_id, PRINTKRB_RECORD_MAX)) {
> 
> I guess LOG_LOUD_CON should also be set in the LOG_CONT case (like
> LOG_NEWLINE does).

Great catch! Yes, it would make sense to set it even in the re-opened record.

> > diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> > index 2b35a9d3919d..4618988baeea 100644
> > --- a/kernel/printk/printk_safe.c
> > +++ b/kernel/printk/printk_safe.c
> > @@ -12,7 +12,30 @@
> >  
> >  #include "internal.h"
> >  
> > -static DEFINE_PER_CPU(int, printk_context);
> > +static DEFINE_PER_CPU(unsigned int, printk_context);
> > +
> > +#define PRINTK_SAFE_CONTEXT_MASK		0x0000ffffU
> > +#define PRINTK_LOUD_CONSOLE_CONTEXT_MASK	0xffff0000U
> > +#define PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET	0x00010000U
> > +
> > +void noinstr printk_loud_console_enter(void)
> > +{
> > +	cant_migrate();
> > +	this_cpu_add(printk_context, PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET);
> > +}
> 
> Have you tested this with lockdep? AFAICT, the write_sysrq_trigger()
> path can migrate since it is only using rcu_read_lock() in
> __handle_sysrq().

Interesting. I have always had connected rcu_read_lock() with
preempt_disable(). But I see that there actually exists preemptive
variant with CONFIG_PREEMPT_RCU. And I guess that preemptive RCU
read lock is a must-to-have on RT.

And indeed:

# echo h >/proc/sysrq-trigger

produced:

[   53.669907] BUG: assuming non migratable context at kernel/printk/printk_safe.c:23
[   53.669920] in_atomic(): 0, irqs_disabled(): 0, migration_disabled() 0 pid: 1637, name: bash
[   53.669931] 2 locks held by bash/1637:
[   53.669936]  #0: ffff8ae680a384a8 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x6e/0xf0
[   53.669968]  #1: ffffffff83f226e0 (rcu_read_lock){....}-{1:3}, at: __handle_sysrq+0x3d/0x120
[   53.670002] CPU: 2 UID: 0 PID: 1637 Comm: bash Not tainted 6.12.0-rc3-default+ #67
[   53.670011] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.3-2-gc13ff2cd-prebuilt.qemu.org 04/01/2014
[   53.670020] Call Trace:
[   53.670026]  <TASK>
[   53.670045]  dump_stack_lvl+0x6c/0xa0
[   53.670064]  __cant_migrate.cold+0x7c/0x89
[   53.670080]  printk_loud_console_enter+0x15/0x30
[   53.670088]  __handle_sysrq+0x60/0x120
[   53.670104]  write_sysrq_trigger+0x6a/0xa0
[   53.670120]  proc_reg_write+0x5f/0xb0
[   53.670132]  vfs_write+0xf9/0x540
[   53.670147]  ? __lock_release.isra.0+0x1a6/0x2c0
[   53.670172]  ? do_user_addr_fault+0x38c/0x720
[   53.670197]  ksys_write+0x6e/0xf0
[   53.670220]  do_syscall_64+0x79/0x190
[   53.670238]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
[   53.670252] RIP: 0033:0x7fa4247d9b13
[   53.670269] Code: 0f 1f 80 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 f3 c3 0f 1f 00 41 54 55 49 89 d4 53 48 89
[   53.670275] RSP: 002b:00007ffe62690f38 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[   53.670282] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007fa4247d9b13
[   53.670288] RDX: 0000000000000002 RSI: 00005557ac516ec0 RDI: 0000000000000001
[   53.670291] RBP: 00005557ac516ec0 R08: 000000000000000a R09: 0000000000000000
[   53.670295] R10: 00007fa4246da468 R11: 0000000000000246 R12: 00007fa424abd500
[   53.670298] R13: 0000000000000002 R14: 00007fa424ac2c00 R15: 0000000000000002
[   53.670350]  </TASK>
[   53.670358] sysrq: HELP : loglevel(0-9) reboot(b) crash(c) show-all-locks(d) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) show-blocked-tasks(w) dump-ftrace-buffer(z) replay-kernel-logs(R) 


IMHO, the best solution would be to call migrate_disable()/enable()
in printk_loud_console_enter()/exit().

We should not disable preemption because the output could
be long.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq
  2024-10-16 17:03 ` [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq Marcos Paulo de Souza
@ 2024-10-18  3:43   ` kernel test robot
  2024-10-18  4:36   ` kernel test robot
  1 sibling, 0 replies; 14+ messages in thread
From: kernel test robot @ 2024-10-18  3:43 UTC (permalink / raw)
  To: Marcos Paulo de Souza, Petr Mladek, Steven Rostedt, John Ogness,
	Sergey Senozhatsky, Greg Kroah-Hartman, Jiri Slaby
  Cc: oe-kbuild-all, linux-kernel, linux-serial, Marcos Paulo de Souza

Hi Marcos,

kernel test robot noticed the following build errors:

[auto build test ERROR on 1d227fcc72223cbdd34d0ce13541cbaab5e0d72f]

url:    https://github.com/intel-lab-lkp/linux/commits/Marcos-Paulo-de-Souza/printk-Introduce-LOUD_CON-flag/20241017-010521
base:   1d227fcc72223cbdd34d0ce13541cbaab5e0d72f
patch link:    https://lore.kernel.org/r/20241016-printk-loud-con-v1-2-065e4dad6632%40suse.com
patch subject: [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq
config: x86_64-buildonly-randconfig-004-20241018 (https://download.01.org/0day-ci/archive/20241018/202410181116.WA27FpBB-lkp@intel.com/config)
compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20241018/202410181116.WA27FpBB-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202410181116.WA27FpBB-lkp@intel.com/

All errors (new ones prefixed by >>):

   drivers/tty/sysrq.c: In function '__handle_sysrq':
>> drivers/tty/sysrq.c:600:9: error: implicit declaration of function 'printk_loud_console_enter' [-Werror=implicit-function-declaration]
     600 |         printk_loud_console_enter();
         |         ^~~~~~~~~~~~~~~~~~~~~~~~~
>> drivers/tty/sysrq.c:610:25: error: implicit declaration of function 'printk_loud_console_exit' [-Werror=implicit-function-declaration]
     610 |                         printk_loud_console_exit();
         |                         ^~~~~~~~~~~~~~~~~~~~~~~~
   cc1: some warnings being treated as errors


vim +/printk_loud_console_enter +600 drivers/tty/sysrq.c

   582	
   583	void __handle_sysrq(u8 key, bool check_mask)
   584	{
   585		const struct sysrq_key_op *op_p;
   586		int orig_suppress_printk;
   587		int i;
   588	
   589		orig_suppress_printk = suppress_printk;
   590		suppress_printk = 0;
   591	
   592		rcu_sysrq_start();
   593		rcu_read_lock();
   594		/*
   595		 * Enter in the console_loud context so that sysrq header is shown to
   596		 * provide the user with positive feedback.  We do not simply emit this
   597		 * at KERN_EMERG as that would change message routing in the consumers
   598		 * of /proc/kmsg.
   599		 */
 > 600		printk_loud_console_enter();
   601	
   602		op_p = __sysrq_get_key_op(key);
   603		if (op_p) {
   604			/*
   605			 * Should we check for enabled operations (/proc/sysrq-trigger
   606			 * should not) and is the invoked operation enabled?
   607			 */
   608			if (!check_mask || sysrq_on_mask(op_p->enable_mask)) {
   609				pr_info("%s\n", op_p->action_msg);
 > 610				printk_loud_console_exit();
   611				op_p->handler(key);
   612			} else {
   613				pr_info("This sysrq operation is disabled.\n");
   614				printk_loud_console_exit();
   615			}
   616		} else {
   617			pr_info("HELP : ");
   618			/* Only print the help msg once per handler */
   619			for (i = 0; i < ARRAY_SIZE(sysrq_key_table); i++) {
   620				if (sysrq_key_table[i]) {
   621					int j;
   622	
   623					for (j = 0; sysrq_key_table[i] !=
   624							sysrq_key_table[j]; j++)
   625						;
   626					if (j != i)
   627						continue;
   628					pr_cont("%s ", sysrq_key_table[i]->help_msg);
   629				}
   630			}
   631			pr_cont("\n");
   632			printk_loud_console_exit();
   633		}
   634		rcu_read_unlock();
   635		rcu_sysrq_end();
   636	
   637		suppress_printk = orig_suppress_printk;
   638	}
   639	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq
  2024-10-16 17:03 ` [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq Marcos Paulo de Souza
  2024-10-18  3:43   ` kernel test robot
@ 2024-10-18  4:36   ` kernel test robot
  1 sibling, 0 replies; 14+ messages in thread
From: kernel test robot @ 2024-10-18  4:36 UTC (permalink / raw)
  To: Marcos Paulo de Souza, Petr Mladek, Steven Rostedt, John Ogness,
	Sergey Senozhatsky, Greg Kroah-Hartman, Jiri Slaby
  Cc: llvm, oe-kbuild-all, linux-kernel, linux-serial,
	Marcos Paulo de Souza

Hi Marcos,

kernel test robot noticed the following build errors:

[auto build test ERROR on 1d227fcc72223cbdd34d0ce13541cbaab5e0d72f]

url:    https://github.com/intel-lab-lkp/linux/commits/Marcos-Paulo-de-Souza/printk-Introduce-LOUD_CON-flag/20241017-010521
base:   1d227fcc72223cbdd34d0ce13541cbaab5e0d72f
patch link:    https://lore.kernel.org/r/20241016-printk-loud-con-v1-2-065e4dad6632%40suse.com
patch subject: [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq
config: i386-buildonly-randconfig-001-20241018 (https://download.01.org/0day-ci/archive/20241018/202410181205.VT06PKmP-lkp@intel.com/config)
compiler: clang version 18.1.8 (https://github.com/llvm/llvm-project 3b5b5c1ec4a3095ab096dd780e84d7ab81f3d7ff)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20241018/202410181205.VT06PKmP-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202410181205.VT06PKmP-lkp@intel.com/

All errors (new ones prefixed by >>):

>> drivers/tty/sysrq.c:600:2: error: call to undeclared function 'printk_loud_console_enter'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
     600 |         printk_loud_console_enter();
         |         ^
>> drivers/tty/sysrq.c:610:4: error: call to undeclared function 'printk_loud_console_exit'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
     610 |                         printk_loud_console_exit();
         |                         ^
   drivers/tty/sysrq.c:614:4: error: call to undeclared function 'printk_loud_console_exit'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
     614 |                         printk_loud_console_exit();
         |                         ^
   drivers/tty/sysrq.c:632:3: error: call to undeclared function 'printk_loud_console_exit'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
     632 |                 printk_loud_console_exit();
         |                 ^
   4 errors generated.


vim +/printk_loud_console_enter +600 drivers/tty/sysrq.c

   582	
   583	void __handle_sysrq(u8 key, bool check_mask)
   584	{
   585		const struct sysrq_key_op *op_p;
   586		int orig_suppress_printk;
   587		int i;
   588	
   589		orig_suppress_printk = suppress_printk;
   590		suppress_printk = 0;
   591	
   592		rcu_sysrq_start();
   593		rcu_read_lock();
   594		/*
   595		 * Enter in the console_loud context so that sysrq header is shown to
   596		 * provide the user with positive feedback.  We do not simply emit this
   597		 * at KERN_EMERG as that would change message routing in the consumers
   598		 * of /proc/kmsg.
   599		 */
 > 600		printk_loud_console_enter();
   601	
   602		op_p = __sysrq_get_key_op(key);
   603		if (op_p) {
   604			/*
   605			 * Should we check for enabled operations (/proc/sysrq-trigger
   606			 * should not) and is the invoked operation enabled?
   607			 */
   608			if (!check_mask || sysrq_on_mask(op_p->enable_mask)) {
   609				pr_info("%s\n", op_p->action_msg);
 > 610				printk_loud_console_exit();
   611				op_p->handler(key);
   612			} else {
   613				pr_info("This sysrq operation is disabled.\n");
   614				printk_loud_console_exit();
   615			}
   616		} else {
   617			pr_info("HELP : ");
   618			/* Only print the help msg once per handler */
   619			for (i = 0; i < ARRAY_SIZE(sysrq_key_table); i++) {
   620				if (sysrq_key_table[i]) {
   621					int j;
   622	
   623					for (j = 0; sysrq_key_table[i] !=
   624							sysrq_key_table[j]; j++)
   625						;
   626					if (j != i)
   627						continue;
   628					pr_cont("%s ", sysrq_key_table[i]->help_msg);
   629				}
   630			}
   631			pr_cont("\n");
   632			printk_loud_console_exit();
   633		}
   634		rcu_read_unlock();
   635		rcu_sysrq_end();
   636	
   637		suppress_printk = orig_suppress_printk;
   638	}
   639	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-17 10:24     ` Petr Mladek
@ 2024-10-18  7:14       ` John Ogness
  2024-10-21 13:33         ` Petr Mladek
  0 siblings, 1 reply; 14+ messages in thread
From: John Ogness @ 2024-10-18  7:14 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Marcos Paulo de Souza, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby, linux-kernel, linux-serial

On 2024-10-17, Petr Mladek <pmladek@suse.com> wrote:
> # echo h >/proc/sysrq-trigger
>
> produced:
>
> [   53.669907] BUG: assuming non migratable context at kernel/printk/printk_safe.c:23
> [   53.669920] in_atomic(): 0, irqs_disabled(): 0, migration_disabled() 0 pid: 1637, name: bash
> [   53.669931] 2 locks held by bash/1637:
> [   53.669936]  #0: ffff8ae680a384a8 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x6e/0xf0
> [   53.669968]  #1: ffffffff83f226e0 (rcu_read_lock){....}-{1:3}, at: __handle_sysrq+0x3d/0x120
> [   53.670002] CPU: 2 UID: 0 PID: 1637 Comm: bash Not tainted 6.12.0-rc3-default+ #67
> [   53.670011] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.3-2-gc13ff2cd-prebuilt.qemu.org 04/01/2014
> [   53.670020] Call Trace:
> [   53.670026]  <TASK>
> [   53.670045]  dump_stack_lvl+0x6c/0xa0
> [   53.670064]  __cant_migrate.cold+0x7c/0x89
> [   53.670080]  printk_loud_console_enter+0x15/0x30
> [   53.670088]  __handle_sysrq+0x60/0x120
> [   53.670104]  write_sysrq_trigger+0x6a/0xa0
> [   53.670120]  proc_reg_write+0x5f/0xb0
> [   53.670132]  vfs_write+0xf9/0x540
> [   53.670147]  ? __lock_release.isra.0+0x1a6/0x2c0
> [   53.670172]  ? do_user_addr_fault+0x38c/0x720
> [   53.670197]  ksys_write+0x6e/0xf0
> [   53.670220]  do_syscall_64+0x79/0x190
> [   53.670238]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
>
> IMHO, the best solution would be to call migrate_disable()/enable()
> in printk_loud_console_enter()/exit().

That will not work because migrate_enable() can only be called from
can_sleep context. Instead, the migrate_disable()/enable() should be at
the few (one?) call sites where printk_loud_console_enter()/exit() is
used from task context.

This is also how printk_deferred_enter()/exit() works, relying on the
caller to disable migration if necessary.

John

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-16 18:11   ` John Ogness
  2024-10-17 10:24     ` Petr Mladek
@ 2024-10-18 12:11     ` Marcos Paulo de Souza
  1 sibling, 0 replies; 14+ messages in thread
From: Marcos Paulo de Souza @ 2024-10-18 12:11 UTC (permalink / raw)
  To: John Ogness, Petr Mladek, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby
  Cc: linux-kernel, linux-serial

On Wed, 2024-10-16 at 20:17 +0206, John Ogness wrote:
> Hi Marcus,
> 
> On 2024-10-16, Marcos Paulo de Souza <mpdesouza@suse.com> wrote:
> > Introduce LOUD_CON flag to printk.
> 
> Generally speaking, I do not like the name "LOUD_CON". The flag is
> related to records, not consoles. Something like "NO_SUPPRESS" or
> "FORCE_PRINT" might be more appropriate. Note that naming is not my
> strength.

Makes sense. I'll talk with Petr to check which better name we case,
but personally speaking I liked FORCE_CON that he suggested.

> 
> > The new flag will make it possible to
> > create a context where printk messages will never be suppressed.
> > This
> > new context information will be stored in the already existing
> > printk_context per-CPU variable. This variable was changed from
> > 'int' to
> > 'unsigned int' to avoid issues with automatic casting.
> > 
> > This mechanism will be used in the next patch to create a
> > loud_console
> > context on sysrq handling, removing an existing workaround on the
> > loglevel global variable. The workaround existed to make sure that
> > sysrq
> > header messages were sent to all consoles.
> 
> IMO the more interesting aspect is that the "loud" flag is stored in
> the
> ringbuffer so that the message is not suppressed, even if printed
> later
> (for example because it was deferred). This actually even fixes a bug
> since the current workaround will not perform as expected if the
> sysrq
> records are deferred (for example due to threaded printing or
> consoles
> that are registered later).

Indeed, I'll describe that this new behavior fixes a problem.

> 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index beb808f4c367..b893825fe21d 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1321,6 +1321,7 @@ static void boot_delay_msec(int level)
> >  	unsigned long timeout;
> >  
> >  	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
> > +		|| is_printk_console_loud()
> >  		|| suppress_message_printing(level)) {
> 
> I do not think "loud" should be a reason to skip the delays. The
> delays
> are there to slow down printing. I would think that for "loud"
> messages,
> this is even more important. I suppose this function (as well as
> printk_delay()) would need a new boolean parameter whether it is a
> "loud" message. Then:
> 
> 	|| (!loud_con && suppress_message_printing(level))

Done locally, thanks!

> 
> > @@ -2273,6 +2274,9 @@ int vprintk_store(int facility, int level,
> >  	if (dev_info)
> >  		flags |= LOG_NEWLINE;
> >  
> > +	if (is_printk_console_loud())
> > +		flags |= LOG_LOUD_CON;
> > +
> >  	if (flags & LOG_CONT) {
> >  		prb_rec_init_wr(&r, reserve_size);
> >  		if (prb_reserve_in_last(&e, prb, &r, caller_id,
> > PRINTKRB_RECORD_MAX)) {
> 
> I guess LOG_LOUD_CON should also be set in the LOG_CONT case (like
> LOG_NEWLINE does).
> 
> > diff --git a/kernel/printk/printk_safe.c
> > b/kernel/printk/printk_safe.c
> > index 2b35a9d3919d..4618988baeea 100644
> > --- a/kernel/printk/printk_safe.c
> > +++ b/kernel/printk/printk_safe.c
> > @@ -12,7 +12,30 @@
> >  
> >  #include "internal.h"
> >  
> > -static DEFINE_PER_CPU(int, printk_context);
> > +static DEFINE_PER_CPU(unsigned int, printk_context);
> > +
> > +#define PRINTK_SAFE_CONTEXT_MASK		0x0000ffffU
> > +#define PRINTK_LOUD_CONSOLE_CONTEXT_MASK	0xffff0000U
> > +#define PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET	0x00010000U
> > +
> > +void noinstr printk_loud_console_enter(void)
> > +{
> > +	cant_migrate();
> > +	this_cpu_add(printk_context,
> > PRINTK_LOUD_CONSOLE_CONTEXT_OFFSET);
> > +}
> 
> Have you tested this with lockdep? AFAICT, the write_sysrq_trigger()
> path can migrate since it is only using rcu_read_lock() in
> __handle_sysrq().

Now I have and I found the error. Let me investigate how I can proceed
here.

Thanks a lot for the review!

> 
> John Ogness


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-16 17:03 ` [PATCH 1/2] printk: Introduce LOUD_CON flag Marcos Paulo de Souza
  2024-10-16 18:11   ` John Ogness
@ 2024-10-19  1:28   ` kernel test robot
  1 sibling, 0 replies; 14+ messages in thread
From: kernel test robot @ 2024-10-19  1:28 UTC (permalink / raw)
  To: Marcos Paulo de Souza, Petr Mladek, Steven Rostedt, John Ogness,
	Sergey Senozhatsky, Greg Kroah-Hartman, Jiri Slaby
  Cc: oe-kbuild-all, linux-kernel, linux-serial, Marcos Paulo de Souza

Hi Marcos,

kernel test robot noticed the following build warnings:

[auto build test WARNING on 1d227fcc72223cbdd34d0ce13541cbaab5e0d72f]

url:    https://github.com/intel-lab-lkp/linux/commits/Marcos-Paulo-de-Souza/printk-Introduce-LOUD_CON-flag/20241017-010521
base:   1d227fcc72223cbdd34d0ce13541cbaab5e0d72f
patch link:    https://lore.kernel.org/r/20241016-printk-loud-con-v1-1-065e4dad6632%40suse.com
patch subject: [PATCH 1/2] printk: Introduce LOUD_CON flag
config: x86_64-randconfig-001-20241018 (https://download.01.org/0day-ci/archive/20241019/202410190915.WgFGTQdE-lkp@intel.com/config)
compiler: gcc-11 (Debian 11.3.0-12) 11.3.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20241019/202410190915.WgFGTQdE-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202410190915.WgFGTQdE-lkp@intel.com/

All warnings (new ones prefixed by >>):

>> vmlinux.o: warning: objtool: printk_loud_console_enter+0x11: call to __cant_migrate() leaves .noinstr.text section
>> vmlinux.o: warning: objtool: printk_loud_console_exit+0x11: call to __cant_migrate() leaves .noinstr.text section

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-18  7:14       ` John Ogness
@ 2024-10-21 13:33         ` Petr Mladek
  2024-10-21 14:11           ` John Ogness
  0 siblings, 1 reply; 14+ messages in thread
From: Petr Mladek @ 2024-10-21 13:33 UTC (permalink / raw)
  To: John Ogness
  Cc: Marcos Paulo de Souza, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby, linux-kernel, linux-serial

On Fri 2024-10-18 09:20:19, John Ogness wrote:
> On 2024-10-17, Petr Mladek <pmladek@suse.com> wrote:
> > # echo h >/proc/sysrq-trigger
> >
> > produced:
> >
> > [   53.669907] BUG: assuming non migratable context at kernel/printk/printk_safe.c:23
> > [   53.669920] in_atomic(): 0, irqs_disabled(): 0, migration_disabled() 0 pid: 1637, name: bash
> > [   53.669931] 2 locks held by bash/1637:
> > [   53.669936]  #0: ffff8ae680a384a8 (sb_writers#4){.+.+}-{0:0}, at: ksys_write+0x6e/0xf0
> > [   53.669968]  #1: ffffffff83f226e0 (rcu_read_lock){....}-{1:3}, at: __handle_sysrq+0x3d/0x120
> > [   53.670002] CPU: 2 UID: 0 PID: 1637 Comm: bash Not tainted 6.12.0-rc3-default+ #67
> > [   53.670011] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.3-2-gc13ff2cd-prebuilt.qemu.org 04/01/2014
> > [   53.670020] Call Trace:
> > [   53.670026]  <TASK>
> > [   53.670045]  dump_stack_lvl+0x6c/0xa0
> > [   53.670064]  __cant_migrate.cold+0x7c/0x89
> > [   53.670080]  printk_loud_console_enter+0x15/0x30
> > [   53.670088]  __handle_sysrq+0x60/0x120
> > [   53.670104]  write_sysrq_trigger+0x6a/0xa0
> > [   53.670120]  proc_reg_write+0x5f/0xb0
> > [   53.670132]  vfs_write+0xf9/0x540
> > [   53.670147]  ? __lock_release.isra.0+0x1a6/0x2c0
> > [   53.670172]  ? do_user_addr_fault+0x38c/0x720
> > [   53.670197]  ksys_write+0x6e/0xf0
> > [   53.670220]  do_syscall_64+0x79/0x190
> > [   53.670238]  entry_SYSCALL_64_after_hwframe+0x76/0x7e
> >
> > IMHO, the best solution would be to call migrate_disable()/enable()
> > in printk_loud_console_enter()/exit().
> 
> That will not work because migrate_enable() can only be called from
> can_sleep context. Instead, the migrate_disable()/enable() should be at
> the few (one?) call sites where printk_loud_console_enter()/exit() is
> used from task context.

Hmm, if I get it correctly, we could not use migrate_disable() in
__handle_sysrq() because it can be called also in atomic context,
for example:

  + pl010_int()
    + pl010_rx_chars()
      + uart_handle_sysrq_char()
	+ handle_sysrq()
	  + __handle_sysrq()

I do not see any easy way how to distinguish whether it was called in
an atomic context or not.

So, I see three possibilities:

  1. Explicitly call preempt_disable() in __handle_sysrq().

     It would be just around the the single line or the help. But still,
     I do not like it much.


  2. Avoid the per-CPU variable. Force adding the LOUD_CON/FORCE_CON
     flag using a global variable, e.g. printk_force_console.

     The problem is that it might affect also messages printed by
     other CPUs. And there might be many.

     Well, console_loglevel is a global variable. The original code
     had a similar problem.


  3. Add the LOUD_CON/FLUSH_CON flag via a parameter. For example,
     by a special LOGLEVEL_FORCE_CON, similar to LOGLEVEL_SCHED.

     I might work well for __handle_sysrq() which calls the affected
     printk() directly.

     But it won't work, for example, for kdb_show_stack(). It wants
     to show messages printed by a nested functions.


I personally prefer the 2nd variant. It fixes the problem and it
should not make things worse.

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-21 13:33         ` Petr Mladek
@ 2024-10-21 14:11           ` John Ogness
  2024-10-23 20:36             ` Marcos Paulo de Souza
  0 siblings, 1 reply; 14+ messages in thread
From: John Ogness @ 2024-10-21 14:11 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Marcos Paulo de Souza, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby, linux-kernel, linux-serial

On 2024-10-21, Petr Mladek <pmladek@suse.com> wrote:
>> That will not work because migrate_enable() can only be called from
>> can_sleep context. Instead, the migrate_disable()/enable() should be at
>> the few (one?) call sites where printk_loud_console_enter()/exit() is
>> used from task context.
>
> Hmm, if I get it correctly, we could not use migrate_disable() in
> __handle_sysrq() because it can be called also in atomic context,

I am talking about callers of __handle_sysrq() and/or their callers.

For example write_sysrq_trigger() could do:

	migrate_disable();
	__handle_sysrq(c, false);
	migrate_enable();

Or a new wrapper could be introduced for this purpose:

static inline void wrapper handle_sysrq_task(u8 key, bool check_mask)
{
	migrate_disable();
	__handle_sysrq(key, check_mask);
	migrate_enable();
}

A quick grep shows about 25 call sites to check.

> I do not see any easy way how to distinguish whether it was called in
> an atomic context or not.

There is no clean way to do that. If this information is needed, it must
be tracked by the call chain.

> So, I see three possibilities:
>
>   1. Explicitly call preempt_disable() in __handle_sysrq().
>
>      It would be just around the the single line or the help. But still,
>      I do not like it much.

Not acceptable for PREEMPT_RT since sysrq is exposed to external inputs.

>   2. Avoid the per-CPU variable. Force adding the LOUD_CON/FORCE_CON
>      flag using a global variable, e.g. printk_force_console.
>
>      The problem is that it might affect also messages printed by
>      other CPUs. And there might be many.
>
>      Well, console_loglevel is a global variable. The original code
>      had a similar problem.

If disabling migration is not an option for you, this would be my second
choice. I assume tagging too many messages is better than not tagging
enough. And, as you say, this is effectively what the current code is
trying to do.

>   3. Add the LOUD_CON/FLUSH_CON flag via a parameter. For example,
>      by a special LOGLEVEL_FORCE_CON, similar to LOGLEVEL_SCHED.
>
>      I might work well for __handle_sysrq() which calls the affected
>      printk() directly.
>
>      But it won't work, for example, for kdb_show_stack(). It wants
>      to show messages printed by a nested functions.

Right, this has limited usefulness and might miss the important things,
which tend to be within helper functions.

John

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-21 14:11           ` John Ogness
@ 2024-10-23 20:36             ` Marcos Paulo de Souza
  2024-10-24  8:34               ` Petr Mladek
  0 siblings, 1 reply; 14+ messages in thread
From: Marcos Paulo de Souza @ 2024-10-23 20:36 UTC (permalink / raw)
  To: John Ogness, Petr Mladek
  Cc: Steven Rostedt, Sergey Senozhatsky, Greg Kroah-Hartman,
	Jiri Slaby, linux-kernel, linux-serial

On Mon, 2024-10-21 at 16:17 +0206, John Ogness wrote:
> On 2024-10-21, Petr Mladek <pmladek@suse.com> wrote:
> > > That will not work because migrate_enable() can only be called
> > > from
> > > can_sleep context. Instead, the migrate_disable()/enable() should
> > > be at
> > > the few (one?) call sites where
> > > printk_loud_console_enter()/exit() is
> > > used from task context.
> > 
> > Hmm, if I get it correctly, we could not use migrate_disable() in
> > __handle_sysrq() because it can be called also in atomic context,
> 
> I am talking about callers of __handle_sysrq() and/or their callers.
> 
> For example write_sysrq_trigger() could do:
> 
> 	migrate_disable();
> 	__handle_sysrq(c, false);
> 	migrate_enable();
> 
> Or a new wrapper could be introduced for this purpose:
> 
> static inline void wrapper handle_sysrq_task(u8 key, bool check_mask)
> {
> 	migrate_disable();
> 	__handle_sysrq(key, check_mask);
> 	migrate_enable();
> }
> 
> A quick grep shows about 25 call sites to check.
> 
> > I do not see any easy way how to distinguish whether it was called
> > in
> > an atomic context or not.
> 
> There is no clean way to do that. If this information is needed, it
> must
> be tracked by the call chain.
> 
> > So, I see three possibilities:
> > 
> >   1. Explicitly call preempt_disable() in __handle_sysrq().
> > 
> >      It would be just around the the single line or the help. But
> > still,
> >      I do not like it much.
> 
> Not acceptable for PREEMPT_RT since sysrq is exposed to external
> inputs.
> 
> >   2. Avoid the per-CPU variable. Force adding the
> > LOUD_CON/FORCE_CON
> >      flag using a global variable, e.g. printk_force_console.
> > 
> >      The problem is that it might affect also messages printed by
> >      other CPUs. And there might be many.
> > 
> >      Well, console_loglevel is a global variable. The original code
> >      had a similar problem.
> 
> If disabling migration is not an option for you, this would be my
> second
> choice. I assume tagging too many messages is better than not tagging
> enough. And, as you say, this is effectively what the current code is
> trying to do.

Thanks for your input John. I talked with Petr and he suggested to
follow this option. I'll prepare the changes and send them after
reviewing them with Petr.

Thanks,
  Marcos

> 
> >   3. Add the LOUD_CON/FLUSH_CON flag via a parameter. For example,
> >      by a special LOGLEVEL_FORCE_CON, similar to LOGLEVEL_SCHED.
> > 
> >      I might work well for __handle_sysrq() which calls the
> > affected
> >      printk() directly.
> > 
> >      But it won't work, for example, for kdb_show_stack(). It wants
> >      to show messages printed by a nested functions.
> 
> Right, this has limited usefulness and might miss the important
> things,
> which tend to be within helper functions.
> 
> John


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [PATCH 1/2] printk: Introduce LOUD_CON flag
  2024-10-23 20:36             ` Marcos Paulo de Souza
@ 2024-10-24  8:34               ` Petr Mladek
  0 siblings, 0 replies; 14+ messages in thread
From: Petr Mladek @ 2024-10-24  8:34 UTC (permalink / raw)
  To: Marcos Paulo de Souza
  Cc: John Ogness, Steven Rostedt, Sergey Senozhatsky,
	Greg Kroah-Hartman, Jiri Slaby, linux-kernel, linux-serial

On Wed 2024-10-23 17:36:04, Marcos Paulo de Souza wrote:
> On Mon, 2024-10-21 at 16:17 +0206, John Ogness wrote:
> > On 2024-10-21, Petr Mladek <pmladek@suse.com> wrote:
> > > > That will not work because migrate_enable() can only be called
> > > > from
> > > > can_sleep context. Instead, the migrate_disable()/enable() should
> > > > be at
> > > > the few (one?) call sites where
> > > > printk_loud_console_enter()/exit() is
> > > > used from task context.
> > > 
> > > Hmm, if I get it correctly, we could not use migrate_disable() in
> > > __handle_sysrq() because it can be called also in atomic context,
> > 
> > I am talking about callers of __handle_sysrq() and/or their callers.
> > 
> > For example write_sysrq_trigger() could do:
> > 
> > 	migrate_disable();
> > 	__handle_sysrq(c, false);
> > 	migrate_enable();
> > 
> > Or a new wrapper could be introduced for this purpose:
> > 
> > static inline void wrapper handle_sysrq_task(u8 key, bool check_mask)
> > {
> > 	migrate_disable();
> > 	__handle_sysrq(key, check_mask);
> > 	migrate_enable();
> > }
> > 
> > A quick grep shows about 25 call sites to check.
> >
> > > I do not see any easy way how to distinguish whether it was called
> > > in
> > > an atomic context or not.
> > 
> > There is no clean way to do that. If this information is needed, it
> > must
> > be tracked by the call chain.
> > 
> > > So, I see three possibilities:
> > > 
> > >   1. Explicitly call preempt_disable() in __handle_sysrq().
> > > 
> > >      It would be just around the the single line or the help. But
> > > still,
> > >      I do not like it much.
> > 
> > Not acceptable for PREEMPT_RT since sysrq is exposed to external
> > inputs.
> > 
> > >   2. Avoid the per-CPU variable. Force adding the
> > > LOUD_CON/FORCE_CON
> > >      flag using a global variable, e.g. printk_force_console.
> > > 
> > >      The problem is that it might affect also messages printed by
> > >      other CPUs. And there might be many.
> > > 
> > >      Well, console_loglevel is a global variable. The original code
> > >      had a similar problem.
> > 
> > If disabling migration is not an option for you, this would be my
> > second
> > choice. I assume tagging too many messages is better than not tagging
> > enough. And, as you say, this is effectively what the current code is
> > trying to do.
> 
> Thanks for your input John. I talked with Petr and he suggested to
> follow this option. I'll prepare the changes and send them after
> reviewing them with Petr.

Just for record. I propose this way because disabling migration would
require checking all callers (25 as mentioned above).
migrate_disable() is needed and can be called only in the task
context.

I do not think that it is worth the effort. And it would be error
prone (hard to maintain).

Best Regards,
Petr

^ permalink raw reply	[flat|nested] 14+ messages in thread

end of thread, other threads:[~2024-10-24  8:34 UTC | newest]

Thread overview: 14+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-10-16 17:03 [PATCH 0/2] printk: Add loud_console printk flag to not suppress sysrq header msgs Marcos Paulo de Souza
2024-10-16 17:03 ` [PATCH 1/2] printk: Introduce LOUD_CON flag Marcos Paulo de Souza
2024-10-16 18:11   ` John Ogness
2024-10-17 10:24     ` Petr Mladek
2024-10-18  7:14       ` John Ogness
2024-10-21 13:33         ` Petr Mladek
2024-10-21 14:11           ` John Ogness
2024-10-23 20:36             ` Marcos Paulo de Souza
2024-10-24  8:34               ` Petr Mladek
2024-10-18 12:11     ` Marcos Paulo de Souza
2024-10-19  1:28   ` kernel test robot
2024-10-16 17:03 ` [PATCH 2/2] tty: sysrq: Use printk_loud_console context on __handle_sysrq Marcos Paulo de Souza
2024-10-18  3:43   ` kernel test robot
2024-10-18  4:36   ` kernel test robot

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).