Hi,
so I had a second look, and I think the patch I posted yesterday is
pretty wrong. How about something like below?
---
>From d65d1b74d3acc51e5d998c5d2cf10d20c28dc2f9 Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhat...@gmail.com>
Date: Tue, 29 Aug 2017 22:30:07 +0900
Subject: [PATCH] printk: restore non-log_prefix messages handling
Pavel reported that
printk("foo"); printk("bar");
now does not produce a single continuation "foobar" line, but
instead produces two lines
foo
bar
The first printk() goes to cont buffer, just as before. The difference
is how we handle the second one. We used to just add it to the cont
buffer:
if (!(lflags & LOG_NEWLINE)) {
if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
cont_flush();
cont_add(...)
}
but now we flush the existing cont buffer and store the second
printk() message separately:
if (cont.len) {
if (cont.owner == current && (lflags & LOG_CONT))
return cont_add();
/* otherwise flush */
cont_flush();
}
because printk("bar") does not have LOG_CONT.
The patch restores the old behaviour.
To verify the change I did the following printk() test again the v4.5
and patched linux-next:
pr_err("foo"); pr_cont("bar"); pr_cont("bar\n");
printk("foo"); printk("foo"); printk("bar\n");
printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo");
printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo");
printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR "ERR
foo\n");
printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo\n");
printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo\n");
printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n"); printk(KERN_CONT "bar\n");
I, however, got a slightly different output (I'll explain the difference):
v4.5 linux-next
foobarbar foobarbar
foofoobar foofoobar
bazbazbaz bazbazbaz
INFO foo INFO foobazbazbaz
bazbazbaz
ERR foo ERR foofoofoobar
foofoobar
foofoo foofoo
bar bar
foo foo
foo err foo err
ERR foo ERR foo
bazbazbaz bazbazbaz
INFO foo INFO foo
bazbazbaz bazbazbaz
ERR foo ERR foo
foobar foobar
bar bar
As we can see the difference is in:
pr_info("INFO foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo")...
and
pr_err("ERR foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo");...
handling.
The output is expected to be two continuation lines; but this is not
the case for old kernels.
What the old kernel does here is:
- it sees that cont buffer already has data: all those !LOG_PREFIX messages
- it also sees that the current messages is LOG_PREFIX and that part of
the cont buffer was already printed to the serial console:
// Flush the conflicting buffer. An earlier newline was missing
// or another task also prints continuation lines
if (!(lflags & LOG_NEWLINE)) {
if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
cont_flush(LOG_NEWLINE);
if (cont_add(text))
printed_len += text_len;
else
printed_len += log_store(text);
}
the problem here is that, flush does not actually flush the buffer and
does not reset the conf buffer state, but sets cont.flushed to true
instead:
if (cont.cons) {
log_store(cont.text);
cont.flags = flags;
cont.flushed = true;
}
- then the kernel attempts to cont_add() the messages. but cont_add() does
not append the messages to the cont buffer, because of this check
if (cont.len && cont.flushed)
return false;
both cont.len and cont.flushed are true. because the kernel waits for
console_unlock() to call console_cont_flush()->cont_print_text(),
which should print the cont.text to the serial console and reset the
cont buffer state.
- but cont_print_text() must be called under logbuf_lock lock, which
we still hold in vprintk_emit(). so the kernel has no chance to flush
the cont buffer and thus cont_add() fails there and forces the kernel
to log_store() the message, allocating a separate logbuf entry for
it.
That's why we see the difference in v4.5 vs linux-next logs. This is
visible only when !LOG_NEWLINE path has to cont_flush() partially
printed cont buffer from under the logbuf_lock.
I think the old behavior had a bug - we need to concatenate
KERN_ERR foo; KERN_CONT bar; KERN_CON bar\n;
regardless the previous cont buffer state.
Signed-off-by: Sergey Senozhatsky <sergey.senozhat...@gmail.com>
Reported-by: Pavel Machek <pa...@ucw.cz>
---
kernel/printk/printk.c | 11 ++++++++---
1 file changed, 8 insertions(+), 3 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ac1fd606d6c5..be868b7d9ceb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1914,12 +1914,17 @@ static size_t log_output(int facility, int level, enum
log_flags lflags, const c
* write from the same process, try to add it to the buffer.
*/
if (cont.len) {
- if (cont.owner == current && (lflags & LOG_CONT)) {
+ /*
+ * Flush the conflicting buffer. An earlier newline was missing,
+ * or another task also prints continuation lines.
+ */
+ if (lflags & LOG_PREFIX || cont.owner != current)
+ cont_flush();
+
+ if (!(lflags & LOG_PREFIX) || lflags & LOG_CONT) {
if (cont_add(facility, level, lflags, text, text_len))
return text_len;
}
- /* Otherwise, make sure it's flushed */
- cont_flush();
}
/* Skip empty continuation lines that couldn't be added - they just
flush */
--
2.14.1
