linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH v2] panic: add an option to replay all the printk message in buffer
@ 2019-04-10 15:37 Feng Tang
  2019-04-17  4:19 ` Andrew Morton
  0 siblings, 1 reply; 14+ messages in thread
From: Feng Tang @ 2019-04-10 15:37 UTC (permalink / raw)
  To: Andrew Morton, Petr Mladek, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel
  Cc: Kees Cook, Borislav Petkov, Feng Tang

Currently on panic, kernel will lower the loglevel and print out
new printk msg only with console_flush_on_panic().

Add an option for users to configure the "panic_print" to see
all dmesg in buffer, some of which they may have never seen due
to the loglevel setting, which will help debugging too.

Thanks to Petr Mladek as somes codes come directly from the sample
code in his review comments.

Signed-off-by: Feng Tang <feng.tang@intel.com>
---
Changelog:

  v2:
    - Add a new func in printk.c dedicated for the replaying, as
      suggested by Petr Mladekand
    - Combine the 2 patches in v1 into one suggested by both Petr
      and Sergey

 Documentation/admin-guide/kernel-parameters.txt |  1 +
 include/linux/console.h                         |  1 +
 kernel/panic.c                                  |  5 +++
 kernel/printk/printk.c                          | 46 ++++++++++++++++++++-----
 4 files changed, 44 insertions(+), 9 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 2b8ee90bb644..7b15c9442325 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3135,6 +3135,7 @@
 			bit 2: print timer info
 			bit 3: print locks info if CONFIG_LOCKDEP is on
 			bit 4: print ftrace buffer
+			bit 5: print all printk messages in buffer
 
 	panic_on_warn	panic() instead of WARN().  Useful to cause kdump
 			on a WARN().
diff --git a/include/linux/console.h b/include/linux/console.h
index ec9bdb3d7bab..42f611a6b7ea 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -176,6 +176,7 @@ extern void console_unlock(void);
 extern void console_conditional_schedule(void);
 extern void console_unblank(void);
 extern void console_flush_on_panic(void);
+extern void console_replay_on_panic(void);
 extern struct tty_driver *console_device(int *);
 extern void console_stop(struct console *);
 extern void console_start(struct console *);
diff --git a/kernel/panic.c b/kernel/panic.c
index 0ae0d7332f12..5a3b7e302c8e 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -51,6 +51,7 @@ EXPORT_SYMBOL_GPL(panic_timeout);
 #define PANIC_PRINT_TIMER_INFO		0x00000004
 #define PANIC_PRINT_LOCK_INFO		0x00000008
 #define PANIC_PRINT_FTRACE_INFO		0x00000010
+#define PANIC_PRINT_ALL_PRINTK_MSG	0x00000020
 unsigned long panic_print;
 
 ATOMIC_NOTIFIER_HEAD(panic_notifier_list);
@@ -134,6 +135,10 @@ EXPORT_SYMBOL(nmi_panic);
 
 static void panic_print_sys_info(void)
 {
+	/* Replay existing messages before adding other sys info. */
+	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG)
+		console_replay_on_panic();
+
 	if (panic_print & PANIC_PRINT_TASK_INFO)
 		show_state();
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 02ca827b8fac..97aab099d22a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -269,6 +269,9 @@ EXPORT_SYMBOL(console_set_on_cmdline);
 /* Flag: console code may call schedule() */
 static int console_may_schedule;
 
+/* Whether to print all messages in buffer */
+static int console_replay;
+
 enum con_msg_format_flags {
 	MSG_FORMAT_DEFAULT	= 0,
 	MSG_FORMAT_SYSLOG	= (1 << 0),
@@ -2386,21 +2389,32 @@ void console_unlock(void)
 
 	for (;;) {
 		struct printk_log *msg;
+		int reset_idx = 0;
 		size_t ext_len = 0;
-		size_t len;
+		size_t len = 0;
 
 		printk_safe_enter_irqsave(flags);
 		raw_spin_lock(&logbuf_lock);
+
 		if (console_seq < log_first_seq) {
 			len = sprintf(text,
 				      "** %llu printk messages dropped **\n",
 				      log_first_seq - console_seq);
 
 			/* messages are gone, move to first one */
+			reset_idx = 1;
+		}
+
+		if (console_replay) {
+			len += sprintf(text + len,
+				       "Replaying the entire log:\n");
+			reset_idx = 1;
+			console_replay = 0;
+		}
+
+		if (reset_idx) {
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
-		} else {
-			len = 0;
 		}
 skip:
 		if (console_seq == log_next_seq)
@@ -2523,12 +2537,7 @@ void console_unblank(void)
 	console_unlock();
 }
 
-/**
- * console_flush_on_panic - flush console content on panic
- *
- * Immediately output all pending messages no matter what.
- */
-void console_flush_on_panic(void)
+static void __flush_on_panic(int replay)
 {
 	/*
 	 * If someone else is holding the console lock, trylock will fail
@@ -2539,9 +2548,28 @@ void console_flush_on_panic(void)
 	 */
 	console_trylock();
 	console_may_schedule = 0;
+	console_replay = replay ? 1 : 0;
 	console_unlock();
 }
 
+/**
+ * console_flush_on_panic - flush console content on panic
+ *
+ * Immediately output all pending messages no matter what.
+ */
+void console_flush_on_panic(void)
+{
+	__flush_on_panic(0);
+}
+
+/**
+ * console_replay_on_panic - replay all messages in buffer on panic
+ */
+void console_replay_on_panic(void)
+{
+	__flush_on_panic(1);
+}
+
 /*
  * Return the console tty driver structure and its associated index
  */
-- 
2.14.1


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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-10 15:37 [PATCH v2] panic: add an option to replay all the printk message in buffer Feng Tang
@ 2019-04-17  4:19 ` Andrew Morton
  2019-04-17  6:48   ` Feng Tang
  0 siblings, 1 reply; 14+ messages in thread
From: Andrew Morton @ 2019-04-17  4:19 UTC (permalink / raw)
  To: Feng Tang
  Cc: Petr Mladek, Steven Rostedt, Sergey Senozhatsky, linux-kernel,
	Kees Cook, Borislav Petkov

On Wed, 10 Apr 2019 23:37:18 +0800 Feng Tang <feng.tang@intel.com> wrote:

> Currently on panic, kernel will lower the loglevel and print out
> new printk msg only with console_flush_on_panic().
> 
> Add an option for users to configure the "panic_print" to see
> all dmesg in buffer, some of which they may have never seen due
> to the loglevel setting, which will help debugging too.
> 
> Thanks to Petr Mladek as somes codes come directly from the sample
> code in his review comments.

CONFIG_PRINTK=n:

kernel/printk/printk.c: In function console_unlock:
kernel/printk/printk.c:2419:11: warning: __builtin_memcpy writing 27 bytes into a region of size 0 overflows the destination [-Wstringop-overflow=]
    len += sprintf(text + len,
           ^~~~~~~~~~~~~~~~~~~
            "Replaying the entire log:\n");
            ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

because LOG_LINE_MAX=0 and PREFIX_MAX=0.


Which is interesting.  The pre-existing

			len = sprintf(text,
				      "** %llu printk messages dropped **\n",
				      log_first_seq - console_seq);

in console_unlock() has the same issue, but the compiler doesn't seem
to want to warn.

(Also, using sprintf() is a bit lame for the new message - could use
strlcpy()).

I'll drop the patch for now - we don't want that warning to come out. 
console_unlock() needs some fixing for the CONFIG_PRINTK=n case.


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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17  4:19 ` Andrew Morton
@ 2019-04-17  6:48   ` Feng Tang
  2019-04-17  9:18     ` Petr Mladek
  0 siblings, 1 reply; 14+ messages in thread
