________________________________________ From: crash-utility-bounces(a)redhat.com <crash-utility-bounces(a)redhat.com&gt; on behalf of shogo.matsumoto(a)fujitsu.com <shogo.matsumoto(a)fujitsu.com&gt; Sent: Thursday, December 16, 2021 16:39 To: &#39;crash-utility(a)redhat.com&#39; Subject: [Crash-utility] [PATCH] log: output logs of printk safe buffers We sometimes overlook logs written to printk safe buffers (safe_print_seq/nmi_print_seq) which have not been flushed yet. This patch will output unflushed logs of the safe buffers at the bottom of log command output as follows: [nmi_print_seq] CPU: 0 BUFFER: ffff888063c18ac0 LEN: 28 nmi print seq test message [safe_print_seq] CPU: 1 BUFFER: ffff888063d19ae0 LEN: 30 safe print seq test message

Note that the safe buffer (struct printk_safe_seq_buf) was introduced in kernel-4.11 and removed in kernel-5.15.

Signed-off-by: Shogo Matsumoto <shogo.matsumoto(a)fujitsu.com&gt; --- defs.h | 3 +++ kernel.c | 58 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 61 insertions(+) diff --git a/defs.h b/defs.h index 7e2a16e..3ee51e0 100644 --- a/defs.h +++ b/defs.h @@ -2146,6 +2146,8 @@ struct offset_table { /* stash of commonly-used offsets */ long wait_queue_entry_private; long wait_queue_head_head; long wait_queue_entry_entry; + long printk_safe_seq_buf_len; + long printk_safe_seq_buf_buffer; }; struct size_table { /* stash of commonly-used sizes */ @@ -2310,6 +2312,7 @@ struct size_table { /* stash of commonly-used sizes */ long prb_desc; long wait_queue_entry; long task_struct_state; + long printk_safe_seq_buf_buffer; };

struct array_table { diff --git a/kernel.c b/kernel.c index f4598ea..cc97176 100644 --- a/kernel.c +++ b/kernel.c @@ -93,6 +93,7 @@ static void source_tree_init(void); static ulong dump_audit_skb_queue(ulong); static ulong __dump_audit(char *); static void dump_audit(void); +static void dump_printk_safe_seq_buf(void); static char *vmcoreinfo_read_string(const char *); static void check_vmcoreinfo(void); static int is_pvops_xen(void); @@ -5048,6 +5049,7 @@ cmd_log(void) } dump_log(msg_flags); + dump_printk_safe_seq_buf(); } @@ -11534,6 +11536,62 @@ dump_audit(void) error(INFO, "kernel audit log is empty\n"); } +static void +__dump_printk_safe_seq_buf(char *buf_name) +{ + int cpu, buffer_size; + char *buffer; + + if (!symbol_exists(buf_name)) { + return; + } + + buffer_size = SIZE(printk_safe_seq_buf_buffer); + buffer = GETBUF(buffer_size); + for (cpu = 0; cpu < kt->cpus; cpu++) { + ulong len_addr, buffer_addr; + int len; + + len_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + OFFSET(printk_safe_seq_buf_len); + buffer_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + OFFSET(printk_safe_seq_buf_buffer); + readmem(len_addr, KVADDR, &len, STRUCT_SIZE("atomic_t"), "printk_safe_seq_buf len", FAULT_ON_ERROR); + readmem(buffer_addr, KVADDR, buffer, buffer_size, "printk_safe_seq_buf buffer", FAULT_ON_ERROR); + + if (len > 0) { + int i, n; + char *p; + fprintf(fp, "[%s] CPU: %d BUFFER: %lx LEN: %d\n", buf_name, cpu, buffer_addr, len); + n = (len <= buffer_size) ? len : buffer_size; + for (i = 0, p = buffer; i < n; i++, p++) { + if (*p == 0x1) { //SOH + i++; p++; + continue; + } else { + fputc(ascii(*p) ? *p : '.', fp); + } + } + fputc('\n', fp); + } + } + FREEBUF(buffer); +} + +static void +dump_printk_safe_seq_buf(void) +{ + if (!STRUCT_EXISTS("printk_safe_seq_buf")) + return; + + if (INVALID_SIZE(printk_safe_seq_buf_buffer)) { + MEMBER_OFFSET_INIT(printk_safe_seq_buf_len, "printk_safe_seq_buf", "len"); + MEMBER_OFFSET_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer"); + MEMBER_SIZE_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer"); + } + + __dump_printk_safe_seq_buf("nmi_print_seq"); + __dump_printk_safe_seq_buf("safe_print_seq"); +} + /* * Reads a string value from the VMCOREINFO data stored in (live) memory. *

-----Original Message----- From: HAGIO KAZUHITO(萩尾　一仁) <k-hagio-ab(a)nec.com&gt; Sent: Tuesday, January 4, 2022 11:31 AM To: Matsumoto, Shogo <shogo.matsumoto(a)fujitsu.com>; Discussion list for crash utility usage, maintenance and development <crash-utility(a)redhat.com&gt; Subject: RE: [Crash-utility] [PATCH] log: output logs of printk safe buffers Hi Matsumoto-san, thanks for the patch, only minor respects below: -----Original Message----- > We sometimes overlook logs written to printk safe buffers > (safe_print_seq/nmi_print_seq) which have not been flushed yet. > > This patch will output unflushed logs of the safe buffers > at the bottom of log command output as follows: > > [nmi_print_seq] CPU: 0 BUFFER: ffff888063c18ac0 LEN: 28 > nmi print seq test message > [safe_print_seq] CPU: 1 BUFFER: ffff888063d19ae0 LEN: 30 > safe print seq test message > > Note that the safe buffer (struct printk_safe_seq_buf) was introduced > in kernel-4.11 and removed in kernel-5.15. > > Signed-off-by: Shogo Matsumoto <shogo.matsumoto(a)fujitsu.com&gt; > --- > defs.h | 3 +++ > kernel.c | 58 +++++++++++++++++++++++++++++++++++++++++++++++++++ +++++ > 2 files changed, 61 insertions(+) > > diff --git a/defs.h b/defs.h > index 7e2a16e..3ee51e0 100644 > --- a/defs.h > +++ b/defs.h > @@ -2146,6 +2146,8 @@ struct offset_table { /* stash of commonly-used offsets */ > long wait_queue_entry_private; > long wait_queue_head_head; > long wait_queue_entry_entry; > + long printk_safe_seq_buf_len; > + long printk_safe_seq_buf_buffer; > }; > > struct size_table { /* stash of commonly-used sizes */ > @@ -2310,6 +2312,7 @@ struct size_table { /* stash of commonly-used sizes */ > long prb_desc; > long wait_queue_entry; > long task_struct_state; > + long printk_safe_seq_buf_buffer; > }; > > struct array_table { > diff --git a/kernel.c b/kernel.c > index f4598ea..cc97176 100644 > --- a/kernel.c > +++ b/kernel.c > @@ -93,6 +93,7 @@ static void source_tree_init(void); > static ulong dump_audit_skb_queue(ulong); > static ulong __dump_audit(char *); > static void dump_audit(void); > +static void dump_printk_safe_seq_buf(void); > static char *vmcoreinfo_read_string(const char *); > static void check_vmcoreinfo(void); > static int is_pvops_xen(void); > @@ -5048,6 +5049,7 @@ cmd_log(void) > } > > dump_log(msg_flags); > + dump_printk_safe_seq_buf(); > } > > > @@ -11534,6 +11536,62 @@ dump_audit(void) > error(INFO, "kernel audit log is empty\n"); > } > > +static void > +__dump_printk_safe_seq_buf(char *buf_name) > +{ > + int cpu, buffer_size; > + char *buffer; > + > + if (!symbol_exists(buf_name)) { > + return; > + } > + > + buffer_size = SIZE(printk_safe_seq_buf_buffer); > + buffer = GETBUF(buffer_size); > + for (cpu = 0; cpu < kt->cpus; cpu++) { > + ulong len_addr, buffer_addr; > + int len; > + > + len_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + > OFFSET(printk_safe_seq_buf_len); I'd like to move the symbol_value() out of the loop. and more exactly, OFFSET(atomic_t_counter) needs to be added, although it's zero. > + buffer_addr = symbol_value(buf_name) + kt->__per_cpu_offset[cpu] + > OFFSET(printk_safe_seq_buf_buffer); > + readmem(len_addr, KVADDR, &len, STRUCT_SIZE("atomic_t"), "printk_safe_seq_buf len", > FAULT_ON_ERROR); I think sizeof(int) is better than STRUCT_SIZE("atomic_t"). Thanks, Kazu > + readmem(buffer_addr, KVADDR, buffer, buffer_size, "printk_safe_seq_buf buffer", > FAULT_ON_ERROR); > + > + if (len > 0) { > + int i, n; > + char *p; > + fprintf(fp, "[%s] CPU: %d BUFFER: %lx LEN: %d\n", buf_name, cpu, buffer_addr, len); > + n = (len <= buffer_size) ? len : buffer_size; > + for (i = 0, p = buffer; i < n; i++, p++) { > + if (*p == 0x1) { //SOH > + i++; p++; > + continue; > + } else { > + fputc(ascii(*p) ? *p : '.', fp); > + } > + } > + fputc('\n', fp); > + } > + } > + FREEBUF(buffer); > +} > + > +static void > +dump_printk_safe_seq_buf(void) > +{ > + if (!STRUCT_EXISTS("printk_safe_seq_buf")) > + return; > + > + if (INVALID_SIZE(printk_safe_seq_buf_buffer)) { > + MEMBER_OFFSET_INIT(printk_safe_seq_buf_len, "printk_safe_seq_buf", "len"); > + MEMBER_OFFSET_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer"); > + MEMBER_SIZE_INIT(printk_safe_seq_buf_buffer, "printk_safe_seq_buf", "buffer"); > + } > + > + __dump_printk_safe_seq_buf("nmi_print_seq"); > + __dump_printk_safe_seq_buf("safe_print_seq"); > +} > + > /* > * Reads a string value from the VMCOREINFO data stored in (live) memory. > * > -- > 2.29.2 > > > > -- > Crash-utility mailing list > Crash-utility(a)redhat.com > https://listman.redhat.com/mailman/listinfo/crash-utility