[PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Hans de Goede]

Commit 375899cddcbb ("printk: make sure to print log on console."), moved
the checking of the loglevel of messages from flush time to the actual
log time.

This introduces one problem, some early boot messages are printed before
parse_early_param() gets called and thus before kernel commandline options
such as quiet, loglevel and ignore_loglevel are parsed.

This causes e.g. the following messages to get printed on x86 systems,
despite the presence of the "quiet" option:

[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable
...
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000874ffffff] usable

This commit fixes this by setting a new LOG_CHK_LEVEL on early boot
messages and doing the loglevel check for these while flushing as before.

Cc: Petr Mladek <pmladek@suse.com>
Cc: Maninder Singh <maninder1.s@samsung.com>
Fixes: 375899cddcbb ("printk: make sure to print log on console.")
Signed-off-by: Hans de Goede <hdegoede@redhat.com>
---
 kernel/printk/printk.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd6f8ed28e01..c5ffd46239a0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -355,6 +355,7 @@ enum log_flags {
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_PREFIX	= 4,	/* text started with a prefix */
 	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
+	LOG_CHK_LEVEL	= 16,	/* check log level during flush */
 };
 
 struct printk_log {
@@ -1881,7 +1882,10 @@ int vprintk_store(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	if (suppress_message_printing(level))
+	/* During early boot loglevel is not setup yet, check it later */
+	if (early_boot_irqs_disabled)
+		lflags |= LOG_CHK_LEVEL;
+	else if (suppress_message_printing(level))
 		lflags |= LOG_NOCONS;
 
 	return log_output(facility, level, lflags,
@@ -2368,7 +2372,9 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
+		if ((msg->flags & LOG_NOCONS) ||
+		    ((msg->flags & LOG_CHK_LEVEL) &&
+				suppress_message_printing(msg->level))) {
 			/*
 			 * Skip record if !ignore_loglevel, and
 			 * record has level above the console loglevel.
-- 
2.19.0.rc0

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

Hi,

On (09/04/18 20:01), Hans de Goede wrote:
> Commit 375899cddcbb ("printk: make sure to print log on console."), moved
> the checking of the loglevel of messages from flush time to the actual
> log time.
> 
> This introduces one problem, some early boot messages are printed before
> parse_early_param() gets called and thus before kernel commandline options
> such as quiet, loglevel and ignore_loglevel are parsed.

Do you use earlycon?

> This causes e.g. the following messages to get printed on x86 systems,
> despite the presence of the "quiet" option:
> 
> [    0.000000] BIOS-provided physical RAM map:
> [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable
> ...
> [    0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000874ffffff] usable
> 
> This commit fixes this by setting a new LOG_CHK_LEVEL on early boot
> messages and doing the loglevel check for these while flushing as before.
> 

Hmm, OK, chances are we need to re-think 375899cddcbb. It might be
the case that we sort of broke CON_PRINTBUFFER handling.

	console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH
	register CON_PRINTBUFFER console
		-> no debug output

So I think that when console_unlock() re-flushes already seen logbuf
messages to a newly registered exclusive [CON_PRINTBUFFER] console we
probably need to look at the current console_loglevel in console_unlock()
loop.

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Hans de Goede]

Hi,

On 05-09-18 04:35, Sergey Senozhatsky wrote:
> Hi,
> 
> On (09/04/18 20:01), Hans de Goede wrote:
>> Commit 375899cddcbb ("printk: make sure to print log on console."), moved
>> the checking of the loglevel of messages from flush time to the actual
>> log time.
>>
>> This introduces one problem, some early boot messages are printed before
>> parse_early_param() gets called and thus before kernel commandline options
>> such as quiet, loglevel and ignore_loglevel are parsed.
> 
> Do you use earlycon?

No, I'm seeing this with the regular/normal console stuff.

>> This causes e.g. the following messages to get printed on x86 systems,
>> despite the presence of the "quiet" option:
>>
>> [    0.000000] BIOS-provided physical RAM map:
>> [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x0000000000057fff] usable
>> ...
>> [    0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000874ffffff] usable
>>
>> This commit fixes this by setting a new LOG_CHK_LEVEL on early boot
>> messages and doing the loglevel check for these while flushing as before.
>>
> 
> Hmm, OK, chances are we need to re-think 375899cddcbb. It might be
> the case that we sort of broke CON_PRINTBUFFER handling.
> 
> 	console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH
> 	register CON_PRINTBUFFER console
> 		-> no debug output
> 
> So I think that when console_unlock() re-flushes already seen logbuf
> messages to a newly registered exclusive [CON_PRINTBUFFER] console we
> probably need to look at the current console_loglevel in console_unlock()
> loop.

So if it breaks quiet and the above use-case maybe we should revert
375899cddcbb for now?

Regards,

Hans

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/05/18 06:53), Hans de Goede wrote:
> > 
> > Do you use earlycon?
> 
> No, I'm seeing this with the regular/normal console stuff.

OK, thanks for the report!
So I think that your case is CON_PRINTBUFFER related as well. We have
a number of logbuf messages before we parse quiet and console_loglevel.
Those messages pass the suppress_message() test. Then when we finally
register a CON_PRINTBUFFER console we update console_loglevel and flush
all logbuf messages, but console_loglevel does not matter anymore.

> > > This commit fixes this by setting a new LOG_CHK_LEVEL on early boot
> > > messages and doing the loglevel check for these while flushing as before.
> > > 
> > 
> > Hmm, OK, chances are we need to re-think 375899cddcbb. It might be
> > the case that we sort of broke CON_PRINTBUFFER handling.
> > 
> > 	console_loglevel = CONSOLE_LOGLEVEL_MOTORMOUTH
> > 	register CON_PRINTBUFFER console
> > 		-> no debug output
> > 
> > So I think that when console_unlock() re-flushes already seen logbuf
> > messages to a newly registered exclusive [CON_PRINTBUFFER] console we
> > probably need to look at the current console_loglevel in console_unlock()
> > loop.
> 
> So if it breaks quiet and the above use-case maybe we should revert
> 375899cddcbb for now?

Maybe all we need to do is to re-introduce suppress_message() check to
console_unlock() when we have exclusive console set (IOW, when we re-flush
logbuf messages to a CON_PRINTBUFFER console).

Just a demonstration of the idea. It does not look very good, tho.
I'd rather have just one suppress_message_printing() in printk code.

// This is not a proposed patch, hence the 80-cols violation.

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c036f128cdc3..231ac18423e1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2416,7 +2416,7 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
+		if (msg->flags & LOG_NOCONS || (exclusive_console && suppress_message_printing(msg->level))) {
 			/*
 			 * Skip record if !ignore_loglevel, and
 			 * record has level above the console loglevel.

---

We are still early in 4.19 -rcs, let's wait a bit and hear from Steven
and Petr, they have bright ideas oftentimes.

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/05/18 14:36), Sergey Senozhatsky wrote:
> 
> OK, thanks for the report!
> So I think that your case is CON_PRINTBUFFER related as well. We have
> a number of logbuf messages before we parse quiet and console_loglevel.
> Those messages pass the suppress_message() test. Then when we finally
> register a CON_PRINTBUFFER console we update console_loglevel and flush
> all logbuf messages, but console_loglevel does not matter anymore.
> 

Hmm, earlycon can also be affected, probably. But I'm not sure if people
do "earlycon" and "quiet" at the same time. May be, who knows...

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/05/18 14:36), Sergey Senozhatsky wrote:
> 
> Just a demonstration of the idea. It does not look very good, tho.
> I'd rather have just one suppress_message_printing() in printk code.
> 
> // This is not a proposed patch, hence the 80-cols violation.
> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c036f128cdc3..231ac18423e1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2416,7 +2416,7 @@ void console_unlock(void)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> -		if (msg->flags & LOG_NOCONS) {
> +		if (msg->flags & LOG_NOCONS || (exclusive_console && suppress_message_printing(msg->level))) {
>  			/*
>  			 * Skip record if !ignore_loglevel, and
>  			 * record has level above the console loglevel.

D'oh... Sorry about that, but, believe it or not, this is completely
not what I had in my mind. What I had, was something like this:

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c036f128cdc3..dadb8c11b0d6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2416,6 +2416,11 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
+
+		if (exclusive_console &&
+				!suppress_message_printing(msg->level))
+			msg->flags &= ~LOG_NOCONS;
+
 		if (msg->flags & LOG_NOCONS) {
 			/*
 			 * Skip record if !ignore_loglevel, and

---

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Wed 2018-09-05 17:33:26, Sergey Senozhatsky wrote:
> On (09/05/18 14:36), Sergey Senozhatsky wrote:
> > 
> > Just a demonstration of the idea. It does not look very good, tho.
> > I'd rather have just one suppress_message_printing() in printk code.
> > 
> > // This is not a proposed patch, hence the 80-cols violation.
> > 
> > ---
> > 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index c036f128cdc3..231ac18423e1 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2416,7 +2416,7 @@ void console_unlock(void)
> >  			break;
> >  
> >  		msg = log_from_idx(console_idx);
> > -		if (msg->flags & LOG_NOCONS) {
> > +		if (msg->flags & LOG_NOCONS || (exclusive_console && suppress_message_printing(msg->level))) {
> >  			/*
> >  			 * Skip record if !ignore_loglevel, and
> >  			 * record has level above the console loglevel.
> 
> D'oh... Sorry about that, but, believe it or not, this is completely
> not what I had in my mind. What I had, was something like this:
> 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c036f128cdc3..dadb8c11b0d6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2416,6 +2416,11 @@ void console_unlock(void)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> +
> +		if (exclusive_console &&
> +				!suppress_message_printing(msg->level))
> +			msg->flags &= ~LOG_NOCONS;

Hmm, this does not help with consoles without CON_PRINTBUFFER
flag. Note that the first registered console prints all messages
even without this flag.

Also there is "debug" earlyparam where we need the opposite. I mean
that we want to show messages that were suppressed by default.

I played with another solution, see the patch below. It defines
which messages have a valid NOCONS flag according to the msg_seq
number. IMHO, it is a bit more straightforward but it is still
a hack. I am not super happy about it.


Hmm, I seriously think about reverting the commit 375899cddcbb
("printk: make sure to print log on console.") and solving it
another way.

For example, the commit was primary about locations that
wanted to make some messages always visible or always
suppressed. We could create LOG_FORCE_NOCONS and
LOG_FORCE_CONS for these two special cases.



Possible solution:


From c0fb2d83ca3ca0bab5e1de5a6e29a1b96756a530 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Wed, 5 Sep 2018 12:57:18 +0200
Subject: [RFC PATCH] printk: Possible solution for loglevel manipulation by
 earlyparams

Early params that manipulate console_loglevel should invalidate
LOG_NOCONS flag for all the existing messages.
---
 include/linux/console.h |  2 ++
 init/main.c             |  6 +++---
 kernel/printk/printk.c  | 27 +++++++++++++++++++++++----
 3 files changed, 28 insertions(+), 7 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index ec9bdb3d7bab..3d3f7ab8f82e 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -195,6 +195,8 @@ extern bool console_suspend_enabled;
 extern void suspend_console(void);
 extern void resume_console(void);
 
+extern void console_set_default_loglevel(int loglevel);
+
 int mda_console_init(void);
 void prom_con_init(void);
 
diff --git a/init/main.c b/init/main.c
index 18f8f0140fa0..936466209494 100644
--- a/init/main.c
+++ b/init/main.c
@@ -213,13 +213,13 @@ EXPORT_SYMBOL(loops_per_jiffy);
 
 static int __init debug_kernel(char *str)
 {
-	console_loglevel = CONSOLE_LOGLEVEL_DEBUG;
+	console_set_default_loglevel(CONSOLE_LOGLEVEL_DEBUG);
 	return 0;
 }
 
 static int __init quiet_kernel(char *str)
 {
-	console_loglevel = CONSOLE_LOGLEVEL_QUIET;
+	console_set_default_loglevel(CONSOLE_LOGLEVEL_QUIET);
 	return 0;
 }
 
@@ -236,7 +236,7 @@ static int __init loglevel(char *str)
 	 * are quite hard to debug
 	 */
 	if (get_option(&str, &newlevel)) {
-		console_loglevel = newlevel;
+		console_set_default_loglevel(newlevel);
 		return 0;
 	}
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 924e37fb1620..b5a0074302e9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -430,6 +430,9 @@ static u32 console_idx;
 static u64 clear_seq;
 static u32 clear_idx;
 
+/* Invalidate nocons flag setting before early param are proceed */
+static u64 console_valid_nocons_seq;
+
 #define PREFIX_MAX		32
 #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
 
@@ -1148,11 +1151,19 @@ module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
 MODULE_PARM_DESC(ignore_loglevel,
 		 "ignore loglevel setting (prints all kernel messages to the console)");
 
-static bool suppress_message_printing(int level)
+static bool nocons_loglevel(int level)
 {
 	return (level >= console_loglevel && !ignore_loglevel);
 }
 
+static bool nocons_msg(struct printk_log *msg)
+{
+	if (console_seq >= console_valid_nocons_seq)
+		return msg->flags & LOG_NOCONS;
+
+	return nocons_loglevel(msg->level);
+}
+
 #ifdef CONFIG_BOOT_PRINTK_DELAY
 
 static int boot_delay; /* msecs delay after each printk during bootup */
@@ -1182,7 +1193,7 @@ static void boot_delay_msec(int level)
 	unsigned long timeout;
 
 	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
-		|| suppress_message_printing(level)) {
+		|| nocons_loglevel(level)) {
 		return;
 	}
 
@@ -1882,7 +1893,7 @@ int vprintk_store(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	if (suppress_message_printing(level))
+	if (nocons_loglevel(level))
 		lflags |= LOG_NOCONS;
 
 	return log_output(facility, level, lflags,
@@ -2031,6 +2042,7 @@ static void console_lock_spinning_enable(void) { }
 static int console_lock_spinning_disable_and_check(void) { return 0; }
 static void call_console_drivers(const char *ext_text, size_t ext_len,
 				 const char *text, size_t len) {}
+static bool nocons_msg(struct printk_log *msg) { return false; }
 static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 
@@ -2197,6 +2209,13 @@ void resume_console(void)
 	console_unlock();
 }
 
+void console_set_default_loglevel(int loglevel)
+{
+	console_loglevel = loglevel;
+	/* Invalidate nocons flag for earlier messages. */
+	console_valid_nocons_seq = log_next_seq;
+}
+
 /**
  * console_cpu_notify - print deferred console messages after CPU hotplug
  * @cpu: unused
@@ -2369,7 +2388,7 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
+		if (nocons_msg(msg)) {
 			/*
 			 * Skip record if !ignore_loglevel, and
 			 * record has level above the console loglevel.
-- 
2.13.7

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Hans de Goede]

HI,

On 05-09-18 13:02, Petr Mladek wrote:
> On Wed 2018-09-05 17:33:26, Sergey Senozhatsky wrote:
>> On (09/05/18 14:36), Sergey Senozhatsky wrote:
>>>
>>> Just a demonstration of the idea. It does not look very good, tho.
>>> I'd rather have just one suppress_message_printing() in printk code.
>>>
>>> // This is not a proposed patch, hence the 80-cols violation.
>>>
>>> ---
>>>
>>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>>> index c036f128cdc3..231ac18423e1 100644
>>> --- a/kernel/printk/printk.c
>>> +++ b/kernel/printk/printk.c
>>> @@ -2416,7 +2416,7 @@ void console_unlock(void)
>>>   			break;
>>>   
>>>   		msg = log_from_idx(console_idx);
>>> -		if (msg->flags & LOG_NOCONS) {
>>> +		if (msg->flags & LOG_NOCONS || (exclusive_console && suppress_message_printing(msg->level))) {
>>>   			/*
>>>   			 * Skip record if !ignore_loglevel, and
>>>   			 * record has level above the console loglevel.
>>
>> D'oh... Sorry about that, but, believe it or not, this is completely
>> not what I had in my mind. What I had, was something like this:
>>
>> ---
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index c036f128cdc3..dadb8c11b0d6 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -2416,6 +2416,11 @@ void console_unlock(void)
>>   			break;
>>   
>>   		msg = log_from_idx(console_idx);
>> +
>> +		if (exclusive_console &&
>> +				!suppress_message_printing(msg->level))
>> +			msg->flags &= ~LOG_NOCONS;
> 
> Hmm, this does not help with consoles without CON_PRINTBUFFER
> flag. Note that the first registered console prints all messages
> even without this flag.
> 
> Also there is "debug" earlyparam where we need the opposite. I mean
> that we want to show messages that were suppressed by default.
> 
> I played with another solution, see the patch below. It defines
> which messages have a valid NOCONS flag according to the msg_seq
> number. IMHO, it is a bit more straightforward but it is still
> a hack. I am not super happy about it.
> 
> 
> Hmm, I seriously think about reverting the commit 375899cddcbb
> ("printk: make sure to print log on console.") and solving it
> another way.
> 
> For example, the commit was primary about locations that
> wanted to make some messages always visible or always
> suppressed. We could create LOG_FORCE_NOCONS and
> LOG_FORCE_CONS for these two special cases.
> 
> 
> 
> Possible solution:

So do you want me to give this solution a try or was this mainly for
discussion purposes?   If you've a fix which you think you are
happy with and plan to merge I would be happy to try it.

Regards,

Hans



> 
> 
>  From c0fb2d83ca3ca0bab5e1de5a6e29a1b96756a530 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@suse.com>
> Date: Wed, 5 Sep 2018 12:57:18 +0200
> Subject: [RFC PATCH] printk: Possible solution for loglevel manipulation by
>   earlyparams
> 
> Early params that manipulate console_loglevel should invalidate
> LOG_NOCONS flag for all the existing messages.
> ---
>   include/linux/console.h |  2 ++
>   init/main.c             |  6 +++---
>   kernel/printk/printk.c  | 27 +++++++++++++++++++++++----
>   3 files changed, 28 insertions(+), 7 deletions(-)
> 
> diff --git a/include/linux/console.h b/include/linux/console.h
> index ec9bdb3d7bab..3d3f7ab8f82e 100644
> --- a/include/linux/console.h
> +++ b/include/linux/console.h
> @@ -195,6 +195,8 @@ extern bool console_suspend_enabled;
>   extern void suspend_console(void);
>   extern void resume_console(void);
>   
> +extern void console_set_default_loglevel(int loglevel);
> +
>   int mda_console_init(void);
>   void prom_con_init(void);
>   
> diff --git a/init/main.c b/init/main.c
> index 18f8f0140fa0..936466209494 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -213,13 +213,13 @@ EXPORT_SYMBOL(loops_per_jiffy);
>   
>   static int __init debug_kernel(char *str)
>   {
> -	console_loglevel = CONSOLE_LOGLEVEL_DEBUG;
> +	console_set_default_loglevel(CONSOLE_LOGLEVEL_DEBUG);
>   	return 0;
>   }
>   
>   static int __init quiet_kernel(char *str)
>   {
> -	console_loglevel = CONSOLE_LOGLEVEL_QUIET;
> +	console_set_default_loglevel(CONSOLE_LOGLEVEL_QUIET);
>   	return 0;
>   }
>   
> @@ -236,7 +236,7 @@ static int __init loglevel(char *str)
>   	 * are quite hard to debug
>   	 */
>   	if (get_option(&str, &newlevel)) {
> -		console_loglevel = newlevel;
> +		console_set_default_loglevel(newlevel);
>   		return 0;
>   	}
>   
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 924e37fb1620..b5a0074302e9 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -430,6 +430,9 @@ static u32 console_idx;
>   static u64 clear_seq;
>   static u32 clear_idx;
>   
> +/* Invalidate nocons flag setting before early param are proceed */
> +static u64 console_valid_nocons_seq;
> +
>   #define PREFIX_MAX		32
>   #define LOG_LINE_MAX		(1024 - PREFIX_MAX)
>   
> @@ -1148,11 +1151,19 @@ module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
>   MODULE_PARM_DESC(ignore_loglevel,
>   		 "ignore loglevel setting (prints all kernel messages to the console)");
>   
> -static bool suppress_message_printing(int level)
> +static bool nocons_loglevel(int level)
>   {
>   	return (level >= console_loglevel && !ignore_loglevel);
>   }
>   
> +static bool nocons_msg(struct printk_log *msg)
> +{
> +	if (console_seq >= console_valid_nocons_seq)
> +		return msg->flags & LOG_NOCONS;
> +
> +	return nocons_loglevel(msg->level);
> +}
> +
>   #ifdef CONFIG_BOOT_PRINTK_DELAY
>   
>   static int boot_delay; /* msecs delay after each printk during bootup */
> @@ -1182,7 +1193,7 @@ static void boot_delay_msec(int level)
>   	unsigned long timeout;
>   
>   	if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
> -		|| suppress_message_printing(level)) {
> +		|| nocons_loglevel(level)) {
>   		return;
>   	}
>   
> @@ -1882,7 +1893,7 @@ int vprintk_store(int facility, int level,
>   	if (dict)
>   		lflags |= LOG_PREFIX|LOG_NEWLINE;
>   
> -	if (suppress_message_printing(level))
> +	if (nocons_loglevel(level))
>   		lflags |= LOG_NOCONS;
>   
>   	return log_output(facility, level, lflags,
> @@ -2031,6 +2042,7 @@ static void console_lock_spinning_enable(void) { }
>   static int console_lock_spinning_disable_and_check(void) { return 0; }
>   static void call_console_drivers(const char *ext_text, size_t ext_len,
>   				 const char *text, size_t len) {}
> +static bool nocons_msg(struct printk_log *msg) { return false; }
>   static size_t msg_print_text(const struct printk_log *msg,
>   			     bool syslog, char *buf, size_t size) { return 0; }
>   
> @@ -2197,6 +2209,13 @@ void resume_console(void)
>   	console_unlock();
>   }
>   
> +void console_set_default_loglevel(int loglevel)
> +{
> +	console_loglevel = loglevel;
> +	/* Invalidate nocons flag for earlier messages. */
> +	console_valid_nocons_seq = log_next_seq;
> +}
> +
>   /**
>    * console_cpu_notify - print deferred console messages after CPU hotplug
>    * @cpu: unused
> @@ -2369,7 +2388,7 @@ void console_unlock(void)
>   			break;
>   
>   		msg = log_from_idx(console_idx);
> -		if (msg->flags & LOG_NOCONS) {
> +		if (nocons_msg(msg)) {
>   			/*
>   			 * Skip record if !ignore_loglevel, and
>   			 * record has level above the console loglevel.
> 

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/05/18 13:02), Petr Mladek wrote:
> Note that the first registered console prints all messages
> even without this flag.

Hmm, OK, interesting point.

I assumed that the first console usually has CON_PRINTBUFFER bit set.
Or even a CON_PRINTBUFFER | CON_ANYTIME combo. E.g. 8250. It sort of
makes sense to have CON_PRINTBUFFER for the first console. Any later
consoles [e.g. fbcon, netcon] don't necessarily have CON_PRINTBUFFER.

So by the time we have callable console "quite" param should be already
parsed [except the earlycon case perhaps]:

	kernel_init_freeable
	 do_one_initcall
	  register_console
happens after
	setup_arch
	 parse_early_param
	  quiet_kernel/debug_kernel.

And
	setup_arch
	 parse_early_param
	  quiet_kernel/debug_kernel
happens before
	console_init
	 con_init
	  register_console.

And the first console has CON_PRINTBUFFER bit set. Well, just because
it sounds reasonable. Those were the main assumptions behind my code
snippet. Was any of those assumptions wrong?

> I played with another solution, see the patch below. It defines
> which messages have a valid NOCONS flag according to the msg_seq
> number. IMHO, it is a bit more straightforward but it is still
> a hack. I am not super happy about it.

I just skimmed through it, and probably missed some parts. But I sort
of expected to see some console_valid_nocons_seq manipulations in
register_console(), when we register a new CON_PRINTBUFFER console
on already running system.

> Hmm, I seriously think about reverting the commit 375899cddcbb
> ("printk: make sure to print log on console.") and solving it
> another way.

I can agree, definitely. That's one of the options.

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Thu 2018-09-06 16:29:40, Sergey Senozhatsky wrote:
> On (09/05/18 13:02), Petr Mladek wrote:
> > Note that the first registered console prints all messages
> > even without this flag.
> 
> Hmm, OK, interesting point.
> 
> I assumed that the first console usually has CON_PRINTBUFFER bit set.
> Or even a CON_PRINTBUFFER | CON_ANYTIME combo. E.g. 8250. It sort of
> makes sense to have CON_PRINTBUFFER for the first console. Any later
> consoles [e.g. fbcon, netcon] don't necessarily have CON_PRINTBUFFER.
> 
> And the first console has CON_PRINTBUFFER bit set. Well, just because
> it sounds reasonable. Those were the main assumptions behind my code
> snippet. Was any of those assumptions wrong?

This assumption makes sense. In fact, I was wrong. I thought that
console_seq/console_idx were not updated until the first console
was registered. But it is not the case.

It means that the hack with exclusive_console might be usable.
But I would prefer to do it a cleaner way.


> > I played with another solution, see the patch below. It defines
> > which messages have a valid NOCONS flag according to the msg_seq
> > number. IMHO, it is a bit more straightforward but it is still
> > a hack. I am not super happy about it.
> 
> I just skimmed through it, and probably missed some parts. But I sort
> of expected to see some console_valid_nocons_seq manipulations in
> register_console(), when we register a new CON_PRINTBUFFER console
> on already running system.

I do not see any reason for this. If quiet/debug/loglevel kernel
parameters are proceed before register_console() call then
console_valid_nocons_seq is already set to the right sequence
number. Otherwise console_loglevel should be still the default
value and there is no reason to re-calculate nocons flag.

But it is rather complicated, still hacky, ...


> > Hmm, I seriously think about reverting the commit 375899cddcbb
> > ("printk: make sure to print log on console.") and solving it
> > another way.
> 
> I can agree, definitely. That's one of the options.

I prefer the revert for now.

Best Regards,
Petr

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Wed 2018-09-05 17:20:53, Hans de Goede wrote:
> HI,
> 
> On 05-09-18 13:02, Petr Mladek wrote:
> > On Wed 2018-09-05 17:33:26, Sergey Senozhatsky wrote:
> > > On (09/05/18 14:36), Sergey Senozhatsky wrote:
> > > > 
> > > > Just a demonstration of the idea. It does not look very good, tho.
> > > > I'd rather have just one suppress_message_printing() in printk code.
> > > > 
> > > > // This is not a proposed patch, hence the 80-cols violation.
> > > > 
> > > > ---
> > > > 
> > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > > index c036f128cdc3..231ac18423e1 100644
> > > > --- a/kernel/printk/printk.c
> > > > +++ b/kernel/printk/printk.c
> > > > @@ -2416,7 +2416,7 @@ void console_unlock(void)
> > > >   			break;
> > > >   		msg = log_from_idx(console_idx);
> > > > -		if (msg->flags & LOG_NOCONS) {
> > > > +		if (msg->flags & LOG_NOCONS || (exclusive_console && suppress_message_printing(msg->level))) {
> > > >   			/*
> > > >   			 * Skip record if !ignore_loglevel, and
> > > >   			 * record has level above the console loglevel.
> > > 
> > > D'oh... Sorry about that, but, believe it or not, this is completely
> > > not what I had in my mind. What I had, was something like this:
> > > 
> > > ---
> > > 
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index c036f128cdc3..dadb8c11b0d6 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -2416,6 +2416,11 @@ void console_unlock(void)
> > >   			break;
> > >   		msg = log_from_idx(console_idx);
> > > +
> > > +		if (exclusive_console &&
> > > +				!suppress_message_printing(msg->level))
> > > +			msg->flags &= ~LOG_NOCONS;
> > 
> > Hmm, this does not help with consoles without CON_PRINTBUFFER
> > flag. Note that the first registered console prints all messages
> > even without this flag.
> > 
> > Also there is "debug" earlyparam where we need the opposite. I mean
> > that we want to show messages that were suppressed by default.
> > 
> > I played with another solution, see the patch below. It defines
> > which messages have a valid NOCONS flag according to the msg_seq
> > number. IMHO, it is a bit more straightforward but it is still
> > a hack. I am not super happy about it.
> > 
> > 
> > Hmm, I seriously think about reverting the commit 375899cddcbb
> > ("printk: make sure to print log on console.") and solving it
> > another way.
> > 
> > For example, the commit was primary about locations that
> > wanted to make some messages always visible or always
> > suppressed. We could create LOG_FORCE_NOCONS and
> > LOG_FORCE_CONS for these two special cases.
> > 
> > 
> > 
> > Possible solution:
> 
> So do you want me to give this solution a try or was this mainly for
> discussion purposes?   If you've a fix which you think you are
> happy with and plan to merge I would be happy to try it.

It was rather for discussion purposes. I prefer the revert
for the moment.

If nobody comes with a better idea or is not against, I am going
to send the revert.

Best Regards,
Petr

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 6712 bytes --]

Hi Hans,

I love your patch! Yet something to improve:

[auto build test ERROR on linus/master]
[also build test ERROR on v4.19-rc2 next-20180906]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Hans-de-Goede/printk-For-early-boot-messages-check-loglevel-when-flushing-the-buffer/20180906-215356
config: parisc-allnoconfig (attached as .config)
compiler: hppa-linux-gnu-gcc (Debian 7.2.0-11) 7.2.0
reproduce:
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # save the attached .config to linux build tree
        GCC_VERSION=7.2.0 make.cross ARCH=parisc 

All errors (new ones prefixed by >>):

   kernel/printk/printk.c: In function 'console_unlock':
>> kernel/printk/printk.c:2377:5: error: implicit declaration of function 'suppress_message_printing' [-Werror=implicit-function-declaration]
        suppress_message_printing(msg->level))) {
        ^~~~~~~~~~~~~~~~~~~~~~~~~
   cc1: some warnings being treated as errors

vim +/suppress_message_printing +2377 kernel/printk/printk.c

  2297	
  2298	/**
  2299	 * console_unlock - unlock the console system
  2300	 *
  2301	 * Releases the console_lock which the caller holds on the console system
  2302	 * and the console driver list.
  2303	 *
  2304	 * While the console_lock was held, console output may have been buffered
  2305	 * by printk().  If this is the case, console_unlock(); emits
  2306	 * the output prior to releasing the lock.
  2307	 *
  2308	 * If there is output waiting, we wake /dev/kmsg and syslog() users.
  2309	 *
  2310	 * console_unlock(); may be called from any context.
  2311	 */
  2312	void console_unlock(void)
  2313	{
  2314		static char ext_text[CONSOLE_EXT_LOG_MAX];
  2315		static char text[LOG_LINE_MAX + PREFIX_MAX];
  2316		unsigned long flags;
  2317		bool do_cond_resched, retry;
  2318	
  2319		if (console_suspended) {
  2320			up_console_sem();
  2321			return;
  2322		}
  2323	
  2324		/*
  2325		 * Console drivers are called with interrupts disabled, so
  2326		 * @console_may_schedule should be cleared before; however, we may
  2327		 * end up dumping a lot of lines, for example, if called from
  2328		 * console registration path, and should invoke cond_resched()
  2329		 * between lines if allowable.  Not doing so can cause a very long
  2330		 * scheduling stall on a slow console leading to RCU stall and
  2331		 * softlockup warnings which exacerbate the issue with more
  2332		 * messages practically incapacitating the system.
  2333		 *
  2334		 * console_trylock() is not able to detect the preemptive
  2335		 * context reliably. Therefore the value must be stored before
  2336		 * and cleared after the the "again" goto label.
  2337		 */
  2338		do_cond_resched = console_may_schedule;
  2339	again:
  2340		console_may_schedule = 0;
  2341	
  2342		/*
  2343		 * We released the console_sem lock, so we need to recheck if
  2344		 * cpu is online and (if not) is there at least one CON_ANYTIME
  2345		 * console.
  2346		 */
  2347		if (!can_use_console()) {
  2348			console_locked = 0;
  2349			up_console_sem();
  2350			return;
  2351		}
  2352	
  2353		for (;;) {
  2354			struct printk_log *msg;
  2355			size_t ext_len = 0;
  2356			size_t len;
  2357	
  2358			printk_safe_enter_irqsave(flags);
  2359			raw_spin_lock(&logbuf_lock);
  2360			if (console_seq < log_first_seq) {
  2361				len = sprintf(text, "** %u printk messages dropped **\n",
  2362					      (unsigned)(log_first_seq - console_seq));
  2363	
  2364				/* messages are gone, move to first one */
  2365				console_seq = log_first_seq;
  2366				console_idx = log_first_idx;
  2367			} else {
  2368				len = 0;
  2369			}
  2370	skip:
  2371			if (console_seq == log_next_seq)
  2372				break;
  2373	
  2374			msg = log_from_idx(console_idx);
  2375			if ((msg->flags & LOG_NOCONS) ||
  2376			    ((msg->flags & LOG_CHK_LEVEL) &&
> 2377					suppress_message_printing(msg->level))) {
  2378				/*
  2379				 * Skip record if !ignore_loglevel, and
  2380				 * record has level above the console loglevel.
  2381				 */
  2382				console_idx = log_next(console_idx);
  2383				console_seq++;
  2384				goto skip;
  2385			}
  2386	
  2387			len += msg_print_text(msg,
  2388					console_msg_format & MSG_FORMAT_SYSLOG,
  2389					text + len,
  2390					sizeof(text) - len);
  2391			if (nr_ext_console_drivers) {
  2392				ext_len = msg_print_ext_header(ext_text,
  2393							sizeof(ext_text),
  2394							msg, console_seq);
  2395				ext_len += msg_print_ext_body(ext_text + ext_len,
  2396							sizeof(ext_text) - ext_len,
  2397							log_dict(msg), msg->dict_len,
  2398							log_text(msg), msg->text_len);
  2399			}
  2400			console_idx = log_next(console_idx);
  2401			console_seq++;
  2402			raw_spin_unlock(&logbuf_lock);
  2403	
  2404			/*
  2405			 * While actively printing out messages, if another printk()
  2406			 * were to occur on another CPU, it may wait for this one to
  2407			 * finish. This task can not be preempted if there is a
  2408			 * waiter waiting to take over.
  2409			 */
  2410			console_lock_spinning_enable();
  2411	
  2412			stop_critical_timings();	/* don't trace print latency */
  2413			call_console_drivers(ext_text, ext_len, text, len);
  2414			start_critical_timings();
  2415	
  2416			if (console_lock_spinning_disable_and_check()) {
  2417				printk_safe_exit_irqrestore(flags);
  2418				return;
  2419			}
  2420	
  2421			printk_safe_exit_irqrestore(flags);
  2422	
  2423			if (do_cond_resched)
  2424				cond_resched();
  2425		}
  2426	
  2427		console_locked = 0;
  2428	
  2429		/* Release the exclusive_console once it is used */
  2430		if (unlikely(exclusive_console))
  2431			exclusive_console = NULL;
  2432	
  2433		raw_spin_unlock(&logbuf_lock);
  2434	
  2435		up_console_sem();
  2436	
  2437		/*
  2438		 * Someone could have filled up the buffer again, so re-check if there's
  2439		 * something to flush. In case we cannot trylock the console_sem again,
  2440		 * there's a new owner and the console_unlock() from them will do the
  2441		 * flush, no worries.
  2442		 */
  2443		raw_spin_lock(&logbuf_lock);
  2444		retry = console_seq != log_next_seq;
  2445		raw_spin_unlock(&logbuf_lock);
  2446		printk_safe_exit_irqrestore(flags);
  2447	
  2448		if (retry && console_trylock())
  2449			goto again;
  2450	}
  2451	EXPORT_SYMBOL(console_unlock);
  2452	

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 4784 bytes --]

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/06/18 16:28), Petr Mladek wrote:
> On Thu 2018-09-06 16:29:40, Sergey Senozhatsky wrote:
> > On (09/05/18 13:02), Petr Mladek wrote:
> > > Note that the first registered console prints all messages
> > > even without this flag.
> > 
> > Hmm, OK, interesting point.
> > 
> > I assumed that the first console usually has CON_PRINTBUFFER bit set.
> > Or even a CON_PRINTBUFFER | CON_ANYTIME combo. E.g. 8250. It sort of
> > makes sense to have CON_PRINTBUFFER for the first console. Any later
> > consoles [e.g. fbcon, netcon] don't necessarily have CON_PRINTBUFFER.
> > 
> > And the first console has CON_PRINTBUFFER bit set. Well, just because
> > it sounds reasonable. Those were the main assumptions behind my code
> > snippet. Was any of those assumptions wrong?
> 
> This assumption makes sense. In fact, I was wrong. I thought that
> console_seq/console_idx were not updated until the first console
> was registered. But it is not the case.
> 
> It means that the hack with exclusive_console might be usable.

Yeah, it is a hack. But not as dirty as it might appear, I think. In some
sense it's aligned with what we do for exlusive_consoles - we treat exclusive
consoles specially. So specially that even if the system panics while we
re-flush logbuf messages to a new exclusive console, we flush_on_panic() only
to that exclusive console, ignoring the rest of them.

Not sure if it's totally right. There can be a netcon, for instance,
available, which will not see panic flush() because of a exclusive
console:

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c036f128cdc3..ede29a7ba6db 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2545,6 +2545,7 @@ void console_flush_on_panic(void)
 	 * ensure may_schedule is cleared.
 	 */
 	console_trylock();
+	exclusive_console = NULL;
 	console_may_schedule = 0;
 	console_unlock();
 }

---

Opinions?

> But I would prefer to do it a cleaner way.

OK.

> But it is rather complicated, still hacky, ...

Right.

> > 
> > I can agree, definitely. That's one of the options.
> 
> I prefer the revert for now.

OK, agreed.
IIRC I didn't see any upstream code which would have been fixed
by the commit in question.

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Fri 2018-09-07 13:21:32, Sergey Senozhatsky wrote:
> On (09/06/18 16:28), Petr Mladek wrote:
> > On Thu 2018-09-06 16:29:40, Sergey Senozhatsky wrote:
> > > On (09/05/18 13:02), Petr Mladek wrote:
> > > > Note that the first registered console prints all messages
> > > > even without this flag.
> > > 
> > > Hmm, OK, interesting point.
> > > 
> > > I assumed that the first console usually has CON_PRINTBUFFER bit set.
> > > Or even a CON_PRINTBUFFER | CON_ANYTIME combo. E.g. 8250. It sort of
> > > makes sense to have CON_PRINTBUFFER for the first console. Any later
> > > consoles [e.g. fbcon, netcon] don't necessarily have CON_PRINTBUFFER.
> > > 
> > > And the first console has CON_PRINTBUFFER bit set. Well, just because
> > > it sounds reasonable. Those were the main assumptions behind my code
> > > snippet. Was any of those assumptions wrong?
> > 
> > This assumption makes sense. In fact, I was wrong. I thought that
> > console_seq/console_idx were not updated until the first console
> > was registered. But it is not the case.
> > 
> > It means that the hack with exclusive_console might be usable.
> 
> Yeah, it is a hack. But not as dirty as it might appear, I think. In some
> sense it's aligned with what we do for exlusive_consoles - we treat exclusive
> consoles specially. So specially that even if the system panics while we
> re-flush logbuf messages to a new exclusive console, we flush_on_panic() only
> to that exclusive console, ignoring the rest of them.

I consider this a bug. Another bug is that other consoles might miss
messages that appear while the older messages are being
replayed on exclusive_console.

AFAIK, nobody complains about it. But I not comfortable with reusing
this racy pattern even more ;-)