From: Feng Tang @ 2019-04-17  6:48 UTC (permalink / raw)
  To: Andrew Morton, Petr Mladek, Steven Rostedt, Sergey Senozhatsky
  Cc: linux-kernel, Kees Cook, Borislav Petkov, ying.huang

Hi Andrew,

On Tue, Apr 16, 2019 at 09:19:22PM -0700, Andrew Morton wrote:
> On Wed, 10 Apr 2019 23:37:18 +0800 Feng Tang <feng.tang@intel.com> wrote:
> 
> > Currently on panic, kernel will lower the loglevel and print out
> > new printk msg only with console_flush_on_panic().
> > 
> > Add an option for users to configure the "panic_print" to see
> > all dmesg in buffer, some of which they may have never seen due
> > to the loglevel setting, which will help debugging too.
> > 
> > Thanks to Petr Mladek as somes codes come directly from the sample
> > code in his review comments.
> 
> CONFIG_PRINTK=n:
> 
> kernel/printk/printk.c: In function console_unlock:
> kernel/printk/printk.c:2419:11: warning: __builtin_memcpy writing 27 bytes into a region of size 0 overflows the destination [-Wstringop-overflow=]
>     len += sprintf(text + len,
>            ^~~~~~~~~~~~~~~~~~~
>             "Replaying the entire log:\n");
>             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 
> because LOG_LINE_MAX=0 and PREFIX_MAX=0.

Thanks for catching this!

> 
> 
> Which is interesting.  The pre-existing
> 
> 			len = sprintf(text,
> 				      "** %llu printk messages dropped **\n",
> 				      log_first_seq - console_seq);
> 
> in console_unlock() has the same issue, but the compiler doesn't seem
> to want to warn.

