[PATCH v4 0/2] Add support to dump printk buffer to console via sysrq

[PATCH v4 0/2] Add support to dump printk buffer to console via sysrq

[Sreenath Vijayan]

Hi,

This patch series enables one to dump the messages in printk ring
buffer unless all CPUs are locked up. This is useful to view the
kernel messages when terminal is unresponsive to enter commands
like dmesg and syslog services are also disabled, especially on
embedded targets. Although debug features like kdb/kgdb already
allow this, these debug configs should be enabled which is often
not the case.

Till the last version, kmsg_dump* interface was being used to
retrieve the messages in printk buffer before dumping them to
consoles. However, John Ogness pointed out the issue with
kmsg_dump* interface that it doesn't work well with extended
consoles. He suggested a new method to reuse the code in
console_flush_on_panic() but without disabling scheduling.

In the first commit, code under CONSOLE_REPLAY_ALL mode in
console_flush_on_panic() is taken out to a helper function
console_rewind_all() to set the console sequence numbder to
oldest record in the printk buffer. And the new function to
dump the buffer called dump_printk_buffer() calls this function
after taking the console lock and then releases the lock which
flushes out the contents of printk buffer to console.

In the second commit, code is added to call dump_printk_buffer()
function when sysrq+D is pressed. As the function may sleep,
it cannot be called from interrupt context. A work is queued
in the system unbound workqueue to call the function when
the key is pressed.

Links to previous discussion:
- https://lore.kernel.org/all/cover.1705331453.git.sreenath.vijayan@sony.com/T/#t
- https://lore.kernel.org/linux-serial/20231221133953.1507021-1-sreenath.vijayan@sony.com/

Changelog:
V3 -> V4:
- refactored code in console_flush_on_panic() under CONSOLE_REPLAY_ALL mode
- added helper function console_rewind_all()
- used console_rewind_all() instead of ksmg_dump*() in dump_printk_buffer()

V2 -> V3:
- split the implementation into two commits
- added function in printk.c to dump printk buffer to consoles
- added Suggested-by tag
- removed code to dump printk buffer from sysrq.c and called
new function

V1 -> V2:
- modified kernel ring buffer to printk ring buffer
- allocated buf dynamically to prevent stack frame size warnings
- used buf of size 2048 to match PRINTK_MESSAGE_MAX and added comment

-- Sreenath

Sreenath Vijayan (2):
  printk: Add function to dump printk buffer directly to consoles
  tty/sysrq: Dump printk ring buffer messages via sysrq

 Documentation/admin-guide/sysrq.rst |  2 +
 drivers/tty/sysrq.c                 | 20 +++++++++-
 include/linux/printk.h              |  4 ++
 kernel/printk/printk.c              | 61 +++++++++++++++++------------
 4 files changed, 62 insertions(+), 25 deletions(-)

-- 
2.43.0

[PATCH v4 1/2] printk: Add function to dump printk buffer directly to consoles

[Sreenath Vijayan]

It is useful to be able to dump the printk buffer directly to
consoles in some situations so as to not flood the buffer.
To do this, we reuse the CONSOLE_REPLAY_ALL mode code in
console_flush_on_panic() by moving the code to a helper function
console_rewind_all(). This is done because console_flush_on_panic()
sets console_may_schedule to 0 but this should not be done in our
case. Then console_rewind_all() is called from the new function
dump_printk_buffer() with console lock held to set the console
sequence number to oldest record in the buffer for all consoles.
Releasing the console lock will flush the contents of printk buffer
to the consoles.

Suggested-by: John Ogness <john.ogness@linutronix.de>
Signed-off-by: Sreenath Vijayan <sreenath.vijayan@sony.com>
Signed-off-by: Shimoyashiki Taichi <taichi.shimoyashiki@sony.com>
---
 include/linux/printk.h |  4 +++
 kernel/printk/printk.c | 61 +++++++++++++++++++++++++-----------------
 2 files changed, 41 insertions(+), 24 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 8ef499ab3c1e..861ff5a545ff 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -192,6 +192,7 @@ 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(void) __cold;
 void printk_trigger_flush(void);
+void dump_printk_buffer(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -271,6 +272,9 @@ static inline void dump_stack(void)
 static inline void printk_trigger_flush(void)
 {
 }
+static void dump_printk_buffer(void)
+{
+}
 #endif
 
 #ifdef CONFIG_SMP
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f2444b581e16..b05ca9f98e53 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3134,6 +3134,32 @@ void console_unblank(void)
 		pr_flush(1000, true);
 }
 