> Not sure if it's totally right. There can be a netcon, for instance,
> available, which will not see panic flush() because of a exclusive
> console:

Good catch.

> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c036f128cdc3..ede29a7ba6db 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2545,6 +2545,7 @@ void console_flush_on_panic(void)
>  	 * ensure may_schedule is cleared.
>  	 */
>  	console_trylock();
> +	exclusive_console = NULL;

This is not be enough. It would cause replying old messages
on all consoles.

Most problems should probably be solved when we store console_seq
before setting exclusive_console. Then we could clear
exclusive_console when reaching the stored sequence number.

Can this be that simple? ;-)


> > I prefer the revert for now.
> 
> OK, agreed.
> IIRC I didn't see any upstream code which would have been fixed
> by the commit in question.

My proposal for 4.19:


From 46ceb577021c8899edd1977a52929b309a5ebf85 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Mon, 10 Sep 2018 15:52:06 +0200
Subject: [PATCH] Revert "printk: make sure to print log on console."

This reverts commit 375899cddcbb26881b03cb3fbdcfd600e4e67f4a.

The visibility of early messages did not longer take into account
"quiet", "debug", and "loglevel" early parameters.

It would be possible to invalidate and recompute LOG_NOCONS flag
for the affected messages. But it would be hairy.

Instead this patch just reverts the problematic commit. We could
come up with a better solution for the original problem. For example,
we could simplify the logic and just mark messages that should always
be visible or always invisible on the console.

