Messages in this thread Patch in this message | | | Date | Mon, 7 Aug 2023 10:19:07 -0700 | Subject | Re: pstore/ram: printk: NULL characters in pstore ramoops area | From | Vijay Balakrishna <> |
| |
I'm including my earlier email as it didn't deliver to linux-kernel@vger.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@linux.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@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@linux.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); >
| |