File makedumpfile-handle-structured-log_buf of Package makedumpfile
From: Jeff Mahoney <jeffm@suse.com>
Subject: Handle Linux >= v3.5 structured logging properly
Patch-mainline: https://sourceforge.net/tracker/?func=detail&aid=3602521&group_id=178938&atid=887142
References: bnc#801063
Linux v3.5 added structured logging which needs different handling
than the simple ring buffer used in previous revisions. Each log
entry consists of a header, text, and an optional dictionary of
key/value pairs. As a result, we need to parse the headers and
pull the text out of the records. The result is the same flat text
file everyone is used to seeing.
Signed-off-by: Jeff Mahoney <jeffm@suse.com>
---
makedumpfile.c | 398 ++++++++++++++++++++++++++++++++++++++++++++++++++-------
makedumpfile.h | 13 +
2 files changed, 363 insertions(+), 48 deletions(-)
--- a/makedumpfile.c
+++ b/makedumpfile.c
@@ -848,6 +848,8 @@ get_symbol_info(void)
SYMBOL_INIT(log_buf, "log_buf");
SYMBOL_INIT(log_buf_len, "log_buf_len");
SYMBOL_INIT(log_end, "log_end");
+ SYMBOL_INIT(log_first_idx, "log_first_idx");
+ SYMBOL_INIT(log_next_idx, "log_next_idx");
SYMBOL_INIT(max_pfn, "max_pfn");
SYMBOL_INIT(modules, "modules");
SYMBOL_INIT(high_memory, "high_memory");
@@ -1175,6 +1177,14 @@ get_structure_info(void)
OFFSET_INIT(elf64_phdr.p_paddr, "elf64_phdr", "p_paddr");
OFFSET_INIT(elf64_phdr.p_memsz, "elf64_phdr", "p_memsz");
+ /* Structure sizes for structured logging */
+ SIZE_INIT(log, "log");
+ OFFSET_INIT(log.ts_nsec, "log", "ts_nsec");
+ OFFSET_INIT(log.len, "log", "len");
+ OFFSET_INIT(log.text_len, "log", "text_len");
+ OFFSET_INIT(log.dict_len, "log", "dict_len");
+ OFFSET_INIT(log.flags, "log", "flags");
+
return TRUE;
}
@@ -1353,6 +1363,8 @@ write_vmcoreinfo_data(void)
WRITE_SYMBOL("log_buf", log_buf);
WRITE_SYMBOL("log_buf_len", log_buf_len);
WRITE_SYMBOL("log_end", log_end);
+ WRITE_SYMBOL("log_first_idx", log_first_idx);
+ WRITE_SYMBOL("log_next_idx", log_next_idx);
WRITE_SYMBOL("max_pfn", max_pfn);
WRITE_SYMBOL("high_memory", high_memory);
WRITE_SYMBOL("node_remap_start_vaddr", node_remap_start_vaddr);
@@ -1371,6 +1383,7 @@ write_vmcoreinfo_data(void)
WRITE_STRUCTURE_SIZE("node_memblk_s", node_memblk_s);
WRITE_STRUCTURE_SIZE("nodemask_t", nodemask_t);
WRITE_STRUCTURE_SIZE("pageflags", pageflags);
+ WRITE_STRUCTURE_SIZE("log", log);
/*
* write the member offset of 1st kernel
@@ -1404,6 +1417,12 @@ write_vmcoreinfo_data(void)
WRITE_MEMBER_OFFSET("node_memblk_s.nid", node_memblk_s.nid);
WRITE_MEMBER_OFFSET("vm_struct.addr", vm_struct.addr);
+ WRITE_MEMBER_OFFSET("log.ts_nsec", log.ts_nsec);
+ WRITE_MEMBER_OFFSET("log.len", log.len);
+ WRITE_MEMBER_OFFSET("log.text_len", log.text_len);
+ WRITE_MEMBER_OFFSET("log.dict_len", log.dict_len);
+ WRITE_MEMBER_OFFSET("log.flags", log.flags);
+
if (SYMBOL(node_data) != NOT_FOUND_SYMBOL)
WRITE_ARRAY_LENGTH("node_data", node_data);
if (SYMBOL(pgdat_list) != NOT_FOUND_SYMBOL)
@@ -1662,6 +1681,8 @@ read_vmcoreinfo(void)
READ_SYMBOL("log_buf", log_buf);
READ_SYMBOL("log_buf_len", log_buf_len);
READ_SYMBOL("log_end", log_end);
+ READ_SYMBOL("log_first_idx", log_first_idx);
+ READ_SYMBOL("log_next_idx", log_next_idx);
READ_SYMBOL("max_pfn", max_pfn);
READ_SYMBOL("high_memory", high_memory);
READ_SYMBOL("node_remap_start_vaddr", node_remap_start_vaddr);
@@ -1677,6 +1698,7 @@ read_vmcoreinfo(void)
READ_STRUCTURE_SIZE("node_memblk_s", node_memblk_s);
READ_STRUCTURE_SIZE("nodemask_t", nodemask_t);
READ_STRUCTURE_SIZE("pageflags", pageflags);
+ READ_STRUCTURE_SIZE("log", log);
READ_MEMBER_OFFSET("page.flags", page.flags);
READ_MEMBER_OFFSET("page._count", page._count);
@@ -1726,6 +1748,12 @@ read_vmcoreinfo(void)
READ_NUMBER("PAGE_BUDDY_MAPCOUNT_VALUE", PAGE_BUDDY_MAPCOUNT_VALUE);
+ READ_MEMBER_OFFSET("log.ts_nsec", log.ts_nsec);
+ READ_MEMBER_OFFSET("log.len", log.len);
+ READ_MEMBER_OFFSET("log.text_len", log.text_len);
+ READ_MEMBER_OFFSET("log.dict_len", log.dict_len);
+ READ_MEMBER_OFFSET("log.flags", log.flags);
+
return TRUE;
}
@@ -3444,14 +3472,310 @@ reset_bitmap_of_free_pages(unsigned long
return TRUE;
}
-int
-dump_dmesg()
+typedef void * printk_msg_t;
+#define printk_msg_len(msg) (USHORT(msg + OFFSET(log.len)))
+#define printk_msg_text_len(msg) (USHORT(msg + OFFSET(log.text_len)))
+
+enum log_flags {
+ LOG_NOCONS = 1, /* already flushed, do not print to console */
+ LOG_NEWLINE = 2, /* text ended with a newline */
+ LOG_PREFIX = 4, /* text started with a prefix */
+ LOG_CONT = 8, /* text is a fragment of a continuation line */
+};
+
+static inline uint8_t printk_msg_flags(printk_msg_t msg)
+{
+ /* This will need handling once bitfields are exported properly */
+ if (OFFSET(log.flags) != INVALID_STRUCTURE_DATA) {
+ return 0;
+ }
+ return 0;
+}
+
+/* get record by index; idx must point to valid msg */
+static printk_msg_t log_from_idx(char *log_buf, uint32_t idx)
+{
+ printk_msg_t msg = (printk_msg_t)(log_buf + idx);
+
+ /*
+ * A length == 0 record is the end of buffer marker. Wrap around and
+ * read the message at the start of the buffer.
+ */
+ if (!printk_msg_len(msg))
+ return (printk_msg_t)log_buf;
+ return msg;
+}
+
+/* get next record; idx must point to valid msg */
+static uint32_t log_next(char *log_buf, uint32_t idx)
+{
+ printk_msg_t msg = (printk_msg_t)(log_buf + idx);
+
+ /* length == 0 indicates the end of the buffer; wrap */
+ /*
+ * A length == 0 record is the end of buffer marker. Wrap around and
+ * read the message at the start of the buffer as *this* one, and
+ * return the one after that.
+ */
+ if (!printk_msg_len(msg)) {
+ msg = (printk_msg_t )log_buf;
+ return printk_msg_len(msg);
+ }
+ return idx + printk_msg_len(msg);
+}
+
+/* human readable text of the record */
+static char *printk_msg_text(const printk_msg_t msg)
+{
+ return (char *)msg + SIZE(log);
+}
+
+static size_t print_time(const printk_msg_t msg, char *logbuf)
+{
+ unsigned long rem_nsec;
+ uint64_t ts = U64(msg + OFFSET(log.ts_nsec));
+
+ if (!logbuf)
+ return 15;
+
+ rem_nsec = ts % 1000000000UL;
+ ts /= 1000000000UL;
+ return sprintf(logbuf, "[%5lu.%06lu] ",
+ (unsigned long)ts, rem_nsec / 1000);
+}
+
+static size_t msg_print_text(const printk_msg_t msg, enum log_flags prev,
+ char *logbuf, size_t size)
+{
+ const char *text = printk_msg_text(msg);
+ size_t text_size = printk_msg_text_len(msg);
+ int prefix = TRUE;
+ int newline = TRUE;
+ size_t len = 0;
+
+ if ((prev & LOG_CONT) && !(printk_msg_flags(msg) & LOG_PREFIX))
+ prefix = FALSE;
+
+ if (printk_msg_flags(msg) & LOG_CONT) {
+ if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
+ prefix = FALSE;
+
+ if (!(printk_msg_flags(msg) & LOG_NEWLINE))
+ newline = FALSE;
+ }
+
+ do {
+ const char *next = memchr(text, '\n', text_size);
+ size_t text_len;
+
+ if (next) {
+ text_len = next - text;
+ next++;
+ text_size -= next - text;
+ } else {
+ text_len = text_size;
+ }
+
+ if (print_time(msg, NULL) + text_len + 1 >= size - len)
+ break;
+
+ if (prefix)
+ len += print_time(msg, logbuf + len);
+ memcpy(logbuf + len, text, text_len);
+ len += text_len;
+ if (next || newline)
+ logbuf[len++] = '\n';
+
+ prefix = TRUE;
+ text = next;
+ } while (text);
+
+ return len;
+}
+
+static char *
+handle_structured_log(unsigned long log_buf_vaddr, int log_buf_len,
+ int *ret_buflen)
+{
+ char *log_buf, *out_buffer;
+ size_t buflen, len = 0;
+ uint32_t idx, first_idx, next_idx;
+ uint8_t flags = 0;
+ int count = 0;
+
+ if (SYMBOL(log_first_idx) == NOT_FOUND_SYMBOL) {
+ ERRMSG("Can't find log_first_idx for structured logging.\n");
+ return NULL;
+ }
+
+ if (SYMBOL(log_next_idx) == NOT_FOUND_SYMBOL) {
+ ERRMSG("Can't find log_next_idx for structured logging.\n");
+ return NULL;
+ }
+
+ if (SIZE(log) == NOT_FOUND_STRUCTURE) {
+ ERRMSG("Can't find struct log for structured logging.\n");
+ return NULL;
+ }
+
+ if (OFFSET(log.len) == INVALID_STRUCTURE_DATA) {
+ ERRMSG("Can't find struct log.len for structured logging.\n");
+ return NULL;
+ }
+
+ if (OFFSET(log.ts_nsec) == INVALID_STRUCTURE_DATA) {
+ ERRMSG("Can't find struct log.ts_nsec for structured logging.\n");
+ return NULL;
+ }
+
+ /* struct log's flags member isn't exported yet, so we can't do
+ * things like honor continuation or prefix bits */
+ if (OFFSET(log.flags) == INVALID_STRUCTURE_DATA)
+ ERRMSG("Can't find struct log.flags - dmesg output may be inconsistent.\n");
+
+ if (!readmem(VADDR, SYMBOL(log_first_idx), &first_idx,
+ sizeof(first_idx))) {
+ ERRMSG("Can't read log_first_idx. %s\n", strerror(errno));
+ return NULL;
+ }
+
+ if (!readmem(VADDR, SYMBOL(log_next_idx), &next_idx,
+ sizeof(next_idx))) {
+ ERRMSG("Can't read log_first_idx. %s\n", strerror(errno));
+ return NULL;
+ }
+
+ log_buf = malloc(log_buf_len);
+ if (!log_buf) {
+ ERRMSG("Can't allocate buffer to read kernel log. %s\n",
+ strerror(errno));
+ return NULL;
+ }
+
+ if (!readmem(VADDR, log_buf_vaddr, log_buf, log_buf_len)) {
+ ERRMSG("Can't read kernel log for structured log input. %s\n",
+ strerror(errno));
+ goto out_fail;
+ }
+
+ idx = first_idx;
+ while (idx != next_idx && len < log_buf_len) {
+ printk_msg_t msg;
+ msg = log_from_idx(log_buf, idx);
+ count++;
+ len += SIZE(log) + printk_msg_len(msg);
+ idx = log_next(log_buf, idx);
+ }
+ DEBUG_MSG("Found %d kernel log entries\n", count);
+
+ /* Buffer length + timestamps */
+ buflen = log_buf_len + 16 * count;
+ out_buffer = malloc(buflen);
+ if (!out_buffer) {
+ ERRMSG("Can't allocate memory for structured log output. %s\n",
+ strerror(errno));
+ goto out_fail;
+ }
+
+ idx = first_idx;
+ len = 0;
+ while (len < buflen && idx != next_idx) {
+ printk_msg_t msg = log_from_idx(log_buf, idx);
+ size_t textlen;
+
+ textlen = msg_print_text(msg, flags, out_buffer + len,
+ buflen - len);
+ if (textlen < 0)
+ break;
+
+ len += textlen;
+
+ flags = printk_msg_flags(msg);
+ idx = log_next(log_buf, idx);
+ }
+
+ *ret_buflen = len;
+
+ return out_buffer;
+out_fail:
+ if (out_buffer)
+ free(out_buffer);
+ if (log_buf)
+ free(log_buf);
+ return NULL;
+}
+
+static char *
+handle_unstructured_log(unsigned long log_buf_vaddr, int log_buf_len,
+ int *ret_buflen)
{
- int log_buf_len, length_log, length_oldlog, ret = FALSE;
- unsigned long log_buf, log_end, index;
+ int length_log, length_oldlog;
+ unsigned long log_end, index;
unsigned long log_end_2_6_24;
unsigned log_end_2_6_25;
+ char *log_buf = malloc(log_buf_len);
+
+ if (!log_buf) {
+ ERRMSG("Can't allocate memory for unstructured log output. %s\n",
+ strerror(errno));
+ return NULL;
+ }
+
+ if (info->kernel_version >= KERNEL_VERSION(2, 6, 25)) {
+ if (!readmem(VADDR, SYMBOL(log_end), &log_end_2_6_25,
+ sizeof(log_end_2_6_25))) {
+ ERRMSG("Can't get log_end. (>= v2.6.25)\n");
+ goto out_fail;
+ }
+ log_end = log_end_2_6_25;
+ } else {
+ if (!readmem(VADDR, SYMBOL(log_end), &log_end_2_6_24,
+ sizeof(log_end_2_6_24))) {
+ ERRMSG("Can't get log_end. (< v2.6.25)\n");
+ goto out_fail;
+ }
+ log_end = log_end_2_6_24;
+ }
+ DEBUG_MSG("log_end : %lx\n", log_end);
+
+ if (log_end < log_buf_len) {
+ length_log = log_end;
+ if(!readmem(VADDR, log_buf_vaddr, log_buf, length_log)) {
+ ERRMSG("Can't read dmesg log.\n");
+ goto out_fail;
+ }
+ } else {
+ index = log_end & (log_buf_len - 1);
+ DEBUG_MSG("index : %lx\n", index);
+ length_log = log_buf_len;
+ length_oldlog = log_buf_len - index;
+ if(!readmem(VADDR, log_buf_vaddr + index,
+ log_buf, length_oldlog)) {
+ ERRMSG("Can't read old dmesg log.\n");
+ goto out_fail;
+ }
+ if(!readmem(VADDR, log_buf_vaddr, log_buf + length_oldlog,
+ index)) {
+ ERRMSG("Can't read new dmesg log.\n");
+ goto out_fail;
+ }
+ }
+
+ *ret_buflen = length_log;
+ return log_buf;
+out_fail:
+ free(log_buf);
+ return NULL;
+}
+
+int
+dump_dmesg()
+{
+ int length_log = 0;
+ int ret = FALSE;
char *log_buffer = NULL;
+ unsigned long log_buf;
+ int log_buf_len;
/*
* log_end has been changed to "unsigned" since linux-2.6.25.
@@ -3468,67 +3792,45 @@ dump_dmesg()
if (!initial())
return FALSE;
- if ((SYMBOL(log_buf) == NOT_FOUND_SYMBOL)
- || (SYMBOL(log_buf_len) == NOT_FOUND_SYMBOL)
- || (SYMBOL(log_end) == NOT_FOUND_SYMBOL)) {
- ERRMSG("Can't find some symbols for log_buf.\n");
+ if (SYMBOL(log_buf) == NOT_FOUND_SYMBOL) {
+ ERRMSG("Can't find log_buf for dmesg dumping.\n");
+ return FALSE;
+ }
+
+ if (SYMBOL(log_buf_len) == NOT_FOUND_SYMBOL) {
+ ERRMSG("Can't find log_buf_len for dmesg dumping.\n");
return FALSE;
}
+
if (!readmem(VADDR, SYMBOL(log_buf), &log_buf, sizeof(log_buf))) {
ERRMSG("Can't get log_buf.\n");
return FALSE;
}
- if (info->kernel_version >= KERNEL_VERSION(2, 6, 25)) {
- if (!readmem(VADDR, SYMBOL(log_end), &log_end_2_6_25,
- sizeof(log_end_2_6_25))) {
- ERRMSG("Can't to get log_end.\n");
- return FALSE;
- }
- log_end = log_end_2_6_25;
- } else {
- if (!readmem(VADDR, SYMBOL(log_end), &log_end_2_6_24,
- sizeof(log_end_2_6_24))) {
- ERRMSG("Can't to get log_end.\n");
- return FALSE;
- }
- log_end = log_end_2_6_24;
- }
+
if (!readmem(VADDR, SYMBOL(log_buf_len), &log_buf_len,
sizeof(log_buf_len))) {
ERRMSG("Can't get log_buf_len.\n");
return FALSE;
}
+
DEBUG_MSG("\n");
DEBUG_MSG("log_buf : %lx\n", log_buf);
- DEBUG_MSG("log_end : %lx\n", log_end);
DEBUG_MSG("log_buf_len : %d\n", log_buf_len);
- if ((log_buffer = malloc(log_buf_len)) == NULL) {
- ERRMSG("Can't allocate memory for log_buf. %s\n",
- strerror(errno));
+ if (SYMBOL(log_end) != NOT_FOUND_SYMBOL)
+ log_buffer = handle_unstructured_log(log_buf, log_buf_len,
+ &length_log);
+ else if (SYMBOL(log_first_idx) != NOT_FOUND_SYMBOL)
+ /* Kernels v3.2 and newer use structured logging */
+ log_buffer = handle_structured_log(log_buf, log_buf_len,
+ &length_log);
+ else
+ ERRMSG("Can't find log_end or log_first_idx. "
+ "Can't read log.\n");
+
+ if (!log_buffer)
return FALSE;
- }
- if (log_end < log_buf_len) {
- length_log = log_end;
- if(!readmem(VADDR, log_buf, log_buffer, length_log)) {
- ERRMSG("Can't read dmesg log.\n");
- goto out;
- }
- } else {
- index = log_end & (log_buf_len - 1);
- DEBUG_MSG("index : %lx\n", index);
- length_log = log_buf_len;
- length_oldlog = log_buf_len - index;
- if(!readmem(VADDR, log_buf + index, log_buffer, length_oldlog)) {
- ERRMSG("Can't read old dmesg log.\n");
- goto out;
- }
- if(!readmem(VADDR, log_buf, log_buffer + length_oldlog, index)) {
- ERRMSG("Can't read new dmesg log.\n");
- goto out;
- }
- }
DEBUG_MSG("length_log : %d\n", length_log);
if (!open_dump_file()) {
--- a/makedumpfile.h
+++ b/makedumpfile.h
@@ -216,9 +216,11 @@ isAnon(unsigned long mapping)
#define STRNEQ(A, B) (A && B && \
(strncmp((char *)(A), (char *)(B), strlen((char *)(B))) == 0))
+#define UCHAR(ADDR) *((unsigned char *)(ADDR))
#define USHORT(ADDR) *((unsigned short *)(ADDR))
#define UINT(ADDR) *((unsigned int *)(ADDR))
#define ULONG(ADDR) *((unsigned long *)(ADDR))
+#define U64(ADDR) *((uint64_t *)(ADDR))
/*
* for symbol
@@ -1090,6 +1092,8 @@ struct symbol_table {
unsigned long long log_buf;
unsigned long long log_buf_len;
unsigned long long log_end;
+ unsigned long long log_first_idx;
+ unsigned long long log_next_idx;
unsigned long long max_pfn;
unsigned long long node_remap_start_vaddr;
unsigned long long node_remap_end_vaddr;
@@ -1171,6 +1175,7 @@ struct size_table {
long elf64_hdr;
long pageflags;
+ long log;
};
struct offset_table {
@@ -1302,6 +1307,14 @@ struct offset_table {
long p_paddr;
long p_memsz;
} elf64_phdr;
+
+ struct log {
+ long ts_nsec;
+ long len;
+ long text_len;
+ long dict_len;
+ long flags;
+ } log;
};
/*