+static void console_rewind_all(void)
+{
+	struct console *c;
+	short flags;
+	int cookie;
+	u64 seq;
+
+	seq = prb_first_valid_seq(prb);
+
+	cookie = console_srcu_read_lock();
+	for_each_console_srcu(c) {
+		flags = console_srcu_read_flags(c);
+
+		if (flags & CON_NBCON) {
+			nbcon_seq_force(c, seq);
+		} else {
+			/*
+			 * This is an unsynchronized assignment. On
+			 * panic legacy consoles are only best effort.
+			 */
+			c->seq = seq;
+		}
+	}
+	console_srcu_read_unlock(cookie);
+}
+
 /**
  * console_flush_on_panic - flush console content on panic
  * @mode: flush all messages in buffer or just the pending ones
@@ -3162,30 +3188,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
 	 */
 	console_may_schedule = 0;
 
-	if (mode == CONSOLE_REPLAY_ALL) {
-		struct console *c;
-		short flags;
-		int cookie;
-		u64 seq;
-
-		seq = prb_first_valid_seq(prb);
-
-		cookie = console_srcu_read_lock();
-		for_each_console_srcu(c) {
-			flags = console_srcu_read_flags(c);
-
-			if (flags & CON_NBCON) {
-				nbcon_seq_force(c, seq);
-			} else {
-				/*
-				 * This is an unsynchronized assignment. On
-				 * panic legacy consoles are only best effort.
-				 */
-				c->seq = seq;
-			}
-		}
-		console_srcu_read_unlock(cookie);
-	}
+	if (mode == CONSOLE_REPLAY_ALL)
+		console_rewind_all();
 
 	console_flush_all(false, &next_seq, &handover);
 }
@@ -4259,6 +4263,15 @@ void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
+/**
+ * Dump the printk ring buffer directly to consoles
+ */
+void dump_printk_buffer(void)
+{
+	console_lock();
+	console_rewind_all();
+	console_unlock();
+}
 #endif
 
 #ifdef CONFIG_SMP
-- 
2.43.0

Re: [PATCH v4 1/2] printk: Add function to dump printk buffer directly to consoles

[John Ogness]

On 2024-02-01, Sreenath Vijayan <sreenath.vijayan@sony.com> wrote:
> It is useful to be able to dump the printk buffer directly to
> consoles in some situations so as to not flood the buffer.
> To do this, we reuse the CONSOLE_REPLAY_ALL mode code in
> console_flush_on_panic() by moving the code to a helper function
> console_rewind_all(). This is done because console_flush_on_panic()
> sets console_may_schedule to 0 but this should not be done in our
> case. Then console_rewind_all() is called from the new function
> dump_printk_buffer() with console lock held to set the console
> sequence number to oldest record in the buffer for all consoles.
> Releasing the console lock will flush the contents of printk buffer
> to the consoles.
>
> Suggested-by: John Ogness <john.ogness@linutronix.de>
> Signed-off-by: Sreenath Vijayan <sreenath.vijayan@sony.com>
> Signed-off-by: Shimoyashiki Taichi <taichi.shimoyashiki@sony.com>

Reviewed-by: John Ogness <john.ogness@linutronix.de>

Re: [PATCH v4 1/2] printk: Add function to dump printk buffer directly to consoles

[Petr Mladek]

On Thu 2024-02-01 15:53:40, Sreenath Vijayan wrote:
> It is useful to be able to dump the printk buffer directly to
> consoles in some situations so as to not flood the buffer.

This is not longer true. I think that it was valid for
the previous versions which used separate buffers with
the kmsg_dump API.

> To do this, we reuse the CONSOLE_REPLAY_ALL mode code in
> console_flush_on_panic() by moving the code to a helper function
> console_rewind_all(). This is done because console_flush_on_panic()
> sets console_may_schedule to 0 but this should not be done in our
> case.

Also the "c->seq = seq;" is not safe in the panic version.
But it will be safe when called under the console_lock.

> Then console_rewind_all() is called from the new function
> dump_printk_buffer() with console lock held to set the console
> sequence number to oldest record in the buffer for all consoles.
> Releasing the console lock will flush the contents of printk buffer
> to the consoles.

My proposed commit message is:

<proposal>
Add a generic function for replaying the kernel log on consoles.
It would allow seeing the the log on an unresponsive terminal
via sysrq interface.

Reuse the existing code from console_flush_on_panic() for
reseting the sequence numbers. It will be safe when called
under console_lock(). Also the console_unlock() will
automatically flush the messages on the consoles.

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3134,6 +3134,32 @@ void console_unblank(void)
>  		pr_flush(1000, true);
>  }
>  

I would call this function __console_rewind_all(void)
because it is not safe on its own. Also It would
deserve a comment, something like:

/*
 * Rewind all consoles to the oldest available record.
 *
 * IMPORTANT: The function is safe only when called under
 *            console_lock(). It is not enforced because
 *	      it is used as a best effort in panic().
 */
static void __console_rewind_all(void)


This would deserve a comment because it is not safe by
default.

> +static void console_rewind_all(void)
> +{
> +	struct console *c;
> +	short flags;
> +	int cookie;
> +	u64 seq;
> +
> +	seq = prb_first_valid_seq(prb);
> +
> +	cookie = console_srcu_read_lock();
> +	for_each_console_srcu(c) {
> +		flags = console_srcu_read_flags(c);
> +
> +		if (flags & CON_NBCON) {
> +			nbcon_seq_force(c, seq);
> +		} else {
> +			/*
> +			 * This is an unsynchronized assignment. On
> +			 * panic legacy consoles are only best effort.
> +			 */

We should change this to something like:

			/*
			 * This assigment is safe only when called under
			 * console_lock(). */
			 */

> +			c->seq = seq;
> +		}
> +	}
> +	console_srcu_read_unlock(cookie);
> +}
> +
>  /**
>   * console_flush_on_panic - flush console content on panic
>   * @mode: flush all messages in buffer or just the pending ones
> @@ -3162,30 +3188,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
>  	 */
>  	console_may_schedule = 0;
>  
> -	if (mode == CONSOLE_REPLAY_ALL) {
> -		struct console *c;
> -		short flags;
> -		int cookie;
> -		u64 seq;
> -
> -		seq = prb_first_valid_seq(prb);
> -
> -		cookie = console_srcu_read_lock();
> -		for_each_console_srcu(c) {
> -			flags = console_srcu_read_flags(c);
> -
> -			if (flags & CON_NBCON) {
> -				nbcon_seq_force(c, seq);
> -			} else {
> -				/*
> -				 * This is an unsynchronized assignment. On
> -				 * panic legacy consoles are only best effort.
> -				 */
> -				c->seq = seq;
> -			}
> -		}
> -		console_srcu_read_unlock(cookie);
> -	}
> +	if (mode == CONSOLE_REPLAY_ALL)
> +		console_rewind_all();
>  
>  	console_flush_all(false, &next_seq, &handover);
>  }
> @@ -4259,6 +4263,15 @@ void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
>  }
>  EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
>  
> +/**
> + * Dump the printk ring buffer directly to consoles
> + */
> +void dump_printk_buffer(void)

I would call this function console_replay_all(). IMHO, it better describes
what it does.

> +{
> +	console_lock();
> +	console_rewind_all();

I would add a comment:

	/* Consoles are flushed as part of console_unlock(). */

> +	console_unlock();
> +}
>  #endif

Best Regards,
Petr

Re: [PATCH v4 1/2] printk: Add function to dump printk buffer directly to consoles

[Sreenath Vijayan]

