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

From: Hans de Goede
Date: Mon Sep 10 2018 - 11:02:21 EST


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@xxxxxxxx>
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@xxxxxxxxxx>
Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>

Sounds like a good solution to me:

Acked-by: Hans de Goede <hdegoede@xxxxxxxxxx>

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++;