For this one, I did some check, and it should be related with the
conditional check 
	if (console_seq < log_first_seq) {

Both the console_seq and log_first_seq will not be touched by any code
when CONFIG_PRINTK=n, and compiler will simply skip the whole code block,
as "console_seq < log_first_seq" will never happen.

But code block following "if (console_replay)" will be compiled, that's
why these warning message will be shown.

> 
> (Also, using sprintf() is a bit lame for the new message - could use
> strlcpy()).
> 
> I'll drop the patch for now - we don't want that warning to come out. 
> console_unlock() needs some fixing for the CONFIG_PRINTK=n case.

My instant thought would be put the console_unlcok() and similar funcs
under CONFIG_PRINTK protection, while adding nop functions in the "else"
segment.

But complexer question will be when CONFIG_PRINTK=n, how those console_xxx
functions should consider these to make compiled binary smaller (though it
rarely happens). would wait for Petr/Sergey/Steven's insights.

Thanks,
Feng

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17  6:48   ` Feng Tang
@ 2019-04-17  9:18     ` Petr Mladek
  2019-04-17  9:46       ` Sergey Senozhatsky
  0 siblings, 1 reply; 14+ messages in thread
From: Petr Mladek @ 2019-04-17  9:18 UTC (permalink / raw)
  To: Feng Tang
  Cc: Andrew Morton, Steven Rostedt, Sergey Senozhatsky, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Wed 2019-04-17 14:48:44, Feng Tang wrote:
> Hi Andrew,
> 
> On Tue, Apr 16, 2019 at 09:19:22PM -0700, Andrew Morton wrote:
> > On Wed, 10 Apr 2019 23:37:18 +0800 Feng Tang <feng.tang@intel.com> wrote:
> > 
> > > Currently on panic, kernel will lower the loglevel and print out
> > > new printk msg only with console_flush_on_panic().
> > > 
> > > Add an option for users to configure the "panic_print" to see
> > > all dmesg in buffer, some of which they may have never seen due
> > > to the loglevel setting, which will help debugging too.
> > > 
> > > Thanks to Petr Mladek as somes codes come directly from the sample
> > > code in his review comments.
> > 
> > CONFIG_PRINTK=n:
> > 
> > kernel/printk/printk.c: In function console_unlock:
> > kernel/printk/printk.c:2419:11: warning: __builtin_memcpy writing 27 bytes into a region of size 0 overflows the destination [-Wstringop-overflow=]
> >     len += sprintf(text + len,
> >            ^~~~~~~~~~~~~~~~~~~
> >             "Replaying the entire log:\n");
> >             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > 
> > because LOG_LINE_MAX=0 and PREFIX_MAX=0.
> 
> Thanks for catching this!
> 
> > 
> > 
> > Which is interesting.  The pre-existing
> > 
> > 			len = sprintf(text,
> > 				      "** %llu printk messages dropped **\n",
> > 				      log_first_seq - console_seq);
> > 
> > in console_unlock() has the same issue, but the compiler doesn't seem
> > to want to warn.
> 
> For this one, I did some check, and it should be related with the
> conditional check 
> 	if (console_seq < log_first_seq) {
> 
> Both the console_seq and log_first_seq will not be touched by any code
> when CONFIG_PRINTK=n, and compiler will simply skip the whole code block,
> as "console_seq < log_first_seq" will never happen.
> 
> But code block following "if (console_replay)" will be compiled, that's
> why these warning message will be shown.
> 
> > 
> > (Also, using sprintf() is a bit lame for the new message - could use
> > strlcpy()).
> > 
> > I'll drop the patch for now - we don't want that warning to come out. 
> > console_unlock() needs some fixing for the CONFIG_PRINTK=n case.
> 
> My instant thought would be put the console_unlcok() and similar funcs
> under CONFIG_PRINTK protection, while adding nop functions in the "else"
> segment.
> 
> But complexer question will be when CONFIG_PRINTK=n, how those console_xxx
> functions should consider these to make compiled binary smaller (though it
> rarely happens). would wait for Petr/Sergey/Steven's insights.

I guess that it is because console_sem is historically used to
synchronize some unrelated things, espcially in tty code.
Unfortunately, it is not easy to clean this up.

For this patch, the best solution seems to be using scnprintf()
instead of sprintf().

Please, note the difference between snprintf() and scnprintf().
We need the "scn*" variant the returns the number of really
printed characters.

Best Regards,
Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17  9:18     ` Petr Mladek
@ 2019-04-17  9:46       ` Sergey Senozhatsky
  2019-04-17 10:50         ` Sergey Senozhatsky
  0 siblings, 1 reply; 14+ messages in thread
From: Sergey Senozhatsky @ 2019-04-17  9:46 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Feng Tang, Andrew Morton, Steven Rostedt, Sergey Senozhatsky,
	linux-kernel, Kees Cook, Borislav Petkov, ying.huang

On (04/17/19 11:18), Petr Mladek wrote:
> > My instant thought would be put the console_unlcok() and similar funcs
> > under CONFIG_PRINTK protection, while adding nop functions in the "else"
> > segment.
> > 
> > But complexer question will be when CONFIG_PRINTK=n, how those console_xxx
> > functions should consider these to make compiled binary smaller (though it
> > rarely happens). would wait for Petr/Sergey/Steven's insights.
> 
> I guess that it is because console_sem is historically used to
> synchronize some unrelated things, espcially in tty code.
> Unfortunately, it is not easy to clean this up.
> 
> For this patch, the best solution seems to be using scnprintf()
> instead of sprintf().

OK, since we have another chance to re-iterate this. Do we really
want to complicate console_unlock() printing loop any further?
Asking off chance, can we return back to the idea of adding enum
FLUSH_PENDING/FLUSH_ALL to console_flush_on_panic()?

Does not look too complex/ugly.

---
-void console_flush_on_panic(void)
+void console_flush_on_panic(enum console_flush_mode flush_mode)
 {
 	/*
 	 * If someone else is holding the console lock, trylock will fail
@@ -2549,6 +2549,10 @@ void console_flush_on_panic(void)
 	 */
 	console_trylock();
 	console_may_schedule = 0;
+	if (flush_mode == FLUSH_ALL) {
+		console_seq = log_first_seq;
+		console_idx = log_first_idx;
+	}
 	console_unlock();
 }
---

	-ss

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17  9:46       ` Sergey Senozhatsky
@ 2019-04-17 10:50         ` Sergey Senozhatsky
  2019-04-17 12:24           ` Petr Mladek
  0 siblings, 1 reply; 14+ messages in thread
From: Sergey Senozhatsky @ 2019-04-17 10:50 UTC (permalink / raw)
  To: Petr Mladek, Feng Tang
  Cc: Andrew Morton, Steven Rostedt, linux-kernel, Kees Cook,
	Borislav Petkov, ying.huang, Sergey Senozhatsky

On (04/17/19 18:46), Sergey Senozhatsky wrote:
> 
> Does not look too complex/ugly.

Looks simpler than adding one more global state to the
console_unlock() printing loop.

// Not tested at all //

---

diff --git a/arch/powerpc/kernel/traps.c b/arch/powerpc/kernel/traps.c
index 1fd45a8650e1..0fb785ed5ec6 100644
--- a/arch/powerpc/kernel/traps.c
+++ b/arch/powerpc/kernel/traps.c
@@ -179,7 +179,7 @@ extern void panic_flush_kmsg_end(void)
 	kmsg_dump(KMSG_DUMP_PANIC);
 	bust_spinlocks(0);
 	debug_locks_off();
-	console_flush_on_panic();
+	console_flush_on_panic(CONSOLE_FLUSH_PENDING);
 }
 
 static unsigned long oops_begin(struct pt_regs *regs)
diff --git a/include/linux/console.h b/include/linux/console.h
index ec9bdb3d7bab..9e306eb4398a 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -175,7 +175,13 @@ extern int console_trylock(void);
 extern void console_unlock(void);
 extern void console_conditional_schedule(void);
 extern void console_unblank(void);
-extern void console_flush_on_panic(void);
+
+enum console_flush_mode {
+	CONSOLE_FLUSH_PENDING,
+	CONSOLE_FLUSH_ALL,
+};
+
+extern void console_flush_on_panic(enum console_flush_mode flush_mode);
 extern struct tty_driver *console_device(int *);
 extern void console_stop(struct console *);
 extern void console_start(struct console *);
diff --git a/kernel/panic.c b/kernel/panic.c
index cd73af35ec66..50eacfc9bc7e 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -51,6 +51,7 @@ EXPORT_SYMBOL_GPL(panic_timeout);
 #define PANIC_PRINT_TIMER_INFO		0x00000004
 #define PANIC_PRINT_LOCK_INFO		0x00000008
 #define PANIC_PRINT_FTRACE_INFO		0x00000010
+#define PANIC_PRINT_ALL_PRINTK_MSG	0x00000020
 unsigned long panic_print;
 
 ATOMIC_NOTIFIER_HEAD(panic_notifier_list);
@@ -148,6 +149,9 @@ static void panic_print_sys_info(void)
 
 	if (panic_print & PANIC_PRINT_FTRACE_INFO)
 		ftrace_dump(DUMP_ALL);
+
+	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG)
+		console_flush_on_panic(CONSOLE_FLUSH_ALL);
 }
 
 /**
@@ -277,7 +281,7 @@ void panic(const char *fmt, ...)
 	 * panic() is not being callled from OOPS.
 	 */
 	debug_locks_off();
-	console_flush_on_panic();
+	console_flush_on_panic(CONSOLE_FLUSH_PENDING);
 
 	panic_print_sys_info();
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 17102fd4c136..da60a185dbbb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2538,7 +2538,7 @@ void console_unblank(void)
  *
  * Immediately output all pending messages no matter what.
  */
-void console_flush_on_panic(void)
+void console_flush_on_panic(enum console_flush_mode flush_mode)
 {
 	/*
 	 * If someone else is holding the console lock, trylock will fail
@@ -2549,6 +2549,14 @@ void console_flush_on_panic(void)
 	 */
 	console_trylock();
 	console_may_schedule = 0;
+	if (flush_mode == CONSOLE_FLUSH_ALL) {
+		/*
+		 * Can be done under logbuf lock, but it's unlikely that
+		 * we will have any race conditions here.
+		 */
+		console_seq = log_first_seq;
+		console_idx = log_first_idx;
+	}
 	console_unlock();
 }
 
---

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17 10:50         ` Sergey Senozhatsky
@ 2019-04-17 12:24           ` Petr Mladek
  2019-04-17 15:18             ` Feng Tang
  0 siblings, 1 reply; 14+ messages in thread
From: Petr Mladek @ 2019-04-17 12:24 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Feng Tang, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Wed 2019-04-17 19:50:10, Sergey Senozhatsky wrote:
> On (04/17/19 18:46), Sergey Senozhatsky wrote:
> > 
> > Does not look too complex/ugly.
> 
> Looks simpler than adding one more global state to the
> console_unlock() printing loop.
> 
> // Not tested at all //
> 
> diff --git a/kernel/panic.c b/kernel/panic.c
> index cd73af35ec66..50eacfc9bc7e 100644
> --- a/kernel/panic.c
> +++ b/kernel/panic.c
> @@ -51,6 +51,7 @@ EXPORT_SYMBOL_GPL(panic_timeout);
>  #define PANIC_PRINT_TIMER_INFO		0x00000004
>  #define PANIC_PRINT_LOCK_INFO		0x00000008
>  #define PANIC_PRINT_FTRACE_INFO		0x00000010
> +#define PANIC_PRINT_ALL_PRINTK_MSG	0x00000020
>  unsigned long panic_print;
>  
>  ATOMIC_NOTIFIER_HEAD(panic_notifier_list);
> @@ -148,6 +149,9 @@ static void panic_print_sys_info(void)
>  
>  	if (panic_print & PANIC_PRINT_FTRACE_INFO)
>  		ftrace_dump(DUMP_ALL);
> +
> +	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG)
> +		console_flush_on_panic(CONSOLE_FLUSH_ALL);