On Wed, Feb 07, 2024 at 03:43:52PM +0100, Petr Mladek wrote:
> On Thu 2024-02-01 15:53:40, Sreenath Vijayan wrote:
> > It is useful to be able to dump the printk buffer directly to
> > consoles in some situations so as to not flood the buffer.
> 
> This is not longer true. I think that it was valid for
> the previous versions which used separate buffers with
> the kmsg_dump API.
> 
> > To do this, we reuse the CONSOLE_REPLAY_ALL mode code in
> > console_flush_on_panic() by moving the code to a helper function
> > console_rewind_all(). This is done because console_flush_on_panic()
> > sets console_may_schedule to 0 but this should not be done in our
> > case.
> 
> Also the "c->seq = seq;" is not safe in the panic version.
> But it will be safe when called under the console_lock.
> 
> > Then console_rewind_all() is called from the new function
> > dump_printk_buffer() with console lock held to set the console
> > sequence number to oldest record in the buffer for all consoles.
> > Releasing the console lock will flush the contents of printk buffer
> > to the consoles.
> 
> My proposed commit message is:
> 
> <proposal>
> Add a generic function for replaying the kernel log on consoles.
> It would allow seeing the the log on an unresponsive terminal
> via sysrq interface.
> 
> Reuse the existing code from console_flush_on_panic() for
> reseting the sequence numbers. It will be safe when called
> under console_lock(). Also the console_unlock() will
> automatically flush the messages on the consoles.
> 
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -3134,6 +3134,32 @@ void console_unblank(void)
> >  		pr_flush(1000, true);
> >  }
> >  
> 
> I would call this function __console_rewind_all(void)
> because it is not safe on its own. Also It would
> deserve a comment, something like:
> 
> /*
>  * Rewind all consoles to the oldest available record.
>  *
>  * IMPORTANT: The function is safe only when called under
>  *            console_lock(). It is not enforced because
>  *	      it is used as a best effort in panic().
>  */
> static void __console_rewind_all(void)
> 
> 
> This would deserve a comment because it is not safe by
> default.
> 
> > +static void console_rewind_all(void)
> > +{
> > +	struct console *c;
> > +	short flags;
> > +	int cookie;
> > +	u64 seq;
> > +
> > +	seq = prb_first_valid_seq(prb);
> > +
> > +	cookie = console_srcu_read_lock();
> > +	for_each_console_srcu(c) {
> > +		flags = console_srcu_read_flags(c);
> > +
> > +		if (flags & CON_NBCON) {
> > +			nbcon_seq_force(c, seq);
> > +		} else {
> > +			/*
> > +			 * This is an unsynchronized assignment. On
> > +			 * panic legacy consoles are only best effort.
> > +			 */
> 
> We should change this to something like:
> 
> 			/*
> 			 * This assigment is safe only when called under
> 			 * console_lock(). */
> 			 */
> 
> > +			c->seq = seq;
> > +		}
> > +	}
> > +	console_srcu_read_unlock(cookie);
> > +}
> > +
> >  /**
> >   * console_flush_on_panic - flush console content on panic
> >   * @mode: flush all messages in buffer or just the pending ones
> > @@ -3162,30 +3188,8 @@ void console_flush_on_panic(enum con_flush_mode mode)
> >  	 */
> >  	console_may_schedule = 0;
> >  
> > -	if (mode == CONSOLE_REPLAY_ALL) {
> > -		struct console *c;
> > -		short flags;
> > -		int cookie;
> > -		u64 seq;
> > -
> > -		seq = prb_first_valid_seq(prb);
> > -
> > -		cookie = console_srcu_read_lock();
> > -		for_each_console_srcu(c) {
> > -			flags = console_srcu_read_flags(c);
> > -
> > -			if (flags & CON_NBCON) {
> > -				nbcon_seq_force(c, seq);
> > -			} else {
> > -				/*
> > -				 * This is an unsynchronized assignment. On
> > -				 * panic legacy consoles are only best effort.
> > -				 */
> > -				c->seq = seq;
> > -			}
> > -		}
> > -		console_srcu_read_unlock(cookie);
> > -	}
> > +	if (mode == CONSOLE_REPLAY_ALL)
> > +		console_rewind_all();
> >  
> >  	console_flush_all(false, &next_seq, &handover);
> >  }
> > @@ -4259,6 +4263,15 @@ void kmsg_dump_rewind(struct kmsg_dump_iter *iter)
> >  }
> >  EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
> >  
> > +/**
> > + * Dump the printk ring buffer directly to consoles
> > + */
> > +void dump_printk_buffer(void)
> 
> I would call this function console_replay_all(). IMHO, it better describes
> what it does.
> 
> > +{
> > +	console_lock();
> > +	console_rewind_all();
> 
> I would add a comment:
> 
> 	/* Consoles are flushed as part of console_unlock(). */
> 
> > +	console_unlock();
> > +}
> >  #endif
> 
> Best Regards,
> Petr

Thank you for the review comments. Will fix all these points in the
next version.

Regards,
Sreenath

[PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Sreenath Vijayan]

When terminal is unresponsive, one cannot use dmesg to view printk
ring buffer messages. Also, syslog services may be disabled,
to check the messages after a reboot, especially on embedded systems.
In this scenario, dump the printk ring buffer messages via sysrq
by pressing sysrq+D.

Signed-off-by: Sreenath Vijayan <sreenath.vijayan@sony.com>
Signed-off-by: Shimoyashiki Taichi <taichi.shimoyashiki@sony.com>
---
 Documentation/admin-guide/sysrq.rst |  2 ++
 drivers/tty/sysrq.c                 | 20 +++++++++++++++++++-
 2 files changed, 21 insertions(+), 1 deletion(-)

diff --git a/Documentation/admin-guide/sysrq.rst b/Documentation/admin-guide/sysrq.rst
index 2f2e5bd440f9..c634e8b4cea2 100644
--- a/Documentation/admin-guide/sysrq.rst
+++ b/Documentation/admin-guide/sysrq.rst
@@ -161,6 +161,8 @@ Command	    Function
             will be printed to your console. (``0``, for example would make
             it so that only emergency messages like PANICs or OOPSes would
             make it to your console.)
+
+``D``	    Dump the printk ring buffer
 =========== ===================================================================
 
 Okay, so what can I use them for?
diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index 02217e3c916b..365f7fa145f0 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -450,6 +450,24 @@ static const struct sysrq_key_op sysrq_unrt_op = {
 	.enable_mask	= SYSRQ_ENABLE_RTNICE,
 };
 
