Re: printk: what is going on with additional newlines?
From: Joe Perches
Date: Tue Aug 29 2017 - 12:37:18 EST
On Tue, 2017-08-29 at 22:40 +0900, Sergey Senozhatsky wrote:
> 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.senozhatsky@xxxxxxxxx>
> 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:
It's possibly dubious to go back to v4.5 behavior.
Linus changed the
printk continuation behavior in v4.9
Unfortunately he did this without
posting anything to lkml
for comment and he broke a bunch of continuation
printks.
> 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.senozhatsky@xxxxxxxxx>
> Reported-by: Pavel Machek <pavel@xxxxxx>
> ---
> 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 */