Re: pstore/ram: printk: NULL characters in pstore ramoops area
From: Vijay Balakrishna
Date: Mon Aug 07 2023 - 13:19:39 EST
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;
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@localhost:~# 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@localhost:~#
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:~#
++++++++++++++++++++++++++++++++++++++++++
[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@localhost:~# 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@localhost:~# 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@0x22b4000000: 12 header, 524276 data, 0 ecc (0/0)
[ 0.340789] ramoops: found existing empty buffer
[ 0.340792] ramoops: attached ramoops:dmesg(1/7)
0x80000@0x22b4080000: 12 header, 524276 data, 0 ecc (0/0)
..
[ 0.340880] ramoops: found existing empty buffer
[ 0.340882] ramoops: attached ramoops:dmesg(7/7)
0x80000@0x22b4380000: 12 header, 524276 data, 0 ecc (0/0)
[ 0.341012] pstore: Registered ramoops as persistent store backend
[ 0.341014] ramoops: using 0x400000@0x22b4000000, ecc: 0
[ 1.164640] dyndbg=file fs/pstore/* +p
[ 1.488770] ramoops: persistent_ram_save_old: A NULL char in prz buffer
root@localhost:~#
root@localhost:~# 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@localhost:~#
(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@xxxxxxxxxxxxxxxxxxx>
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);