+static void dmesg_dump_callback(struct work_struct *work)
+{
+	dump_printk_buffer();
+}
+
+static DECLARE_WORK(sysrq_dmesg_work, dmesg_dump_callback);
+
+static void sysrq_handle_dmesg_dump(u8 key)
+{
+	queue_work(system_unbound_wq, &sysrq_dmesg_work);
+}
+static struct sysrq_key_op sysrq_dmesg_dump_op = {
+	.handler        = sysrq_handle_dmesg_dump,
+	.help_msg       = "dump-dmesg(D)",
+	.action_msg     = "Dump dmesg",
+	.enable_mask    = SYSRQ_ENABLE_DUMP,
+};
+
 /* Key Operations table and lock */
 static DEFINE_SPINLOCK(sysrq_key_table_lock);
 
@@ -505,7 +523,7 @@ static const struct sysrq_key_op *sysrq_key_table[62] = {
 	NULL,				/* A */
 	NULL,				/* B */
 	NULL,				/* C */
-	NULL,				/* D */
+	&sysrq_dmesg_dump_op,		/* D */
 	NULL,				/* E */
 	NULL,				/* F */
 	NULL,				/* G */
-- 
2.43.0

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[John Ogness]

On 2024-02-01, Sreenath Vijayan <sreenath.vijayan@sony.com> wrote:
> When terminal is unresponsive, one cannot use dmesg to view printk
> ring buffer messages. Also, syslog services may be disabled,
> to check the messages after a reboot, especially on embedded systems.
> In this scenario, dump the printk ring buffer messages via sysrq
> by pressing sysrq+D.
>
> Signed-off-by: Sreenath Vijayan <sreenath.vijayan@sony.com>
> Signed-off-by: Shimoyashiki Taichi <taichi.shimoyashiki@sony.com>

Reviewed-by: John Ogness <john.ogness@linutronix.de>

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Petr Mladek]

On Thu 2024-02-01 13:12:41, Sreenath Vijayan wrote:
> When terminal is unresponsive, one cannot use dmesg to view printk
> ring buffer messages. Also, syslog services may be disabled,
> to check the messages after a reboot, especially on embedded systems.
> In this scenario, dump the printk ring buffer messages via sysrq
> by pressing sysrq+D.

I would use sysrq-R and say that it replays the kernel log on
consoles.

The word "dump" is ambiguous. People might thing that it calls
dmesg dumpers.

Also the messages would be shown on the terminal only when
console_loglevel is set to show all messages. This is done
in __handle_sysrq(). But it is not done in the workqueue
context.

Finally, the commit message should explain why workqueues are used
and what are the limitations. Something like:

<add>
The log is replayed using workqueues. The reason is that it has to
be done a safe way (in compare with panic context).

This also means that the sysrq won't have the desired effect
when the system is in so bad state that workqueues do not
make any progress.
</add>

Another reason might be that we do not want to do it in
an interrupt context. But this reason is questionable.
Many other sysrq commands do a complicate work and
print many messages as well.

Another reason is that the function need to use console_lock()
which can't be called in IRQ context. Maybe, we should use
console_trylock() instead.

The function would replay the messages only when console_trylock()
succeeds. Users could repeat the sysrq when it fails.

Idea:

Using console_trylock() actually might be more reliable than
workqueues. console_trylock() might fail repeatably when:

    + the console_lock() owner is stuck. But workqueues would fail
      in this case as well.

    + there is a flood of messages. In this case, replaying
      the log would not help much.

Another advantage is that the consoles would be flushed
in sysrq context with the manipulated console_loglevel.

Best Regards,
Petr

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Greg KH]