The console must be replayed as the first thing in
panic_print_sys_info(). Otherwise, the original messages
are replaced by the other dumps. Especially ftrace_dump()
might be pretty long.

Also the names of the function and the parameter are misleading.
All messages are already flushed when this is called.

>  }
>  
>  /**
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 17102fd4c136..da60a185dbbb 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2549,6 +2549,14 @@ void console_flush_on_panic(void)
>  	 */
>  	console_trylock();
>  	console_may_schedule = 0;
> +	if (flush_mode == CONSOLE_FLUSH_ALL) {
> +		/*
> +		 * Can be done under logbuf lock, but it's unlikely that
> +		 * we will have any race conditions here.
> +		 */
> +		console_seq = log_first_seq;
> +		console_idx = log_first_idx;

I agree that it is easier. The cost is that the same messages are
printed again without any explanation.

I still think that it would be convenient to write a header line.
It would help to understand the log for any, even 3rd-party, reader.
Also it would help to find the beginning in a very long log.

If the complexity of console_unlock() is the concern, we could
refactor the code, e.g. put this "reset log" code into a separate
function.

Best Regards,
Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17 12:24           ` Petr Mladek
@ 2019-04-17 15:18             ` Feng Tang
  2019-04-18  0:00               ` Sergey Senozhatsky
  0 siblings, 1 reply; 14+ messages in thread
From: Feng Tang @ 2019-04-17 15:18 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Wed, Apr 17, 2019 at 02:24:58PM +0200, Petr Mladek wrote:
> On Wed 2019-04-17 19:50:10, Sergey Senozhatsky wrote:
> > On (04/17/19 18:46), Sergey Senozhatsky wrote:
> > > 
> > > Does not look too complex/ugly.
> > 
> > Looks simpler than adding one more global state to the
> > console_unlock() printing loop.
> > 
> > // Not tested at all //
> > 
> > diff --git a/kernel/panic.c b/kernel/panic.c
> > index cd73af35ec66..50eacfc9bc7e 100644
> > --- a/kernel/panic.c
> > +++ b/kernel/panic.c
> > @@ -51,6 +51,7 @@ EXPORT_SYMBOL_GPL(panic_timeout);
> >  #define PANIC_PRINT_TIMER_INFO		0x00000004
> >  #define PANIC_PRINT_LOCK_INFO		0x00000008
> >  #define PANIC_PRINT_FTRACE_INFO		0x00000010
> > +#define PANIC_PRINT_ALL_PRINTK_MSG	0x00000020
> >  unsigned long panic_print;
> >  
> >  ATOMIC_NOTIFIER_HEAD(panic_notifier_list);
> > @@ -148,6 +149,9 @@ static void panic_print_sys_info(void)
> >  
> >  	if (panic_print & PANIC_PRINT_FTRACE_INFO)
> >  		ftrace_dump(DUMP_ALL);
> > +
> > +	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG)
> > +		console_flush_on_panic(CONSOLE_FLUSH_ALL);
> 
> The console must be replayed as the first thing in
> panic_print_sys_info(). Otherwise, the original messages
> are replaced by the other dumps. Especially ftrace_dump()
> might be pretty long.
> 
> Also the names of the function and the parameter are misleading.
> All messages are already flushed when this is called.
> 
> >  }
> >  
> >  /**
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 17102fd4c136..da60a185dbbb 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2549,6 +2549,14 @@ void console_flush_on_panic(void)
> >  	 */
> >  	console_trylock();
> >  	console_may_schedule = 0;
> > +	if (flush_mode == CONSOLE_FLUSH_ALL) {
> > +		/*
> > +		 * Can be done under logbuf lock, but it's unlikely that
> > +		 * we will have any race conditions here.
> > +		 */
> > +		console_seq = log_first_seq;
> > +		console_idx = log_first_idx;

This is very similar to my V1 patch :), excepted I used a bool
as the parameter.

> 
> I agree that it is easier. The cost is that the same messages are
> printed again without any explanation.
> 
> I still think that it would be convenient to write a header line.
> It would help to understand the log for any, even 3rd-party, reader.
> Also it would help to find the beginning in a very long log.

My thought is, the replay is only a debug option and disabled by default,
so when user specifically enable the bit of PANIC_PRINT_ALL_PRINTK_MSG,
the whole replay of printk msg should be expected.

Thanks,
Feng

> 
> If the complexity of console_unlock() is the concern, we could
> refactor the code, e.g. put this "reset log" code into a separate
> function.
> 
> Best Regards,
> Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-17 15:18             ` Feng Tang
@ 2019-04-18  0:00               ` Sergey Senozhatsky
  2019-04-18  7:45                 ` Petr Mladek
  0 siblings, 1 reply; 14+ messages in thread
From: Sergey Senozhatsky @ 2019-04-18  0:00 UTC (permalink / raw)
  To: Petr Mladek, Feng Tang
  Cc: Sergey Senozhatsky, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On (04/17/19 23:18), Feng Tang wrote:
> > > +++ b/kernel/printk/printk.c
> > > @@ -2549,6 +2549,14 @@ void console_flush_on_panic(void)
> > >  	 */
> > >  	console_trylock();
> > >  	console_may_schedule = 0;
> > > +	if (flush_mode == CONSOLE_FLUSH_ALL) {
> > > +		/*
> > > +		 * Can be done under logbuf lock, but it's unlikely that
> > > +		 * we will have any race conditions here.
> > > +		 */
> > > +		console_seq = log_first_seq;
> > > +		console_idx = log_first_idx;
> 
> This is very similar to my V1 patch :), excepted I used a bool
> as the parameter.

Yes it is :)

