Re: pstore/ram: printk: NULL characters in pstore ramoops area

[Petr Mladek]

On Tue 2023-08-08 18:21:46, Vijay Balakrishna wrote:
> Thanks for your reply Petr.
> 
> See inline.
> 
> On 8/8/23 01:15, Petr Mladek wrote:
> > On Mon 2023-08-07 10:19:07, Vijay Balakrishna wrote:
> > > I'm including my earlier email as it didn't deliver to
> > > linux-kernel@xxxxxxxxxxxxxxx due to HTML subpart.  Also sharing new findings
> > > --
> > > 
> > > Limiting the size of buffer exposed to record_print_text() and
> > > prb_for_each_record() in kmsg_dump_get_buffer() also resolves this issue [5]
> > > -- no NULL characters in pstore/ramoops memory.  The advantage is no memory
> > > allocation (as done in previously shared changes [4]) which could be
> > > problematic during kernel shutdown/reboot or during kexec reboot.
> > > 
> > > [5]
> > > 
> > > Author: Vijay Balakrishna <vijayb@xxxxxxxxxxxxxxxxxxx>
> > > Date:   Sat Aug 5 18:47:27 2023 +0000
> > > 
> > >      printk: limit the size of buffer exposed to record_print_text() by
> > > kmsg_dump_get_buffer()
> > > 
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index b82e4c3b52f4..8feec932aa35 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -3453,9 +3453,9 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper,
> > > bool syslog,
> > >           */
> > >          next_seq = seq;
> > > 
> > > -       prb_rec_init_rd(&r, &info, buf, size);
> > > 
> > >          len = 0;
> > > +       prb_rec_init_rd(&r, &info, buf + len, (size - len) >= LOG_LINE_MAX +
> > > PREFIX_MAX ? LOG_LINE_MAX + PREFIX_MAX : size - len);
> > >          prb_for_each_record(seq, prb, seq, &r) {
> > >                  if (r.info->seq >= dumper->next_seq)
> > >                          break;
> > > @@ -3463,7 +3463,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper,
> > > bool syslog,
> > >                  len += record_print_text(&r, syslog, time);
> > > 
> > >                  /* Adjust record to store to remaining buffer space. */
> > > -               prb_rec_init_rd(&r, &info, buf + len, size - len);
> > > +               prb_rec_init_rd(&r, &info, buf + len, (size - len) >=
> > > LOG_LINE_MAX + PREFIX_MAX ? LOG_LINE_MAX + PREFIX_MAX : size - len);
> > >          }
> > > 
> > >          dumper->next_seq = next_seq;
> 
> Any comments on above change to limit buffer size/range exposed?

I have the feeling that this is just a workaround. I would like to
understand what exactly happens there. I want to be sure that
there is no buffer overflow or other problems.

> The buffer passed to kmsg_dump_get_buffer() is kzalloc()'ed in
> fs/pstore/ram.c: ramoops_probe()
> 
>                 cxt->pstore.buf = kzalloc(cxt->pstore.bufsize, GFP_KERNEL);
> 
> that may explain NULL characters in buffer.

Yeah, it might explain why there are so many '\0' in a row. Here is
the dump from the initial mail:.

