From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753919AbdH2Nke (ORCPT ); Tue, 29 Aug 2017 09:40:34 -0400 Received: from mail-pf0-f195.google.com ([209.85.192.195]:33332 "EHLO mail-pf0-f195.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751220AbdH2Nkc (ORCPT ); Tue, 29 Aug 2017 09:40:32 -0400 Date: Tue, 29 Aug 2017 22:40:48 +0900 From: Sergey Senozhatsky To: Pavel Machek Cc: Sergey Senozhatsky , Sergey Senozhatsky , Petr Mladek , Steven Rostedt , Jan Kara , Andrew Morton , Jiri Slaby , Andreas Mohr , Tetsuo Handa , linux-kernel@vger.kernel.org Subject: Re: printk: what is going on with additional newlines? Message-ID: <20170829134048.GA437@jagdpanzerIV.localdomain> References: <20170815025625.1977-1-sergey.senozhatsky@gmail.com> <20170828090521.GA25025@amd> <20170828102830.GA403@jagdpanzerIV.localdomain> <20170828122109.GA532@jagdpanzerIV.localdomain> <20170828124634.GD492@amd> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20170828124634.GD492@amd> User-Agent: Mutt/1.8.3 (2017-05-23) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 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 Reported-by: Pavel Machek --- 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