I will reply to Petr's and Feng's email.

> > I agree that it is easier. The cost is that the same messages are
> > printed again without any explanation.
> > 
> > I still think that it would be convenient to write a header line.
> > It would help to understand the log for any, even 3rd-party, reader.
> > Also it would help to find the beginning in a very long log.
>
> My thought is, the replay is only a debug option and disabled by default,
> so when user specifically enable the bit of PANIC_PRINT_ALL_PRINTK_MSG,
> the whole replay of printk msg should be expected.

I think that PANIC_PRINT_ALL_PRINTK_MSG is a debugging option; a quite
specific one. So people who ask the kernel to PANIC_PRINT_ALL_PRINTK_MSG
they know what they are doing, and we probably will not cofuse anyone.
After all, we don't print any headers when we ftrace_dump() or imitate
sysrq via sysrq_timer_list_show(), or for any other panic_print_sys_info()
printouts. So it's OK to just do the simple thing for
PANIC_PRINT_ALL_PRINTK_MSG.

	-ss

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-18  0:00               ` Sergey Senozhatsky
@ 2019-04-18  7:45                 ` Petr Mladek
  2019-04-18  9:00                   ` Feng Tang
  2019-04-18 10:50                   ` Sergey Senozhatsky
  0 siblings, 2 replies; 14+ messages in thread