Also this patch does not put back the unused LOG_NOCONS flag.

Reported-by: Hans de Goede <hdegoede@redhat.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 11 ++++-------
 1 file changed, 4 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fd6f8ed28e01..5fae295fcb75 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -351,7 +351,6 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
  */
 
 enum log_flags {
-	LOG_NOCONS	= 1,	/* suppress print, do not print to console */
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_PREFIX	= 4,	/* text started with a prefix */
 	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
@@ -1881,9 +1880,6 @@ int vprintk_store(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	if (suppress_message_printing(level))
-		lflags |= LOG_NOCONS;
-
 	return log_output(facility, level, lflags,
 			  dict, dictlen, text, text_len);
 }
@@ -2368,10 +2364,11 @@ void console_unlock(void)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
+		if (suppress_message_printing(msg->level)) {
 			/*
-			 * Skip record if !ignore_loglevel, and
-			 * record has level above the console loglevel.
+			 * Skip record we have buffered and already printed
+			 * directly to the console when we received it, and
+			 * record that has level above the console loglevel.
 			 */
 			console_idx = log_next(console_idx);
 			console_seq++;
-- 
2.13.7

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Hans de Goede]

Hi,

On 10-09-18 16:57, Petr Mladek wrote:
> On Fri 2018-09-07 13:21:32, Sergey Senozhatsky wrote:
>> On (09/06/18 16:28), Petr Mladek wrote:
>>> On Thu 2018-09-06 16:29:40, Sergey Senozhatsky wrote:
>>>> On (09/05/18 13:02), Petr Mladek wrote:
>>>>> Note that the first registered console prints all messages
>>>>> even without this flag.
>>>>
>>>> Hmm, OK, interesting point.
>>>>
>>>> I assumed that the first console usually has CON_PRINTBUFFER bit set.
>>>> Or even a CON_PRINTBUFFER | CON_ANYTIME combo. E.g. 8250. It sort of
>>>> makes sense to have CON_PRINTBUFFER for the first console. Any later
>>>> consoles [e.g. fbcon, netcon] don't necessarily have CON_PRINTBUFFER.
>>>>
>>>> And the first console has CON_PRINTBUFFER bit set. Well, just because
>>>> it sounds reasonable. Those were the main assumptions behind my code
>>>> snippet. Was any of those assumptions wrong?
>>>
>>> This assumption makes sense. In fact, I was wrong. I thought that
>>> console_seq/console_idx were not updated until the first console
>>> was registered. But it is not the case.
>>>
>>> It means that the hack with exclusive_console might be usable.
>>
>> Yeah, it is a hack. But not as dirty as it might appear, I think. In some
>> sense it's aligned with what we do for exlusive_consoles - we treat exclusive
>> consoles specially. So specially that even if the system panics while we
>> re-flush logbuf messages to a new exclusive console, we flush_on_panic() only
>> to that exclusive console, ignoring the rest of them.
> 
> I consider this a bug. Another bug is that other consoles might miss
> messages that appear while the older messages are being
> replayed on exclusive_console.
> 
> AFAIK, nobody complains about it. But I not comfortable with reusing
> this racy pattern even more ;-)
> 
> 
>> Not sure if it's totally right. There can be a netcon, for instance,
>> available, which will not see panic flush() because of a exclusive
>> console:
> 
> Good catch.
> 
>> ---
>>
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index c036f128cdc3..ede29a7ba6db 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -2545,6 +2545,7 @@ void console_flush_on_panic(void)
>>   	 * ensure may_schedule is cleared.
>>   	 */
>>   	console_trylock();
>> +	exclusive_console = NULL;
> 
> This is not be enough. It would cause replying old messages
> on all consoles.
> 
> Most problems should probably be solved when we store console_seq
> before setting exclusive_console. Then we could clear
> exclusive_console when reaching the stored sequence number.
> 
> Can this be that simple? ;-)
> 
> 
>>> I prefer the revert for now.
>>
>> OK, agreed.
>> IIRC I didn't see any upstream code which would have been fixed
>> by the commit in question.
> 
> My proposal for 4.19:
> 
> 
>  From 46ceb577021c8899edd1977a52929b309a5ebf85 Mon Sep 17 00:00:00 2001
> From: Petr Mladek <pmladek@suse.com>
> Date: Mon, 10 Sep 2018 15:52:06 +0200
> Subject: [PATCH] Revert "printk: make sure to print log on console."
> 
> This reverts commit 375899cddcbb26881b03cb3fbdcfd600e4e67f4a.
> 
> The visibility of early messages did not longer take into account
> "quiet", "debug", and "loglevel" early parameters.
> 
> It would be possible to invalidate and recompute LOG_NOCONS flag
> for the affected messages. But it would be hairy.
> 
> Instead this patch just reverts the problematic commit. We could
> come up with a better solution for the original problem. For example,
> we could simplify the logic and just mark messages that should always
> be visible or always invisible on the console.
> 
> Also this patch does not put back the unused LOG_NOCONS flag.
> 
> Reported-by: Hans de Goede <hdegoede@redhat.com>
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Sounds like a good solution to me:

