Re: [Crash-utility] [PATCH v2] 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 LEN: 188 MESSAGE_LOST: 0 WORK: ffff8c31fbc19ce8 BUFFER: ffff8c31fbc19d00 message2 message2 message2 message2 Uhhuh. NMI received for unknown reason 30 on CPU 0. Do you have a strange power saving mode enabled? Dazed and confused, but trying to continue [safe_print_seq] CPU: 1 LEN: 38 MESSAGE_LOST: 0 WORK: ffff8c31fbc9ad08 BUFFER: ffff8c31fbc9ad20 message1 message1 message1 message1

Note that the safe buffer (struct printk_safe_seq_buf) was introduced in kernel-4.11 (f92bac3b141b8233e34ddf32d227e12bfba07b48, 099f1c84c0052ec1b27f1c3942eed5830d86bdbb, ddb9baa822265b55afffd9815a2758a4b70006c1)

and removed in kernel-5.15 (93d102f094be9beab28e5afb656c188b16a3793b). v2 Changes: - add all members of struct printk_safe_seq_buf - support help -o - consider OFFSET(atomic_t_counter) for atomic_t member - some code refactoring Signed-off-by: Shogo Matsumoto <shogo.matsumoto(a)fujitsu.com&gt; --- defs.h | 5 ++++ kernel.c | 87 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ symbols.c | 6 ++++ 3 files changed, 98 insertions(+) diff --git a/defs.h b/defs.h index b63741c..f590910 100644 --- a/defs.h +++ b/defs.h @@ -2146,6 +2146,10 @@ 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_message_lost; + long printk_safe_seq_buf_work; + long printk_safe_seq_buf_buffer; }; struct size_table { /* stash of commonly-used sizes */ @@ -2310,6 +2314,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 37b7af7..b2a597c 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(); } @@ -11544,6 +11546,91 @@ 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; + ulong len_addr, message_lost_addr, work_addr, buffer_addr; + + if (!symbol_exists(buf_name)) { + return; + } + + len_addr = symbol_value(buf_name) + OFFSET(printk_safe_seq_buf_len) + + OFFSET(atomic_t_counter); + message_lost_addr = symbol_value(buf_name) + + OFFSET(printk_safe_seq_buf_message_lost) + + OFFSET(atomic_t_counter); + work_addr = symbol_value(buf_name) + OFFSET(printk_safe_seq_buf_work); + buffer_addr = symbol_value(buf_name) + OFFSET(printk_safe_seq_buf_buffer); + + buffer_size = SIZE(printk_safe_seq_buf_buffer); + buffer = GETBUF(buffer_size); + for (cpu = 0; cpu < kt->cpus; cpu++) { + int len; + ulong per_cpu_offset; + per_cpu_offset = kt->__per_cpu_offset[cpu]; + + readmem(len_addr + per_cpu_offset, KVADDR, &len, sizeof(int), + "printk_safe_seq_buf len", FAULT_ON_ERROR); + + if (len > 0) { + int message_lost; + int i, n; + char *p; + + readmem(message_lost_addr + per_cpu_offset, KVADDR, + &message_lost, sizeof(int), + "printk_safe_seq_buf message_lost", FAULT_ON_ERROR); + readmem(buffer_addr + per_cpu_offset, KVADDR, + buffer, buffer_size, + "printk_safe_seq_buf buffer", FAULT_ON_ERROR); + + fprintf(fp, "[%s] CPU: %d LEN: %d MESSAGE_LOST: %d" + " WORK: %lx BUFFER: %lx\n", + buf_name, cpu, len, message_lost, + work_addr + per_cpu_offset, + buffer_addr + per_cpu_offset);

+ + 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_message_lost, + "printk_safe_seq_buf", "message_lost"); + MEMBER_OFFSET_INIT(printk_safe_seq_buf_work, + "printk_safe_seq_buf", "work"); + 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. * diff --git a/symbols.c b/symbols.c index 73baa95..5c575a9 100644 --- a/symbols.c +++ b/symbols.c @@ -10523,6 +10523,11 @@ dump_offset_table(char *spec, ulong makestruct) fprintf(fp, " prb_data_ring_size_bits: %ld\n", OFFSET(prb_data_ring_size_bits)); fprintf(fp, " prb_data_ring_data: %ld\n", OFFSET(prb_data_ring_data)); fprintf(fp, " atomit_long_t_counter: %ld\n", OFFSET(atomic_long_t_counter)); + fprintf(fp, " printk_safe_seq_buf_len: %ld\n", OFFSET(printk_safe_seq_buf_len)); + fprintf(fp, "printk_safe_seq_buf_message_lost: %ld\n", + OFFSET(printk_safe_seq_buf_message_lost)); + fprintf(fp, " printk_safe_seq_buf_work: %ld\n", OFFSET(printk_safe_seq_buf_work)); + fprintf(fp, " printk_safe_seq_buf_buffer: %ld\n", OFFSET(printk_safe_seq_buf_buffer)); fprintf(fp, " sched_rt_entity_my_q: %ld\n", OFFSET(sched_rt_entity_my_q)); @@ -10954,6 +10959,7 @@ dump_offset_table(char *spec, ulong makestruct) fprintf(fp, " printk_info: %ld\n", SIZE(printk_info)); fprintf(fp, " printk_ringbuffer: %ld\n", SIZE(printk_ringbuffer)); fprintf(fp, " prb_desc: %ld\n", SIZE(prb_desc)); + fprintf(fp, " printk_safe_seq_buf_buffer: %ld\n", SIZE(printk_safe_seq_buf_buffer)); fprintf(fp, "\n array_table:\n"); -- 2.26.2 I also attach a test module printk_safe_buf_test.c which I used to test this patch. How to use: 1. Load the test module 2. Generate a NMI interrupt 3. Start crash on a live system and execute log command I tested with the module in Fedora 32 (5.6.8-300.fc32.x86_64) and CentOS 8 (4.18.0-348.el8.x86_64). kallsyms_lookup_name should be replaced with the specific address if kernel >= 5.7 is used. printk_safe_buf_test.c: ===== #include <linux/module.h> #include <linux/kprobes.h> #include <linux/irq_work.h> #include <linux/nmi.h> static int msg1_line = 0; static int output_msg1(struct kprobe *p, struct pt_regs *regs) { if (msg1_line++ < 1) printk(KERN_INFO "message1 message1 message1 message1\n"); return 0; } static int output_msg2(unsigned int cmd, struct pt_regs *regs) { int i; for (i = 0; i < 1; i++) printk(KERN_INFO "message2 message2 message2 message2\n"); return 0; } static void empty_work(struct irq_work *work) { } static struct kprobe kp = { .symbol_name = "__printk_safe_exit", .pre_handler = output_msg1, }; static int __init printk_safe_buf_test_init(void) { int i, ret = 0; ulong safe_print_seq, nmi_print_seq, per_cpu_offset; struct dummy_printk_safe_seq_buf { atomic_t len; atomic_t message_lost; struct irq_work work; }; safe_print_seq = kallsyms_lookup_name("safe_print_seq"); nmi_print_seq = kallsyms_lookup_name("nmi_print_seq"); per_cpu_offset = kallsyms_lookup_name("__per_cpu_offset"); if (!(safe_print_seq && nmi_print_seq && per_cpu_offset)) return -1; for (i = 0; i < num_possible_cpus(); i++) { ulong offset = ((ulong*)per_cpu_offset)[i]; init_irq_work(&((struct dummy_printk_safe_seq_buf*)(offset + safe_print_seq))->work, empty_work); init_irq_work(&((struct dummy_printk_safe_seq_buf*)(offset + nmi_print_seq))->work, empty_work); } ret = register_kprobe(&kp); if (ret < 0) { pr_err("register kp failed%d\n", ret); return ret; } register_nmi_handler(NMI_LOCAL, output_msg2, 0, "output_msg2"); return 0; } static void __exit printk_safe_buf_test_exit(void) { unregister_nmi_handler(NMI_LOCAL, "output_msg2"); unregister_kprobe(&kp); return; } module_init(printk_safe_buf_test_init); module_exit(printk_safe_buf_test_exit); MODULE_LICENSE("GPL"); =====