[PATCH v2] printk: Always report lost messages on serial console

[Petr Mladek]

The "printk messages dropped" report is 'attached' to a kernel
message located at console_idx offset. This does not work well
if we skip that message due to loglevel filtering, because in
this case we also skip/lose dropped message report.

A simple solution would be to ignore the level and always print
the warning with the next message.

But the situation suggests that we are under a high load and
could not afford printing less important messages.

Also we could not print only the warning because we might lose
even more messages in the meantime.

The best solution seems to be to print the warning with
the next visible message.

This patch tries to keep readability of the code. It puts
msg_print*() calls into a helper function. Also it hides there
the visibility check and increment of console_idx/console_seq.

Reported-by: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>
---
 kernel/printk/printk.c | 70 +++++++++++++++++++++++++++++---------------------
 1 file changed, 41 insertions(+), 29 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0dbde4e7bb15..ae80dc3284dc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2161,6 +2161,35 @@ static inline int can_use_console(void)
 	return cpu_online(raw_smp_processor_id()) || have_callable_console();
 }
 
+static bool console_check_and_print_next_msg(
+		char *text, size_t size, size_t *len,
+		char *ext_text, size_t ext_size, size_t *ext_len)
+{
+	struct printk_log *msg = log_from_idx(console_idx);
+	bool ret = true;
+
+	if (suppress_message_printing(msg->level)) {
+		ret = false;
+		goto out;
+	}
+
+	*len += msg_print_text(msg, false, text, size);
+	if (nr_ext_console_drivers) {
+		*ext_len = msg_print_ext_header(ext_text, ext_size,
+						msg, console_seq);
+		*ext_len += msg_print_ext_body(ext_text + *ext_len,
+					       ext_size - *ext_len,
+					       log_dict(msg), msg->dict_len,
+					       log_text(msg), msg->text_len);
+	}
+
+out:
+	console_idx = log_next(console_idx);
+	console_seq++;
+
+	return ret;
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -2215,9 +2244,9 @@ void console_unlock(void)
 	}
 
 	for (;;) {
-		struct printk_log *msg;
+		bool visible_msg = false;
 		size_t ext_len = 0;
-		size_t len;
+		size_t len = 0;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		if (seen_seq != log_next_seq) {
@@ -2232,37 +2261,20 @@ void console_unlock(void)
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
-		} else {
-			len = 0;
 		}
-skip:
-		if (console_seq == log_next_seq)
-			break;
 
-		msg = log_from_idx(console_idx);
-		if (suppress_message_printing(msg->level)) {
-			/*
-			 * 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++;
-			goto skip;
-		}
+		/* Get the next message with a visible level */
+		while (console_seq < log_next_seq && !visible_msg) {
+			visible_msg = console_check_and_print_next_msg(
+					text + len, sizeof(text) - len, &len,
+					ext_text, sizeof(ext_text), &ext_len);
 
-		len += msg_print_text(msg, false, text + len, sizeof(text) - len);
-		if (nr_ext_console_drivers) {
-			ext_len = msg_print_ext_header(ext_text,
-						sizeof(ext_text),
-						msg, console_seq);
-			ext_len += msg_print_ext_body(ext_text + ext_len,
-						sizeof(ext_text) - ext_len,
-						log_dict(msg), msg->dict_len,
-						log_text(msg), msg->text_len);
 		}
-		console_idx = log_next(console_idx);
-		console_seq++;
+
+		/* No warning and no visible message => done */
+		if (!len && !visible_msg)
+			break;
+
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-- 
1.8.5.6