[PATCH] 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. As a result we could have only one copy of

	console_idx = log_next(console_idx);
	console_seq++;

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0dbde4e7bb15..7cc2e7effdc3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1234,6 +1234,28 @@ static size_t msg_print_text(const struct printk_log *msg, bool syslog, char *bu
 	return len;
 }
 
+static bool console_check_and_print_msg(u32 console_idx,
+			     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);
+
+	if (suppress_message_printing(msg->level))
+		return false;
+
+	*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);
+	}
+
+	return true;
+}
+
 static int syslog_print(char __user *buf, int size)
 {
 	char *text;
@@ -2215,9 +2237,9 @@ void console_unlock(void)
 	}
 
 	for (;;) {
-		struct printk_log *msg;
+		bool printed_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 +2254,22 @@ 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.
-			 */
+		/* Get the next message with a visible level */
+		while (console_seq < log_next_seq && !printed_msg) {
+			printed_msg = console_check_and_print_msg(console_seq,
+					text + len, sizeof(text) - len, &len,
+					ext_text, sizeof(ext_text), &ext_len);
+
 			console_idx = log_next(console_idx);
 			console_seq++;
-			goto skip;
 		}
 
-		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 && !printed_msg)
+			break;
+
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
-- 
1.8.5.6