On Wed, Feb 07, 2024 at 04:09:34PM +0100, Petr Mladek wrote:
> On Thu 2024-02-01 13:12:41, Sreenath Vijayan wrote:
> > When terminal is unresponsive, one cannot use dmesg to view printk
> > ring buffer messages. Also, syslog services may be disabled,
> > to check the messages after a reboot, especially on embedded systems.
> > In this scenario, dump the printk ring buffer messages via sysrq
> > by pressing sysrq+D.
> 
> I would use sysrq-R and say that it replays the kernel log on
> consoles.
> 
> The word "dump" is ambiguous. People might thing that it calls
> dmesg dumpers.
> 
> Also the messages would be shown on the terminal only when
> console_loglevel is set to show all messages. This is done
> in __handle_sysrq(). But it is not done in the workqueue
> context.
> 
> Finally, the commit message should explain why workqueues are used
> and what are the limitations. Something like:
> 
> <add>
> The log is replayed using workqueues. The reason is that it has to
> be done a safe way (in compare with panic context).
> 
> This also means that the sysrq won't have the desired effect
> when the system is in so bad state that workqueues do not
> make any progress.
> </add>
> 
> Another reason might be that we do not want to do it in
> an interrupt context. But this reason is questionable.
> Many other sysrq commands do a complicate work and
> print many messages as well.
> 
> Another reason is that the function need to use console_lock()
> which can't be called in IRQ context. Maybe, we should use
> console_trylock() instead.
> 
> The function would replay the messages only when console_trylock()
> succeeds. Users could repeat the sysrq when it fails.
> 
> Idea:
> 
> Using console_trylock() actually might be more reliable than
> workqueues. console_trylock() might fail repeatably when:
> 
>     + the console_lock() owner is stuck. But workqueues would fail
>       in this case as well.
> 
>     + there is a flood of messages. In this case, replaying
>       the log would not help much.
> 
> Another advantage is that the consoles would be flushed
> in sysrq context with the manipulated console_loglevel.

I just remembered all the rt-changes coming down the pipe for
consoles/printk, is this going to mess with that?

And in thinking about it, the workqueue is a worry, sysrq is only
usually hit if you have a lockup, and this isn't going to work well
here, if at all, in that situation.

So when this option fails when people need it the most, perhaps it's not
worth adding?  When else would people want to use it?

thanks,

greg k-h

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[John Ogness]

On 2024-02-08, Greg KH <gregkh@linuxfoundation.org> wrote:
> I just remembered all the rt-changes coming down the pipe for
> consoles/printk, is this going to mess with that?

It will not mess with the changes because we will continue to support
the legacy consoles anyway.

> So when this option fails when people need it the most, perhaps it's not
> worth adding?  When else would people want to use it?

The feature could be massively improved once the rt-changes (atomic
consoles) become available.

Petr also brought up valid points about this feature (such as the
loglevel) that should be considered. We should clarify what exactly we
want this feature to do. The actual implementation is the easy part.

John

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Sreenath Vijayan]

On Wed, Feb 07, 2024 at 04:09:34PM +0100, Petr Mladek wrote:
> On Thu 2024-02-01 13:12:41, Sreenath Vijayan wrote:
> > When terminal is unresponsive, one cannot use dmesg to view printk
> > ring buffer messages. Also, syslog services may be disabled,
> > to check the messages after a reboot, especially on embedded systems.
> > In this scenario, dump the printk ring buffer messages via sysrq
> > by pressing sysrq+D.
> 
> I would use sysrq-R and say that it replays the kernel log on
> consoles.
> 
> The word "dump" is ambiguous. People might thing that it calls
> dmesg dumpers.
>

Ok noted. We proposed sysrq-D as it is an alternative to dmesg
command and might be easier to remember.
 
> Also the messages would be shown on the terminal only when
> console_loglevel is set to show all messages. This is done
> in __handle_sysrq(). But it is not done in the workqueue
> context.
> 

Yes, the initial implementation was using write() of consoles
so the messages would be shown irrespective of the console log
level. The current implementation depends on the console log
level but many other sysrq keys dump the messages at KERN_INFO
level. In my understanding, __handle_sysrq() dumps only the
sysrq header at the manipulated loglevel. It restores original
loglevel before calling callback function for the key.
If console_loglevel is set to show KERN_INFO messages, it would
dump most of the important printk messages in our case. Also the
loglevel can be modified using sysrq itself now.

> Finally, the commit message should explain why workqueues are used
> and what are the limitations. Something like:
> 
> <add>
> The log is replayed using workqueues. The reason is that it has to
> be done a safe way (in compare with panic context).
> 
> This also means that the sysrq won't have the desired effect
> when the system is in so bad state that workqueues do not
> make any progress.
> </add>
> 
> Another reason might be that we do not want to do it in
> an interrupt context. But this reason is questionable.
> Many other sysrq commands do a complicate work and
> print many messages as well.
>

Noted. Will add this if we proceed with workqueue implementation.
 
> Another reason is that the function need to use console_lock()
> which can't be called in IRQ context. Maybe, we should use
> console_trylock() instead.
> 
> The function would replay the messages only when console_trylock()
> succeeds. Users could repeat the sysrq when it fails.
> 
> Idea:
> 
> Using console_trylock() actually might be more reliable than
> workqueues. console_trylock() might fail repeatably when:
> 
>     + the console_lock() owner is stuck. But workqueues would fail
>       in this case as well.
> 
>     + there is a flood of messages. In this case, replaying
>       the log would not help much.
> 
> Another advantage is that the consoles would be flushed
> in sysrq context with the manipulated console_loglevel.
> 
> Best Regards,
> Petr