Acked-by: Hans de Goede <hdegoede@redhat.com>

Regards,

Hans



> ---
>   kernel/printk/printk.c | 11 ++++-------
>   1 file changed, 4 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fd6f8ed28e01..5fae295fcb75 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -351,7 +351,6 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
>    */
>   
>   enum log_flags {
> -	LOG_NOCONS	= 1,	/* suppress print, do not print to console */
>   	LOG_NEWLINE	= 2,	/* text ended with a newline */
>   	LOG_PREFIX	= 4,	/* text started with a prefix */
>   	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
> @@ -1881,9 +1880,6 @@ int vprintk_store(int facility, int level,
>   	if (dict)
>   		lflags |= LOG_PREFIX|LOG_NEWLINE;
>   
> -	if (suppress_message_printing(level))
> -		lflags |= LOG_NOCONS;
> -
>   	return log_output(facility, level, lflags,
>   			  dict, dictlen, text, text_len);
>   }
> @@ -2368,10 +2364,11 @@ void console_unlock(void)
>   			break;
>   
>   		msg = log_from_idx(console_idx);
> -		if (msg->flags & LOG_NOCONS) {
> +		if (suppress_message_printing(msg->level)) {
>   			/*
> -			 * Skip record if !ignore_loglevel, and
> -			 * record has level above the console loglevel.
> +			 * Skip record we have buffered and already printed
> +			 * directly to the console when we received it, and
> +			 * record that has level above the console loglevel.
>   			 */
>   			console_idx = log_next(console_idx);
>   			console_seq++;
> 

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/10/18 16:57), Petr Mladek wrote:
> 
> Good catch.
> 
> > ---
> > 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index c036f128cdc3..ede29a7ba6db 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2545,6 +2545,7 @@ void console_flush_on_panic(void)
> >  	 * ensure may_schedule is cleared.
> >  	 */
> >  	console_trylock();
> > +	exclusive_console = NULL;
> 
> This is not be enough. It would cause replying old messages
> on all consoles.

Oh, that was intentional. I consider repeated messages to be less
problematic than the missing ones.

> Most problems should probably be solved when we store console_seq
> before setting exclusive_console. Then we could clear
> exclusive_console when reaching the stored sequence number.
> 
> Can this be that simple? ;-)

This can work, yes.

I also thought about doing it the way Linus, Jan Kara and Hannes
Reinecke proposed:

- store the console_seq nr of the first oops_in_progress message
  (oops_console_seq) and flush only messages that are in
  [oops_console_seq - 200, log_next_seq] range, as opposed to complete
  logbuf flush.

Hannes asked for this several times. And it was in Jan's printk patches
long time ago (if I'm not mistaken - sorry if I am -- Jan said that Linus
wanted that "just N messages prior to oops" thing).

Jan's patch:
 https://lore.kernel.org/lkml/1457964820-4642-3-git-send-email-sergey.senozhatsky@gmail.com/T/#u


> This reverts commit 375899cddcbb26881b03cb3fbdcfd600e4e67f4a.
> 
> Reported-by: Hans de Goede <hdegoede@redhat.com>
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Tue 2018-09-11 11:30:39, Sergey Senozhatsky wrote:
> On (09/10/18 16:57), Petr Mladek wrote:
> > 
> > Good catch.
> > 
> > > ---
> > > 
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index c036f128cdc3..ede29a7ba6db 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -2545,6 +2545,7 @@ void console_flush_on_panic(void)
> > >  	 * ensure may_schedule is cleared.
> > >  	 */
> > >  	console_trylock();
> > > +	exclusive_console = NULL;
> > 
> > This is not be enough. It would cause replying old messages
> > on all consoles.
> 
> Oh, that was intentional. I consider repeated messages to be less
> problematic than the missing ones.

It makes some sense. But it might be problematic with slow consoles.
I prefer to avoid it if there is a better solution.


> > Most problems should probably be solved when we store console_seq
> > before setting exclusive_console. Then we could clear
> > exclusive_console when reaching the stored sequence number.
> > 
> > Can this be that simple? ;-)
> 
> This can work, yes.

