From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751919AbdH2QhP (ORCPT ); Tue, 29 Aug 2017 12:37:15 -0400 Received: from smtprelay0036.hostedemail.com ([216.40.44.36]:45727 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1751272AbdH2QhO (ORCPT ); Tue, 29 Aug 2017 12:37:14 -0400 X-Session-Marker: 6A6F6540706572636865732E636F6D X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,joe@perches.com,:::::::::::::::::::::::,RULES_HIT:2:41:355:379:541:599:800:960:973:988:989:1260:1277:1311:1313:1314:1345:1359:1373:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:1801:2198:2199:2393:2553:2559:2562:2828:2915:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3874:4049:4119:4184:4321:4605:5007:6117:6119:7514:7576:7875:7903:8660:9121:9545:10004:10848:10967:11026:11232:11233:11658:11914:12043:12050:12295:12296:12438:12555:12740:12760:12895:13148:13230:13439:14096:14097:14659:21060:21080:21088:21324:21433:21451:21627:30045:30054:30069:30070:30075:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:2,LUA_SUMMARY:none X-HE-Tag: moon21_5bee54d157619 X-Filterd-Recvd-Size: 8031 Message-ID: <1504024630.2040.25.camel@perches.com> Subject: Re: printk: what is going on with additional newlines? From: Joe Perches To: Sergey Senozhatsky , Pavel Machek , Linus Torvalds Cc: Sergey Senozhatsky , Petr Mladek , Steven Rostedt , Jan Kara , Andrew Morton , Jiri Slaby , Andreas Mohr , Tetsuo Handa , linux-kernel@vger.kernel.org Date: Tue, 29 Aug 2017 09:37:10 -0700 In-Reply-To: <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> <20170829134048.GA437@jagdpanzerIV.localdomain> Content-Type: text/plain; charset="ISO-8859-1" X-Mailer: Evolution 3.22.6-1ubuntu1 Mime-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 > 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 > 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 */