Re: printk: what is going on with additional newlines?

[Joe Perches <joe@perches.com>]

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@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:

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@gmail.com>
> Reported-by: Pavel Machek <pavel@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 */