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

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

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:

 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 */
-- 
2.14.1