Yes, this seems to work well from interrupt context when the
console lock owner is not stuck. We can also manipulate
the console_loglevel. Something like this:

//in printk.c
void console_replay_all(void)
{
       if (console_trylock()) {
               __console_rewind_all();
               console_unlock();
       }
}

//in sysrq.c
static void sysrq_handle_dmesg_dump(u8 key)
{
       int orig_log_level = console_loglevel;
       console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
       console_replay_all();
       console_loglevel = orig_log_level;
}


The downside I see is that the user may have to hit the
key multiple times or give up trying if the console lock
owner is busy at the time of key press. This information
should probably be updated in the documentation.

Please let me know your opinion.

Regards,
Sreenath

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Sreenath Vijayan]

On Wed, Feb 07, 2024 at 04:09:34PM +0100, Petr Mladek wrote:
> On Thu 2024-02-01 13:12:41, Sreenath Vijayan wrote:
> > When terminal is unresponsive, one cannot use dmesg to view printk
> > ring buffer messages. Also, syslog services may be disabled,
> > to check the messages after a reboot, especially on embedded systems.
> > In this scenario, dump the printk ring buffer messages via sysrq
> > by pressing sysrq+D.
> 
> I would use sysrq-R and say that it replays the kernel log on
> consoles.
> 
> The word "dump" is ambiguous. People might thing that it calls
> dmesg dumpers.
>

Ok noted. We proposed sysrq-D as it is an alternative to dmesg
command and might be easier to remember.
 
> Also the messages would be shown on the terminal only when
> console_loglevel is set to show all messages. This is done
> in __handle_sysrq(). But it is not done in the workqueue
> context.
>

Yes, the initial implementation was using write() of consoles
so the messages would be shown irrespective of the console log
level. The current implementation depends on the console log
level but many other sysrq keys dump the messages at KERN_INFO
level. In my understanding, __handle_sysrq() dumps only the
sysrq header at the manipulated loglevel. It restores original
loglevel before calling callback function for the key.
If console_loglevel is set to show KERN_INFO messages, it would
dump most of the important printk messages in our case. Also the
loglevel can be modified using sysrq itself now.
 
> Finally, the commit message should explain why workqueues are used
> and what are the limitations. Something like:
> 
> <add>
> The log is replayed using workqueues. The reason is that it has to
> be done a safe way (in compare with panic context).
> 
> This also means that the sysrq won't have the desired effect
> when the system is in so bad state that workqueues do not
> make any progress.
> </add>
> 
> Another reason might be that we do not want to do it in
> an interrupt context. But this reason is questionable.
> Many other sysrq commands do a complicate work and
> print many messages as well.
>

Noted. Will add this if we proceed with workqueue implementation.
 
> Another reason is that the function need to use console_lock()
> which can't be called in IRQ context. Maybe, we should use
> console_trylock() instead.
> 
> The function would replay the messages only when console_trylock()
> succeeds. Users could repeat the sysrq when it fails.
> 
> Idea:
> 
> Using console_trylock() actually might be more reliable than
> workqueues. console_trylock() might fail repeatably when:
> 
>     + the console_lock() owner is stuck. But workqueues would fail
>       in this case as well.
> 
>     + there is a flood of messages. In this case, replaying
>       the log would not help much.
> 
> Another advantage is that the consoles would be flushed
> in sysrq context with the manipulated console_loglevel.
> 
> Best Regards,
> Petr

Yes, this seems to work well from interrupt context when the
console lock owner is not stuck. We can also manipulate
the console_loglevel. Something like this:

//in printk.c
void console_replay_all(void)
{
       if (console_trylock()) {
               __console_rewind_all();
               console_unlock();
       }
}

//in sysrq.c
static void sysrq_handle_dmesg_dump(u8 key)
{
       int orig_log_level = console_loglevel;
       console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
       console_replay_all();
       console_loglevel = orig_log_level;
}


The downside I see is that the user may have to hit the
key multiple times or give up trying if the console lock
owner is busy at the time of key press. This information
should probably be updated in the documentation.

Please let me know your opinion.

Regards,
Sreenath

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[Sreenath Vijayan]

