| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20170103145532.GL14894@pathway.suse.cz>
Date: Tue, 3 Jan 2017 15:55:32 +0100
From: Petr Mladek <pmladek@...e.com>
To: Sergey Senozhatsky <sergey.senozhatsky@...il.com>
Cc: Andrew Morton <akpm@...ux-foundation.org>,
Steven Rostedt <rostedt@...dmis.org>,
Peter Hurley <peter@...leysoftware.com>,
linux-kernel@...r.kernel.org,
Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Subject: Re: [PATCH 2/2] printk: always report lost messages on serial console
On Sat 2016-12-24 23:09:02, Sergey Senozhatsky wrote:
> 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.
Good catch!
> Disable suppress_message_printing() loglevel filtering if we
> must report "printk messages dropped" condition.
>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@...il.com>
> ---
> kernel/printk/printk.c | 5 ++++-
> 1 file changed, 4 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 11a9842a2f47..6a7ebcb0bb6e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2218,6 +2218,7 @@ void console_unlock(void)
> struct printk_log *msg;
> size_t ext_len = 0;
> size_t len;
> + bool report_dropped_msg = false;
>
> raw_spin_lock_irqsave(&logbuf_lock, flags);
> if (seen_seq != log_next_seq) {
> @@ -2232,6 +2233,7 @@ void console_unlock(void)
> /* messages are gone, move to first one */
> console_seq = log_first_seq;
> console_idx = log_first_idx;
> + report_dropped_msg = true;
> } else {
> len = 0;
> }
> @@ -2240,7 +2242,8 @@ void console_unlock(void)
> break;
>
> msg = log_from_idx(console_idx);
> - if (suppress_message_printing(msg->level)) {
> + if (!report_dropped_msg &&
> + suppress_message_printing(msg->level)) {
> /*
> * Skip record we have buffered and already printed
> * directly to the console when we received it, and
This causes the opposite problem. We might print a message that was supposed
to be suppressed. I think that it is not a good idea in this
situation. I played with it and cooked a patch, see below.
Please, do not feel offended. I do not want to take you credits
for finding the problem.
But the printk code is very twisted and console_unlock() is one
of the worst pieces. Solution based on my concerns could make
it even worse. I do not want to push you into clean ups and
tried it myself.
The result is not as good as I hoped. But it it is not worse, IMHO.
Which is good given the circumstances.
Feel free to provide even better one and use pieces from my patch.
I also think about spling it into two patches and make msg_print()
helper in a separate patch.
>From 976073de3e0f3daa4f1d700ef605165d97533c9b Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@...e.com>
Date: Tue, 3 Jan 2017 14:32:04 +0100
Subject: [PATCH] printk: Always report lost messages on serial console
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@...il.com>
Signed-off-by: Petr Mladek <pmladek@...e.com>
---
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
Powered by blists - more mailing lists