9:29 p.m.
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>
---
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");
=====