On Wed, Feb 14, 2024 at 04:42:36PM +0530, Sreenath Vijayan wrote:
> On Wed, Feb 07, 2024 at 04:09:34PM +0100, Petr Mladek wrote:
> > Idea:
> > 
> > Using console_trylock() actually might be more reliable than
> > workqueues. console_trylock() might fail repeatably when:
> > 
> >     + the console_lock() owner is stuck. But workqueues would fail
> >       in this case as well.
> > 
> >     + there is a flood of messages. In this case, replaying
> >       the log would not help much.
> > 
> > Another advantage is that the consoles would be flushed
> > in sysrq context with the manipulated console_loglevel.
> > 
> > Best Regards,
> > Petr
> 
> Yes, this seems to work well from interrupt context when the
> console lock owner is not stuck. We can also manipulate
> the console_loglevel. Something like this:
> 
> //in printk.c
> void console_replay_all(void)
> {
>        if (console_trylock()) {
>                __console_rewind_all();
>                console_unlock();
>        }
> }
> 
> //in sysrq.c
> static void sysrq_handle_dmesg_dump(u8 key)
> {
>        int orig_log_level = console_loglevel;
>        console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
>        console_replay_all();
>        console_loglevel = orig_log_level;
> }
> 
> 
> The downside I see is that the user may have to hit the
> key multiple times or give up trying if the console lock
> owner is busy at the time of key press. This information
> should probably be updated in the documentation.
> 
> Please let me know your opinion.
> 
> Regards,
> Sreenath

Hi,

Kindly let me know your opinion on the suggested changes.

Regards,
Sreenath

Re: [PATCH v4 2/2] tty/sysrq: Dump printk ring buffer messages via sysrq

[John Ogness]

On 2024-02-14, Sreenath Vijayan <sreenath.vijayan@sony.com> wrote:
> //in printk.c
> void console_replay_all(void)
> {
>        if (console_trylock()) {
>                __console_rewind_all();
>                console_unlock();
>        }
> }
>
> //in sysrq.c
> static void sysrq_handle_dmesg_dump(u8 key)
> {
>        int orig_log_level = console_loglevel;
>        console_loglevel = CONSOLE_LOGLEVEL_DEFAULT;
>        console_replay_all();
>        console_loglevel = orig_log_level;
> }

Note that there is already a sysrq 0-9 to change the loglevel. That may
be more appropriate.

John

Re: [PATCH v4 0/2] Add support to dump printk buffer to console via sysrq

[Petr Mladek]

Hi,

first, I am sorry for joining the game so late. I was sick
and have had a lot of pending tasks after Christmas's holidays
and the sickness.

On Thu 2024-02-01 13:12:39, Sreenath Vijayan wrote:
> Hi,
> 
> This patch series enables one to dump the messages in printk ring
> buffer unless all CPUs are locked up. This is useful to view the
> kernel messages when terminal is unresponsive to enter commands
> like dmesg and syslog services are also disabled, especially on
> embedded targets.

What is the exact scenario for this feature, please?

IMHO, rewinding the entire log on an unresponsive terminal
has a questionable value. Most messages would scroll down
quickly and only the last messages would stay visible.

Also this code would rewind all consoles, including
(slow) serial ones. I wonder if rewind on these consoles
would be useful as well.

That said, I am not completely against this feature.
I just want to be sure that it does what you expect.

Best Regards,
Petr

Re: [PATCH v4 0/2] Add support to dump printk buffer to console via sysrq

[Sreenath Vijayan]

On Wed, Feb 07, 2024 at 03:12:09PM +0100, Petr Mladek wrote:
> Hi,
> 
> first, I am sorry for joining the game so late. I was sick
> and have had a lot of pending tasks after Christmas's holidays
> and the sickness.
> 
> On Thu 2024-02-01 13:12:39, Sreenath Vijayan wrote:
> > Hi,
> > 
> > This patch series enables one to dump the messages in printk ring
> > buffer unless all CPUs are locked up. This is useful to view the
> > kernel messages when terminal is unresponsive to enter commands
> > like dmesg and syslog services are also disabled, especially on
> > embedded targets.
> 
> What is the exact scenario for this feature, please?
> 

Sometimes, we do some testing without connecting display or consoles
and when we connect back to console, we find the system in a hung
state and unable to enter any commands. The system maynot be
completely locked up. In this scenario, we use this feature to view
the printk buffer to get some idea about why the system is hung.

Basically, this can be used in any scenario where you are unable
to enter commands due to some reason, but atleast one cpu is in
a condition to process the unbound workqueue. We have found this
useful during nfs hangs also.

> IMHO, rewinding the entire log on an unresponsive terminal
> has a questionable value. Most messages would scroll down
> quickly and only the last messages would stay visible.
> 
> Also this code would rewind all consoles, including
> (slow) serial ones. I wonder if rewind on these consoles
> would be useful as well.
> 
> That said, I am not completely against this feature.
> I just want to be sure that it does what you expect.
> 
> Best Regards,
> Petr

We mostly use this to display the kernel messages on serial
consoles and have found it to be working fine. In this case,
we use some terminal emulator and can scroll through the output.

Regards,
Sreenath