Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1722603
| From | Joe Perches <joe@perches.com> |
|---|---|
| Newsgroups | linux.kernel |
| Subject | Re: printk: what is going on with additional newlines? |
| Date | 2017-08-29 18:40 +0200 |
| Message-ID | <ujRIu-4WZ-11@gated-at.bofh.it> (permalink) |
| References | (1 earlier) <ujods-3Ju-7@gated-at.bofh.it> <ujpsS-4p8-35@gated-at.bofh.it> <ujrl0-5xq-21@gated-at.bofh.it> <ujrEm-5DK-23@gated-at.bofh.it> <ujP3X-3gG-1@gated-at.bofh.it> |
| Organization | linux.* mail to news gateway |
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 */
Back to linux.kernel | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread
printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-28 11:10 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 12:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 14:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 14:40 +0200
Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-28 14:50 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-29 15:50 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 18:40 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:10 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:20 +0200
Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-08-29 22:50 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 23:00 +0200
Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-09-02 08:20 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-02 19:10 +0200
Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-08-30 02:00 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-30 02:00 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:10 +0200
Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-08-30 03:20 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:50 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 04:00 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 04:30 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 04:40 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 04:50 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 05:00 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 07:40 +0200
Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-08 12:20 +0200
Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-05 11:50 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-05 12:10 +0200
Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-05 14:30 +0200
Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-09-05 14:40 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-05 16:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-05 15:50 +0200
Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-06 10:00 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-01 15:30 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 19:40 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-01 22:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 07:30 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-04 07:50 +0200
Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-09-05 17:00 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-06 04:20 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-06 04:40 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 06:40 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 07:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-29 19:40 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 20:00 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 20:10 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:10 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:00 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 18:50 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:20 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:30 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:40 +0200
Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:40 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:50 +0200
Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-29 22:30 +0200
Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-01 03:50 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 04:10 +0200
Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-01 09:00 +0200
Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 09:30 +0200
Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-01 09:30 +0200
Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-09-01 13:20 +0200
csiph-web