From: Petr Mladek @ 2019-04-18  7:45 UTC (permalink / raw)
  To: Sergey Senozhatsky
  Cc: Feng Tang, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Thu 2019-04-18 09:00:14, Sergey Senozhatsky wrote:
> I think that PANIC_PRINT_ALL_PRINTK_MSG is a debugging option; a quite
> specific one. So people who ask the kernel to PANIC_PRINT_ALL_PRINTK_MSG
> they know what they are doing, and we probably will not cofuse anyone.
> After all, we don't print any headers when we ftrace_dump() or imitate
> sysrq via sysrq_timer_list_show(), or for any other panic_print_sys_info()
> printouts. So it's OK to just do the simple thing for
> PANIC_PRINT_ALL_PRINTK_MSG.

The following functions are currently called from panic_print_sys_info():

+ show_state():
	printk(KERN_INFO
		"  task                        PC stack   pid father\n");
+ show_mem():
	printk("Mem-Info:\n");

+ sysrq_timer_list_show()
	no global header; but each section can be easily distinguished
	because there are several static strings that explains the
	content

+ debug_show_all_locks()
	pr_warn("\nShowing all locks held in the system:\n");

+ ftrace_dump():
	printk(KERN_TRACE "Dumping ftrace buffer:\n");


The person that enabled the debugging option might know what it did
when it process the log the very same day. It might be less clear
for others reading the log.

Also it still might be convenient to find the beginning easily.
Or it might help to orientate when several test runs
(over night test) are squashed in a single file. I see
such logs pretty often.

That said, I do not resist on it.

Best Regards,
Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-18  7:45                 ` Petr Mladek
@ 2019-04-18  9:00                   ` Feng Tang
  2019-04-18 11:01                     ` Petr Mladek
  2019-04-18 10:50                   ` Sergey Senozhatsky
  1 sibling, 1 reply; 14+ messages in thread
From: Feng Tang @ 2019-04-18  9:00 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

Hi Petr,

On Thu, Apr 18, 2019 at 09:45:52AM +0200, Petr Mladek wrote:
> On Thu 2019-04-18 09:00:14, Sergey Senozhatsky wrote:
> > I think that PANIC_PRINT_ALL_PRINTK_MSG is a debugging option; a quite
> > specific one. So people who ask the kernel to PANIC_PRINT_ALL_PRINTK_MSG
> > they know what they are doing, and we probably will not cofuse anyone.
> > After all, we don't print any headers when we ftrace_dump() or imitate
> > sysrq via sysrq_timer_list_show(), or for any other panic_print_sys_info()
> > printouts. So it's OK to just do the simple thing for
> > PANIC_PRINT_ALL_PRINTK_MSG.
> 
> The following functions are currently called from panic_print_sys_info():
> 
> + show_state():
> 	printk(KERN_INFO
> 		"  task                        PC stack   pid father\n");
> + show_mem():
> 	printk("Mem-Info:\n");
> 
> + sysrq_timer_list_show()
> 	no global header; but each section can be easily distinguished
> 	because there are several static strings that explains the
> 	content
> 
> + debug_show_all_locks()
> 	pr_warn("\nShowing all locks held in the system:\n");
> 
> + ftrace_dump():
> 	printk(KERN_TRACE "Dumping ftrace buffer:\n");
> 
> 
> The person that enabled the debugging option might know what it did
> when it process the log the very same day. It might be less clear
> for others reading the log.
> 
> Also it still might be convenient to find the beginning easily.
> Or it might help to orientate when several test runs
> (over night test) are squashed in a single file. I see
> such logs pretty often.