I'll try to cook up a patch later this week.


> I also thought about doing it the way Linus, Jan Kara and Hannes
> Reinecke proposed:
> 
> - store the console_seq nr of the first oops_in_progress message
>   (oops_console_seq) and flush only messages that are in
>   [oops_console_seq - 200, log_next_seq] range, as opposed to complete
>   logbuf flush.
> 
> Hannes asked for this several times. And it was in Jan's printk patches
> long time ago (if I'm not mistaken - sorry if I am -- Jan said that Linus
> wanted that "just N messages prior to oops" thing).
> 
> Jan's patch:
>  https://lore.kernel.org/lkml/1457964820-4642-3-git-send-email-sergey.senozhatsky@gmail.com/T/#u

The patch might be useful but it also might be controversial. It would
deserve discussion with a wide audience in a dedicated thread.


> > This reverts commit 375899cddcbb26881b03cb3fbdcfd600e4e67f4a.
> > 
> > Reported-by: Hans de Goede <hdegoede@redhat.com>
> > Signed-off-by: Petr Mladek <pmladek@suse.com>
> 
> Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

I have just pushed the patch into printk.git, for-4.19-rc4 branch.

Note that I merged also a revert of the build fix
commit ffaa619af1b06 ("printk: Fix warning about unused
suppress_message_printing"). I am sorry that I missed
it in the original patch. It is an obvious oneliner.
It should not invalidate the acks.

Best Regards,
Petr

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/11/18 10:47), Petr Mladek wrote:
> > Oh, that was intentional. I consider repeated messages to be less
> > problematic than the missing ones.
> 
> It makes some sense. But it might be problematic with slow consoles.