root@localhost:~# hexdump -C /var/lib/systemd/pstore/dmesg-ramoops-0
00000000  53 68 75 74 64 6f 77 6e  23 31 20 50 61 72 74 31 |Shutdown#1 Part1|
00000010  0a 3c 36 3e 5b 20 20 20  20 30 2e 30 30 30 30 30 |.<6>[    0.00000|
..
0000ff50  2e 0a 3c 35 3e 5b 20 32  31 38 37 2e 31 31 31 37 |..<5>[ 2187.1117|
0000ff60  31 38 5d 20 61 75 64 69  74 3a 20 74 79 70 65 3d |18] audit: type=|
0000ff70  31 31 33 31 20 61 75 64  69 74 28 31 36 39 30 39 |1131 audit(16909|
0000ff80  31 31 30 34 34 2e 35 36  30 3a 31 37 33 29 3a 20 |11044.560:173): |
0000ff90  70 69 64 3d 31 20 75 69  64 3d 30 20 61 75 69 64 |pid=1 uid=0 auid|
0000ffa0  3d 34 32 39 34 39 36 37  32 39 35 20 73 65 73 3d |=4294967295 ses=|
0000ffb0  34 32 39 34 39 36 37 32  39 35 20 73 75 62 6a 3d |4294967295 subj=|
0000ffc0  73 79 73 74 65 6d 5f 75  3a 73 79 73 74 65 6d 5f |system_u:system_|
0000ffd0  72 3a 69 6e 69 74 5f 74  20 6d 73 67 3d 27 75 6e |r:init_t msg='un|
0000ffe0  69 74 3d xx xx xx xx xx  xx xx xx 2d 65 6e 6d 64 |it=xxxxxxxx-enmd|
0000fff0  2d 6f 77 6e 65 72 73 68  69 70 20 63 6f 6d 6d 3d |-ownership comm=|
00010000  22 73 79 73 74 65 00 00  00 00 00 00 00 00 00 00 |"syste..........|
00010010  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
*
00010050  00 00 0a 3c 33 30 3e 5b  20 32 31 38 37 2e 31 31 |...<30>[ 2187.11|
..
root@localhost:~#

If I count correctly, there are 76 '\0' characters. It can't be easily
explained by writing '\0' into a wrong position. But copying zeroed
buffer might explain it.

Another interesting thing is that the message is interrupted in
the middle of a word "syste...". I expect that it was "systemd"
because there is pid=1 earlier.

It looks like the message was not read completely.

> Output seen after adding NULL character check before calling
> record_print_text() suggest the issue may not be in record_print_text().

Maybe, this check is not enough. Maybe the problem is the other way
that the the message was not read completely.

It might be interesting to check if there are '\0' characters before
the end of the message. It should not happen. The length of the
stored message is defined by vsnprintf() in vprintk_store().
And it should not count the trailing '\0' character.


> (diffs below are from v5.10.178)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 17a310dcb6d9..4cbb845424f5 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3431,10 +3431,17 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper
> *dumper, bool syslog,
>         /* actually read text into the buffer now */
>         l = 0;
>         while (prb_read_valid(prb, seq, &r)) {
> +               size_t pr_len;
>                 if (r.info->seq >= dumper->next_seq)
>                         break;
> 
> -               l += record_print_text(&r, syslog, time);
> +               if (null_char(r.text_buf, r.info->text_len))
> +                       pr_crit("%s: pre record_print_text() a NULL char in
> record text_buf, l %zu, textlen %zu\n", __func__, l, r.info->text_len);

Please, try to check:

	if (r.info->text_len && r.info->text_len - 1)
		pr_crit(....

> +               pr_len = record_print_text(&r, syslog, time);
> +               l += pr_len;
> +
> +               if (null_char(r.text_buf, pr_len))
> +                       pr_crit("%s: post record_print_text() a NULL char in
> record text_buf, l %zu, pr_len %zu\n", __func__, l, pr_len);
> 
>                 /* adjust record to store to remaining buffer space */
>                 prb_rec_init_rd(&r, &info, buf + l, size - l);
> 
> (output during warm reboot)
> 
> [   12.400817] ramoops: ramoops_pstore_write: A NULL char in record buf,
> size 70648
> [   12.408217] printk: kmsg_dump_get_buffer: pre record_print_text() a NULL
> char in record text_buf, l 65505, textlen 53
> [   12.408219] printk: kmsg_dump_get_buffer: post record_print_text() a NULL
> char in record text_buf, l 65578, pr_len 73
> 
> As I replied to Kees last week, we will try to repro with modern/mainline
> kernel hopefully soon.

Yeah, that would be great as well.

Best Regards,
Petr

PS: Please, do not send .html mails. It breaks formatting and
    diff could not be applied.

    Also top-posting is not ideal. It is always easier when
    the comments are written right after the commented text.

    The interleave posting also allows to keep only the important
    parts of the original message in the reply. It helps to
    keep each reply small while keeping the needed context.

    See "interleaved posting" at https://en.wikipedia.org/wiki/Posting_style