Thanks for checking all the info. For the note, how about adding
something like this inside panic_print_sys_info()?

	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG) {
		printk("\nprintk: will replay all the messages in buffer:\n");
		console_flush_on_panic(CONSOLE_FLUSH_ALL);
	}

If you are all fine with it, I'll go post a v3, thanks,

- Feng

> 
> That said, I do not resist on it.
> 
> Best Regards,
> Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-18  7:45                 ` Petr Mladek
  2019-04-18  9:00                   ` Feng Tang
@ 2019-04-18 10:50                   ` Sergey Senozhatsky
  1 sibling, 0 replies; 14+ messages in thread
From: Sergey Senozhatsky @ 2019-04-18 10:50 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Feng Tang, Andrew Morton, Steven Rostedt,
	linux-kernel, Kees Cook, Borislav Petkov, ying.huang

On (04/18/19 09:45), Petr Mladek wrote:
> The following functions are currently called from panic_print_sys_info():
> 
> + show_state():
> 	printk(KERN_INFO
> 		"  task                        PC stack   pid father\n");
> + show_mem():
> 	printk("Mem-Info:\n");
> 
> + sysrq_timer_list_show()
> 	no global header; but each section can be easily distinguished
> 	because there are several static strings that explains the
> 	content
> 
> + debug_show_all_locks()
> 	pr_warn("\nShowing all locks held in the system:\n");
> 
> + ftrace_dump():
> 	printk(KERN_TRACE "Dumping ftrace buffer:\n");

Oh, thanks.

> The person that enabled the debugging option might know what it did
> when it process the log the very same day. It might be less clear
> for others reading the log.
> 
> Also it still might be convenient to find the beginning easily.
> Or it might help to orientate when several test runs
> (over night test) are squashed in a single file. I see
> such logs pretty often.

OK, well since we are talking here about serial log, then we probably
can just add printk("dump logbuf:\n"). It will appear before the
FLUSH_ALL output. Or we can just tweak panic code a bit - anything
panic_print_sys_info() prints can be "after" end of panic marker.

Basically, just move pr_emerg("---[ end Kernel panic...") a bit. I don't
quite understand why is it at the bottom - we don't always print end of
panic maker, e.g. when panic_timeout != 0. Not sure if this was
intentional.

---
diff --git a/kernel/panic.c b/kernel/panic.c
index 50eacfc9bc7e..1940a142c26e 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -282,6 +282,7 @@ void panic(const char *fmt, ...)
 	 */
 	debug_locks_off();
 	console_flush_on_panic(CONSOLE_FLUSH_PENDING);
+	pr_emerg("---[ end Kernel panic - not syncing: %s ]---\n", buf);
 
 	panic_print_sys_info();
 
@@ -331,7 +332,6 @@ void panic(const char *fmt, ...)
 		disabled_wait(caller);
 	}
 #endif
-	pr_emerg("---[ end Kernel panic - not syncing: %s ]---\n", buf);
 
 	/* Do not scroll important messages printed above */
 	suppress_printk = 1;
---

	-ss

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-18  9:00                   ` Feng Tang
@ 2019-04-18 11:01                     ` Petr Mladek
  2019-04-19  2:08                       ` Feng Tang
  0 siblings, 1 reply; 14+ messages in thread
From: Petr Mladek @ 2019-04-18 11:01 UTC (permalink / raw)
  To: Feng Tang
  Cc: Sergey Senozhatsky, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Thu 2019-04-18 17:00:44, Feng Tang wrote:
> Hi Petr,
> 
> On Thu, Apr 18, 2019 at 09:45:52AM +0200, Petr Mladek wrote:
> > On Thu 2019-04-18 09:00:14, Sergey Senozhatsky wrote:
> > > I think that PANIC_PRINT_ALL_PRINTK_MSG is a debugging option; a quite
> > > specific one. So people who ask the kernel to PANIC_PRINT_ALL_PRINTK_MSG
> > > they know what they are doing, and we probably will not cofuse anyone.
> > > After all, we don't print any headers when we ftrace_dump() or imitate
> > > sysrq via sysrq_timer_list_show(), or for any other panic_print_sys_info()
> > > printouts. So it's OK to just do the simple thing for
> > > PANIC_PRINT_ALL_PRINTK_MSG.
> > 
> > The following functions are currently called from panic_print_sys_info():
> > 
> > + show_state():
> > 	printk(KERN_INFO
> > 		"  task                        PC stack   pid father\n");
> > + show_mem():
> > 	printk("Mem-Info:\n");
> > 
> > + sysrq_timer_list_show()
> > 	no global header; but each section can be easily distinguished
> > 	because there are several static strings that explains the
> > 	content
> > 
> > + debug_show_all_locks()
> > 	pr_warn("\nShowing all locks held in the system:\n");
> > 
> > + ftrace_dump():
> > 	printk(KERN_TRACE "Dumping ftrace buffer:\n");
> > 
> > 
> > The person that enabled the debugging option might know what it did
> > when it process the log the very same day. It might be less clear
> > for others reading the log.
> > 
> > Also it still might be convenient to find the beginning easily.
> > Or it might help to orientate when several test runs
> > (over night test) are squashed in a single file. I see
> > such logs pretty often.
> 
> Thanks for checking all the info. For the note, how about adding
> something like this inside panic_print_sys_info()?
> 
> 	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG) {
> 		printk("\nprintk: will replay all the messages in buffer:\n");
> 		console_flush_on_panic(CONSOLE_FLUSH_ALL);
> 	}