Right. And this is why I brought up Jan's patch.
And I agree that we better discuss that approach in a separate thread.

> > > Most problems should probably be solved when we store console_seq
> > > before setting exclusive_console. Then we could clear
> > > exclusive_console when reaching the stored sequence number.
> > > 
> > > Can this be that simple? ;-)
> > 
> > This can work, yes.
> 
> I'll try to cook up a patch later this week.

Hmm, wouldn't the same "it might be problematic with slow consoles"
argument apply to this solution as well? If we flush_on_panic(), and
have a slow exclusive_console then flushing logbuf to that slow
exclusive_console can take quite some time, before we even begin to
flush oops messages.

So maybe we can do the following:

- store console_seq when we register exclusive console
- in flush_on_panic, if we have exclusive console set
    - clear exclusive console
    - rollback console_seq to the value it had before we set exclusive console

So we will not re-flush all logbuf messages, but only the new ones and
should get to oops messages sooner.

IOW, something like this?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 53c94cbce0af..4ef199572df7 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -424,6 +424,7 @@ static u32 log_next_idx;
 /* the next printk record to write to the console */
 static u64 console_seq;
 static u32 console_idx;
+static u64 rollback_console_seq;
 
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
@@ -2592,6 +2593,10 @@ void console_flush_on_panic(void)
 	 */
 	console_trylock();
 	console_may_schedule = 0;
