[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <d8bb1ec7-a4c5-43a2-9de0-9643a70b899f@linux.microsoft.com>
Date: Mon, 7 Aug 2023 10:19:07 -0700
From: Vijay Balakrishna <vijayb@...ux.microsoft.com>
To: Petr Mladek <pmladek@...e.com>,
Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
Steven Rostedt <rostedt@...dmis.org>,
John Ogness <john.ogness@...utronix.de>,
Kees Cook <keescook@...omium.org>,
Colin Cross <ccross@...roid.com>,
Tony Luck <tony.luck@...el.com>,
Anton Vorontsov <anton@...msg.org>
Cc: linux-kernel@...r.kernel.org
Subject: Re: pstore/ram: printk: NULL characters in pstore ramoops area
I'm including my earlier email as it didn't deliver to
linux-kernel@...r.kernel.org 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@...ux.microsoft.com>
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;
On 8/3/23 16:34, Vijay Balakrishna wrote:
>
> Hello,
>
> We are noticing NULL characters in ramoops/pstore memory after a warm
> or a kexec reboot [1] in our 5.10 ARM64 product kernel after moving
> from 5.4 kernel. I ruled out fs/pstore/* as the source from where
> NULL characters originate by adding debug code [2] and confirming from
> collected output [3]. Then isolated further to printk log/ring buffer
> area, the NULL characters were already present in buffer in
> kmsg_dump_get_buffer() when kmsg log lines are read. After looking at
> printk merges in mainline kernel, I cherry-picked following which
> looked related to our 5.10 kernel and still see NULL characters.
>
> 4260e0e5510158d704898603331e5365ebe957de printk: consolidate
> kmsg_dump_get_buffer/syslog_print_all code
> 726b5097701a8d46f5354be780e1a11fc4ca1187 printk: refactor
> kmsg_dump_get_buffer()
> bb07b16c44b2c6ddbafa44bb06454719002e828e printk: limit second loop
> of syslog_print_all
>
> Looking at syslog_print_all() I notice it uses a local buffer unlike
> kmsg_dump_get_buffer() which manipulates buffer in-place to add syslog
> and timestamp prefix data. I made changes [4] to
> kmsg_dump_get_buffer() to use a local buffer similar to
> syslog_print_all() after which I don't see NULL characters in ramoops
> area. I couldn't spot any suspicious code in record_print_text()
> where prefix data added in-place. I'm reaching out to both pstore/ram
> and printk folks for comments. I can investigate/debug further with
> assistance and input from you.
>
> Note:
>
> - NULL characters show up starting at same offset 0x00010006, but #of
> NULL characters varies between reboots
>
> - I have removed pstore compression related kernel configs and using
> dyndbg config for investigation
>
> - NULL characters are replacing some actual data
>
> Thanks for your time.
>
> Vijay
>
> ++++++++++++++++++++++++++++++++++++++++++
>
> [1]
>
> root@...alhost:~# od -c /var/lib/systemd/pstore/dmesg-ramoops-0
> 0000000 S h u t d o w n # 1 P a r t 1
> 0000020 \n < 6 > [ 0 . 0 0 0 0 0
> ..
> 0177520 . \n < 5 > [ 2 1 8 7 . 1 1 1 7
> 0177540 1 8 ] a u d i t : t y p e =
> 0177560 1 1 3 1 a u d i t ( 1 6 9 0 9
> 0177600 1 1 0 4 4 . 5 6 0 : 1 7 3 ) :
> 0177620 p i d = 1 u i d = 0 a u i d
> 0177640 = 4 2 9 4 9 6 7 2 9 5 s e s =
> 0177660 4 2 9 4 9 6 7 2 9 5 s u b j =
> 0177700 s y s t e m _ u : s y s t e m _
> 0177720 r : i n i t _ t m s g = ' u n
> 0177740 i t = x x x x x x x x - e n m d
> 0177760 - o w n e r s h i p c o m m =
> 0200000 " s y s t e \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
> 0200020 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
> *
> 0200120 \0 \0 \n < 3 0 > [ 2 1 8 7 . 1 1
> 0200140 1 9 0 5 ] s y s t e m d [ 1 ]
> ..
> root@...alhost:~#
>
> root@...alhost:~# 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@...alhost:~#
>
> ++++++++++++++++++++++++++++++++++++++++++
>
> [2]
>
> ramoops: pstore: detect NULL char
>
> diff --git a/fs/pstore/ram.c b/fs/pstore/ram.c
> index ade66dbe5f39..1825972151b2 100644
> --- a/fs/pstore/ram.c
> +++ b/fs/pstore/ram.c
> @@ -383,6 +383,10 @@ static int notrace ramoops_pstore_write(struct
> pstore_record *record)
> size = record->size;
> if (size + hlen > prz->buffer_size)
> size = prz->buffer_size - hlen;
> + if (null_char(record->buf, size))
> + pr_crit("%s: A NULL char in record buf, size %zu\n",
> __func__, size);
> + else
> + pr_crit("%s: No NULL char in record buf, size %zu\n",
> __func__, size);
> persistent_ram_write(prz, record->buf, size);
>
> cxt->dump_write_cnt = (cxt->dump_write_cnt + 1) % cxt->max_dump_cnt;
> diff --git a/fs/pstore/ram_core.c b/fs/pstore/ram_core.c
> index a7630c2fea18..fafbccbfceea 100644
> --- a/fs/pstore/ram_core.c
> +++ b/fs/pstore/ram_core.c
> @@ -272,10 +272,22 @@ ssize_t persistent_ram_ecc_string(struct
> persistent_ram_zone *prz,
> return ret;
> }
>
> +bool null_char(const void *s, size_t count)
> +{
> + char *p = (char *)s;
> +
> + while (count--) {
> + if (*p++ == '\0')
> + return true;
> + }
> + return false;
> +}
> +
> static void notrace persistent_ram_update(struct persistent_ram_zone
> *prz,
> const void *s, unsigned int start, unsigned int count)
> {
> struct persistent_ram_buffer *buffer = prz->buffer;
> +
> memcpy_toio(buffer->data + start, s, count);
> persistent_ram_update_ecc(prz, start, count);
> }
> @@ -309,6 +321,11 @@ void persistent_ram_save_old(struct
> persistent_ram_zone *prz)
> }
>
> prz->old_log_size = size;
> +
> + if (null_char(&buffer->data[start], size - start) ||
> + null_char(&buffer->data[0], start))
> + pr_debug("%s: A NULL char in prz buffer\n", __func__);
> +
> memcpy_fromio(prz->old_log, &buffer->data[start], size - start);
> memcpy_fromio(prz->old_log + size - start, &buffer->data[0], start);
> }
> diff --git a/fs/pstore/ram_internal.h b/fs/pstore/ram_internal.h
> index 5f694698351f..d0fd15a6f7af 100644
> --- a/fs/pstore/ram_internal.h
> +++ b/fs/pstore/ram_internal.h
> @@ -96,3 +96,4 @@ void *persistent_ram_old(struct persistent_ram_zone
> *prz);
> void persistent_ram_free_old(struct persistent_ram_zone *prz);
> ssize_t persistent_ram_ecc_string(struct persistent_ram_zone *prz,
> char *str, size_t len);
> +bool null_char(const void *s, size_t count);
>
> ++++++++++++++++++++++++++++++++++++++++++
>
> [3]
>
> root@...alhost:~# reboot
> [ 2188.073362] systemd-shutdown[1]: Could not detach loopback
> /dev/loop1: Device or resource busy
> [ 2188.082272] systemd-shutdown[1]: Could not detach loopback
> /dev/loop0: Device or resource busy
> [ 2188.091873] watchdog: watchdog0: watchdog did not stop!
> [ 2188.099227] systemd-shutdown[1]: Failed to finalize loop devices,
> DM devices, ignoring.
> [ 2188.306671] reboot: Restarting system
> [ 2188.316932] ramoops: ramoops_pstore_write: A NULL char in record
> buf, size 88190
>
> (post reboot)
>
> root@...alhost:~# dmesg | grep -e ramoops -e pstore
> ..
> [ 0.331540] ramoops 22b4000000.ramoops: using Device Tree
> [ 0.331560] ramoops: found existing buffer, size 88214, start 88214
> [ 0.339972] ramoops: persistent_ram_save_old: A NULL char in prz buffer
> [ 0.340775] ramoops: attached ramoops:dmesg(0/7)
> 0x80000@...2b4000000: 12 header, 524276 data, 0 ecc (0/0)
> [ 0.340789] ramoops: found existing empty buffer
> [ 0.340792] ramoops: attached ramoops:dmesg(1/7)
> 0x80000@...2b4080000: 12 header, 524276 data, 0 ecc (0/0)
> ..
> [ 0.340880] ramoops: found existing empty buffer
> [ 0.340882] ramoops: attached ramoops:dmesg(7/7)
> 0x80000@...2b4380000: 12 header, 524276 data, 0 ecc (0/0)
> [ 0.341012] pstore: Registered ramoops as persistent store backend
> [ 0.341014] ramoops: using 0x400000@...2b4000000, ecc: 0
> [ 1.164640] dyndbg=file fs/pstore/* +p
> [ 1.488770] ramoops: persistent_ram_save_old: A NULL char in prz buffer
> root@...alhost:~#
>
> root@...alhost:~# ls -l /var/lib/systemd/pstore/dmesg-ramoops-0
> -rw------- 1 root root 88190 Aug 1 17:30
> /var/lib/systemd/pstore/dmesg-ramoops-0
> root@...alhost:~#
>
> (copy and paste of the line with NULL characters from dmesg-ramoops-o
> file from a vi session)
> <5>[ 2187.111718] audit: type=1131 audit(1690911044.560:173): pid=1
> uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t
> msg='unit=xxxxxxxx-enmd-ownership
> comm="syste^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
>
> ++++++++++++++++++++++++++++++++++++++++++
>
> [4]
>
> Author: Vijay Balakrishna <vijayb@...ux.microsoft.com>
> Date: Thu Aug 3 17:23:32 2023 +0000
>
> printk: use local buffer in kmsg_dump_get_buffer()
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index b82e4c3b52f4..19080cb6c557 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3420,6 +3420,11 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper
> *dumper, bool syslog,
> size_t len = 0;
> bool ret = false;
> bool time = printk_time;
> + char *text;
> +
> + text = kmalloc(LOG_LINE_MAX + PREFIX_MAX, GFP_KERNEL);
> + if (!text)
> + return ret;
>
> if (!dumper->active || !buf || !size)
> goto out;
> @@ -3453,17 +3458,18 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper
> *dumper, bool syslog,
> */
> next_seq = seq;
>
> - prb_rec_init_rd(&r, &info, buf, size);
> + prb_rec_init_rd(&r, &info, text, LOG_LINE_MAX + PREFIX_MAX);
>
> len = 0;
> prb_for_each_record(seq, prb, seq, &r) {
> + size_t textlen;
> +
> if (r.info->seq >= dumper->next_seq)
> break;
>
> - 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);
> + textlen = record_print_text(&r, syslog, time);
> + memcpy(buf + len, text, textlen);
> + len += textlen;
> }
>
> dumper->next_seq = next_seq;
> @@ -3472,6 +3478,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper
> *dumper, bool syslog,
> out:
> if (len_out)
> *len_out = len;
> + kfree(text);
> return ret;
> }
> EXPORT_SYMBOL_GPL(kmsg_dump_get_buffer);
>
Powered by blists - more mailing lists