This will store the message at the end of the buffer. It will repeat
the message once again when replaying the log. I personally think
that it is worse than printing nothing.


> If you are all fine with it, I'll go post a v3, thanks,

I suggest to wait few days. We might get opinion from someone
else...

Then sent whatever approach makes most sense to you. In fact, you
are the 3rd person in this triangle. I believe that we will
respect it. Last many mails are just a bike shedding.

Just one thing. Please, use "replay" in the function or parameter
name. The effect of console_flush_on_panic(CONSOLE_FLUSH_ALL)
is really hard to guess from the name.

Best Regards,
Petr

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

* Re: [PATCH v2] panic: add an option to replay all the printk message in buffer
  2019-04-18 11:01                     ` Petr Mladek
@ 2019-04-19  2:08                       ` Feng Tang
  0 siblings, 0 replies; 14+ messages in thread
From: Feng Tang @ 2019-04-19  2:08 UTC (permalink / raw)
  To: Petr Mladek
  Cc: Sergey Senozhatsky, Andrew Morton, Steven Rostedt, linux-kernel,
	Kees Cook, Borislav Petkov, ying.huang

On Thu, Apr 18, 2019 at 01:01:52PM +0200, Petr Mladek wrote:
> On Thu 2019-04-18 17:00:44, Feng Tang wrote:
> > Hi Petr,
> > 
> > On Thu, Apr 18, 2019 at 09:45:52AM +0200, Petr Mladek wrote:
> > > On Thu 2019-04-18 09:00:14, Sergey Senozhatsky wrote:
> > > > I think that PANIC_PRINT_ALL_PRINTK_MSG is a debugging option; a quite
> > > > specific one. So people who ask the kernel to PANIC_PRINT_ALL_PRINTK_MSG
> > > > they know what they are doing, and we probably will not cofuse anyone.
> > > > After all, we don't print any headers when we ftrace_dump() or imitate
> > > > sysrq via sysrq_timer_list_show(), or for any other panic_print_sys_info()
> > > > printouts. So it's OK to just do the simple thing for
> > > > PANIC_PRINT_ALL_PRINTK_MSG.
> > > 
> > > The following functions are currently called from panic_print_sys_info():
> > > 
> > > + show_state():
> > > 	printk(KERN_INFO
> > > 		"  task                        PC stack   pid father\n");
> > > + show_mem():
> > > 	printk("Mem-Info:\n");
> > > 
> > > + sysrq_timer_list_show()
> > > 	no global header; but each section can be easily distinguished
> > > 	because there are several static strings that explains the
> > > 	content
> > > 
> > > + debug_show_all_locks()
> > > 	pr_warn("\nShowing all locks held in the system:\n");
> > > 
> > > + ftrace_dump():
> > > 	printk(KERN_TRACE "Dumping ftrace buffer:\n");
> > > 
> > > 
> > > The person that enabled the debugging option might know what it did
> > > when it process the log the very same day. It might be less clear
> > > for others reading the log.
> > > 
> > > Also it still might be convenient to find the beginning easily.
> > > Or it might help to orientate when several test runs
> > > (over night test) are squashed in a single file. I see
> > > such logs pretty often.
> > 
> > Thanks for checking all the info. For the note, how about adding
> > something like this inside panic_print_sys_info()?
> > 
> > 	if (panic_print & PANIC_PRINT_ALL_PRINTK_MSG) {
> > 		printk("\nprintk: will replay all the messages in buffer:\n");
> > 		console_flush_on_panic(CONSOLE_FLUSH_ALL);
> > 	}
> 
> This will store the message at the end of the buffer. It will repeat
> the message once again when replaying the log. I personally think
> that it is worse than printing nothing.

Got it :) 

> 
> 
> > If you are all fine with it, I'll go post a v3, thanks,
> 
> I suggest to wait few days. We might get opinion from someone
> else...
> 
> Then sent whatever approach makes most sense to you. In fact, you
> are the 3rd person in this triangle. I believe that we will
> respect it. Last many mails are just a bike shedding.
> 
> Just one thing. Please, use "replay" in the function or parameter
> name. The effect of console_flush_on_panic(CONSOLE_FLUSH_ALL)
> is really hard to guess from the name.

Ok. thanks

- Feng

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

end of thread, other threads:[~2019-04-19  2:05 UTC | newest]

Thread overview: 14+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-04-10 15:37 [PATCH v2] panic: add an option to replay all the printk message in buffer Feng Tang
2019-04-17  4:19 ` Andrew Morton
2019-04-17  6:48   ` Feng Tang
2019-04-17  9:18     ` Petr Mladek
2019-04-17  9:46       ` Sergey Senozhatsky
2019-04-17 10:50         ` Sergey Senozhatsky
2019-04-17 12:24           ` Petr Mladek
2019-04-17 15:18             ` Feng Tang
2019-04-18  0:00               ` Sergey Senozhatsky
2019-04-18  7:45                 ` Petr Mladek
2019-04-18  9:00                   ` Feng Tang
2019-04-18 11:01                     ` Petr Mladek
2019-04-19  2:08                       ` Feng Tang
2019-04-18 10:50                   ` Sergey Senozhatsky

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).