+	if (exclusive_console) {
+		exclusive_console = NULL;
+		console_seq = rollback_console_seq;
+	}
 	console_unlock();
 }
 
@@ -2793,6 +2798,7 @@ void register_console(struct console *newcon)
 		 * for us.
 		 */
 		logbuf_lock_irqsave(flags);
+		rollback_console_seq = console_seq;
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
 		logbuf_unlock_irqrestore(flags);

---

	-ss

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Petr Mladek]

On Wed 2018-09-12 16:49:30, Sergey Senozhatsky wrote:
> On (09/11/18 10:47), Petr Mladek wrote:
> > > > Most problems should probably be solved when we store console_seq
> > > > before setting exclusive_console. Then we could clear
> > > > exclusive_console when reaching the stored sequence number.
> 
> Hmm, wouldn't the same "it might be problematic with slow consoles"
> argument apply to this solution as well?

It would just fix a clear bug.

> So maybe we can do the following:
> 
> - store console_seq when we register exclusive console
> - in flush_on_panic, if we have exclusive console set
>     - clear exclusive console
>     - rollback console_seq to the value it had before we set exclusive console
 
> ---
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 53c94cbce0af..4ef199572df7 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -424,6 +424,7 @@ static u32 log_next_idx;
>  /* the next printk record to write to the console */
>  static u64 console_seq;
>  static u32 console_idx;
> +static u64 rollback_console_seq;
>  
>  /* the next printk record to read after the last 'clear' command */
>  static u64 clear_seq;
> @@ -2592,6 +2593,10 @@ void console_flush_on_panic(void)
>  	 */
>  	console_trylock();
>  	console_may_schedule = 0;
> +	if (exclusive_console) {
> +		exclusive_console = NULL;
> +		console_seq = rollback_console_seq;

This might be controversial. Yes, it might help in some situations
(slow exclusive console). But it might be counterproductive
when the exclusive console is the one that is readable
after the crash, used for debugging and this change causes
an incomplete log.

I would do this change only when people complains about
the current behavior.

I think that more important is to do:

@@ -2415,6 +2415,9 @@ void console_unlock(void)
                console_seq++;
                raw_spin_unlock(&logbuf_lock);
 
+               if (exclusive_console && console_seq >= rollback_console_seq)
+                       exclusive_console = NULL;
+
                /*
                 * While actively printing out messages, if another printk()
                 * were to occur on another CPU, it may wait for this one to

IMHO, this is a clear win. It fixes a clear mistake.

I would just rename the variable to exclusive_console_seq_stop or so.

Best Regards,
Petr

Re: [PATCH 4.19 regression fix] printk: For early boot messages check loglevel when flushing the buffer

[Sergey Senozhatsky]

On (09/12/18 15:33), Petr Mladek wrote:
> >  	console_trylock();
> >  	console_may_schedule = 0;
> > +	if (exclusive_console) {
> > +		exclusive_console = NULL;
> > +		console_seq = rollback_console_seq;
> 
> This might be controversial. Yes, it might help in some situations
> (slow exclusive console). But it might be counterproductive
> when the exclusive console is the one that is readable
> after the crash, used for debugging and this change causes
> an incomplete log.

Well, OK. We still print oops messages, just get to this point sooner.

> I would do this change only when people complains about
> the current behavior.

OK. Agreed.

> I think that more important is to do:
[..]
> IMHO, this is a clear win. It fixes a clear mistake.
> 
> I would just rename the variable to exclusive_console_seq_stop or so.

OK. Send a patch.

Reported-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>


	-ss