Date:   Wed, 4 Oct 2017 15:17:03 +0200
From:   Petr Mladek <pmladek@...e.com>
To:     pierre kuo <vichy.kuo@...il.com>
Cc:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        rostedt@...dmis.org, linux-kernel@...r.kernel.org
Subject: Re: [RFC V2] printk: add warning while drop partial text in msg

Hi,

I was curious why you see these results. I think that I finally
understand it.

On Tue 2017-09-12 14:07:09, pierre kuo wrote:
> The experimental steps are list as follows.
> Feel free to give your comments.
> 
> Prerequisite:
> a) kernel version:
>     commit: a80099a152d0 ("Merge tag 'xfs-4.13-merge-6' of
> git://git.kernel.org/pub/scm/fs/xfs/xfs-linux")
> 
> 1. Add below patch in log_store to tell the content and length of log
> that saved in log_text(msg) for below step #2 .
> @@ -629,6 +629,11 @@ static int log_store(int facility, int level,
>         msg->len = size;
> 
>         /* insert message */
> +       if (msg->text_len > 512) {
> +               trace_printk("%s\n", log_text(msg));
> +               trace_printk("msg->text_len %d\n", msg->text_len);
> +       }
> +
>         log_next_idx += msg->len;
>         log_next_seq++;
> 
> 2. Use below kernel thread sample for adding the string to msg.
> int per_cpu_thread_fn(void* data)
> {
>     unsigned int index = 0;
>     unsigned int len = 0;
>     char* local_string = kzalloc(2048, GFP_KERNEL);
> 
>     do {
>         len += sprintf((local_string + len), "this is the %d line\n", index++);
>     }while(len < 576);
>     printk_deferred("%s", local_string);

You call printk() for a string which length is slightly above 576
characters. Therefore it fits into textbuf[LOG_LINE_MAX] in vprintk_emit().
It is stored in a single record into the main log buffer.
Nothing is lost at this stage. So far so good.


>     return 0;
> }
> 
> 3. After running above #2, here is trace output from #1
> (from the output, total "29 lines" of local_string has successfully
> saved in log_buf)
> # cat /sys/kernel/debug/tracing/trace;
> # tracer: nop
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>   per_cpu_thread-81    [000] d..1    26.555745: log_store: this is the 0 line
> this is the 1 line
> this is the 2 line
[...]
> this is the 27 line
> this is the 28 line
> this is the 29 line
>   per_cpu_thread-81    [000] d..1    26.555753: log_store: msg->text_len 589

The above messages are from ftrace buffer. Please note that the
timestamp is printed only for "this is the 0 line". It confirms
that all lines fit into textbuf[LOG_LINE_MAX] and were stored
as a single record by a single log_store() call.


> 4. Write a user mode programs with buffer size 2MB, triple size bigger
> than the text length in msg we saved in above #2, and repeatedly
> calling SYSLOG_ACTION_READ for getting the log.
> Then the log we got will _NOT_ show over than "this is the 26 line" as
> below, that mean line#27 ~ line#29 are missing.
> (the source is attached as "simple_log.tar.bz2")
> <4>[   39.467710] this is the 0 line
> <4>[   39.467710] this is the 1 line
[...]
> <4>[   39.467710] this is the 24 line
> <4>[   39.467710] this is the 25 line
> <4>[   39.467710] this is the 26 line

You used SYSLOG_ACTION_READ. Therefore the above lines were
formatted by msg_print_text() called from syslog_print().

Now, msg_print_text() could not write directly into the 2MB
big buffer because it is is from userspace. Instead, it writes
the messages into the temporary buffer that is later copied
to the userspace one by copy_to_user().

The temporary buffer is allocated in syslog_print():

	text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);

The expectation is that there will be needed only one timestamp
(prefix) for each stored record (line).

But we saved more lines in a single record. Therefore msg_print_text()
has to add many timestamps (prefixes). As a result the original 576
bytes long message does not fit into 1024 bytes big buffer and
is shrunken.


There are several possible solutions:

+ We could update vprintk_emit() to detect all newlines and
  call log_store() for each part. But this would be a waste
  of the space.

+ We could increase the size provided by syslog_printk().
  But this is ugly.

+ We could go back to the original idea and print a warning
  about shrunken message when the first record is not fully
  stored by msg_print_text().

I think that the last solution is the best. Note that the
original patch was wrong because it warned in any
msg_print_text() and not only the first one.

Another question is that printk() is used a wrong way here.
I will comment this in another mail in this thread.

Best Regards,
Petr

Powered by blists - more mailing lists