From 093a20f2bdc6024d77e6c09d8577af006e211bc63151b2d51a06fe173dc790f3 Mon Sep 17 00:00:00 2001 From: David Mair Date: Thu, 7 Feb 2013 16:20:49 +0000 Subject: [PATCH] Accepting request 150311 from home:jeff_mahoney:branches:Kernel:kdump - Added support for structured logging added in Linux v3.5. (bnc#801063) OBS-URL: https://build.opensuse.org/request/show/150311 OBS-URL: https://build.opensuse.org/package/show/Kernel:kdump/makedumpfile?expand=0&rev=64 --- makedumpfile-handle-structured-log_buf | 555 +++++++++++++++++++++++++ makedumpfile.changes | 5 + makedumpfile.spec | 4 +- 3 files changed, 563 insertions(+), 1 deletion(-) create mode 100644 makedumpfile-handle-structured-log_buf diff --git a/makedumpfile-handle-structured-log_buf b/makedumpfile-handle-structured-log_buf new file mode 100644 index 0000000..d19545a --- /dev/null +++ b/makedumpfile-handle-structured-log_buf @@ -0,0 +1,555 @@ +From: Jeff Mahoney +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 +--- + 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; + }; + + /* diff --git a/makedumpfile.changes b/makedumpfile.changes index fd8bbc1..2d8e870 100644 --- a/makedumpfile.changes +++ b/makedumpfile.changes @@ -1,3 +1,8 @@ +------------------------------------------------------------------- +Mon Jan 28 22:46:29 UTC 2013 - jeffm@suse.com + +- Added support for structured logging added in Linux v3.5. (bnc#801063) + ------------------------------------------------------------------- Fri Dec 7 15:58:28 UTC 2012 - ptesarik@suse.cz diff --git a/makedumpfile.spec b/makedumpfile.spec index f16d06e..bafa209 100644 --- a/makedumpfile.spec +++ b/makedumpfile.spec @@ -1,7 +1,7 @@ # # spec file for package makedumpfile # -# Copyright (c) 2012 SUSE LINUX Products GmbH, Nuernberg, Germany. +# Copyright (c) 2013 SUSE LINUX Products GmbH, Nuernberg, Germany. # # All modifications and additions to the file contributed by third parties # remain the property of their copyright owners, unless otherwise agreed @@ -37,6 +37,7 @@ Url: https://sourceforge.net/projects/makedumpfile/ Source: %{name}-%{version}.tar.bz2 Source1: README.static Patch0: %{name}-coptflags.diff +Patch1: %{name}-handle-structured-log_buf BuildRoot: %{_tmppath}/%{name}-%{version}-build ExclusiveArch: %ix86 x86_64 ia64 ppc64 s390x %arm @@ -55,6 +56,7 @@ Authors: %prep %setup -q %patch0 -p1 +%patch1 -p1 %build LIBS_STATIC=