From 2b938b78aa5375b063ec32e0037f6b4114aa4495 Mon Sep 17 00:00:00 2001 From: Alexander Egorenkov Date: Thu, 2 Sep 2021 15:08:35 +0200 Subject: [PATCH] zdump: Introduce multi-level message logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Use util_log from libutil to output various log messages that can be helpful during problem analysis. Signed-off-by: Alexander Egorenkov Signed-off-by: Jan Höppner --- zdump/dfi.c | 38 +++++++++++++++++++++++++++++++++++++- zdump/dfi_elf.c | 15 +++++++++++++++ zdump/dfi_s390.c | 11 +++++++++++ zdump/dfi_vmcoreinfo.c | 10 ++++++++++ zdump/opts.c | 12 ++++++++++-- zdump/zgetdump.h | 2 +- 6 files changed, 84 insertions(+), 4 deletions(-) diff --git a/zdump/dfi.c b/zdump/dfi.c index 97488917..d9cce30d 100644 --- a/zdump/dfi.c +++ b/zdump/dfi.c @@ -10,6 +10,8 @@ */ #include + +#include "lib/util_log.h" #include "zgetdump.h" #define TIME_FMT_STR "%a, %d %b %Y %H:%M:%S %z" @@ -160,7 +162,7 @@ static void mem_map_print(void) /* * Print each memory chunk if verbose specified */ - if (g.opts.verbose_specified) { + if (g.opts.verbose) { dfi_mem_chunk_iterate(mem_chunk) { zero_str = ""; if (mem_chunk->read_fn == dfi_mem_chunk_read_zero) @@ -391,6 +393,11 @@ void dfi_mem_chunk_virt_add(u64 start, u64 size, void *data, dfi_mem_chunk_read_fn read_fn, dfi_mem_chunk_free_fn free_fn) { + util_log_print(UTIL_LOG_DEBUG, + "DFI add %svirt mem chunk start 0x%016lx size 0x%016lx\n", + read_fn == dfi_mem_chunk_read_zero ? "zero " : "", + start, size); + if (size == 0) return; mem_chunk_create(&l.mem_virt, start, size, data, read_fn, free_fn); @@ -404,6 +411,11 @@ void dfi_mem_chunk_add_vol(u64 start, u64 size, void *data, dfi_mem_chunk_free_fn free_fn, u32 volnr) { + util_log_print(UTIL_LOG_DEBUG, + "DFI add %svol mem chunk start 0x%016lx size 0x%016lx volnr %u\n", + read_fn == dfi_mem_chunk_read_zero ? "zero " : "", + start, size, volnr); + if (size == 0) return; mem_chunk_create(&l.mem_phys, start, size, data, read_fn, free_fn); @@ -605,6 +617,9 @@ struct util_list *dfi_cpu_list(void) */ void dfi_mem_read(u64 addr, void *buf, size_t cnt) { + util_log_print(UTIL_LOG_TRACE, + "DFI virt mem read addr 0x%016lx size 0x%016lx\n", + addr, cnt); mem_read(&l.mem_virt, addr, buf, cnt); } @@ -613,6 +628,9 @@ void dfi_mem_read(u64 addr, void *buf, size_t cnt) */ void dfi_mem_phys_read(u64 addr, void *buf, size_t cnt) { + util_log_print(UTIL_LOG_TRACE, + "DFI phys mem read addr 0x%016lx size 0x%016lx\n", + addr, cnt); mem_read(&l.mem_phys, addr, buf, cnt); } @@ -1074,6 +1092,8 @@ static void kdump_init(void) { unsigned long base, size; + util_log_print(UTIL_LOG_TRACE, "DFI kdump initialization\n"); + if (!dfi_mem_range_valid(0x10418, sizeof(base))) return; if (!dfi_mem_range_valid(0x10420, sizeof(size))) @@ -1088,6 +1108,9 @@ static void kdump_init(void) return; l.kdump_base = base; l.kdump_size = size; + util_log_print(UTIL_LOG_INFO, + "DFI found valid kdump base 0x%016lx size 0x%016lx\n", + l.kdump_base, l.kdump_size); /* * For dumped kdump and user has selected "prod" we swap * the crashkernel memory with old memory. If user selected "kdump", @@ -1150,6 +1173,8 @@ static void utsname_init(void) unsigned long ptr; char buf[1024]; + util_log_print(UTIL_LOG_TRACE, "DFI utsname initialization\n"); + if (dfi_vmcoreinfo_symbol(&ptr, "init_uts_ns")) return; if (dfi_mem_read_rc(ptr, buf, sizeof(buf))) @@ -1160,6 +1185,8 @@ static void utsname_init(void) if (strncmp(utsname->sysname, "Linux", sizeof(utsname->version)) != 0) return; dfi_attr_utsname_set(utsname); + util_log_print(UTIL_LOG_INFO, "DFI utsname release %s version %s\n", + utsname->release, utsname->version); } /* @@ -1169,6 +1196,8 @@ static void livedump_init(void) { u64 magic; + util_log_print(UTIL_LOG_TRACE, "DFI livedump initialization\n"); + if (dfi_mem_read_rc(0, &magic, sizeof(magic))) return; if (magic == dfi_live_dump_magic) @@ -1205,12 +1234,15 @@ int dfi_init(void) struct dfi *dfi; int i = 0, rc; + util_log_print(UTIL_LOG_TRACE, "DFI initialization\n"); + l.arch = DFI_ARCH_UNKNOWN; mem_init(&l.mem_virt); mem_init(&l.mem_phys); attr_init(); dfi_cpu_info_init(DFI_CPU_CONTENT_NONE); while ((dfi = dfi_vec[i])) { + util_log_print(UTIL_LOG_DEBUG, "DFI trying %s\n", dfi->name); l.dfi = dfi; g.fh = dfi_dump_open(g.opts.device); rc = dfi->init(); @@ -1222,6 +1254,8 @@ int dfi_init(void) utsname_init(); livedump_init(); } + util_log_print(UTIL_LOG_DEBUG, "DFI %s returned with rc %d\n", + dfi->name, rc); if (rc == 0 || rc == -EINVAL) return rc; zg_close(g.fh); @@ -1235,6 +1269,8 @@ int dfi_init(void) */ void dfi_exit(void) { + util_log_print(UTIL_LOG_TRACE, "DFI exit\n"); + if (l.dfi && l.dfi->exit) l.dfi->exit(); } diff --git a/zdump/dfi_elf.c b/zdump/dfi_elf.c index 18c8eb13..f6f616aa 100644 --- a/zdump/dfi_elf.c +++ b/zdump/dfi_elf.c @@ -17,6 +17,7 @@ #include #include "lib/util_libc.h" +#include "lib/util_log.h" #include "zgetdump.h" /* @@ -38,6 +39,11 @@ static int pt_load_add(Elf64_Phdr *phdr) { u64 *off_ptr; + util_log_print(UTIL_LOG_DEBUG, + "DFI ELF p_paddr 0x%016lx p_vaddr 0x%016lx p_offset 0x%016lx p_filesz 0x%016lx p_memsz 0x%016lx\n", + phdr->p_paddr, phdr->p_vaddr, phdr->p_offset, + phdr->p_filesz, phdr->p_memsz); + if (phdr->p_paddr != phdr->p_vaddr) { phdr->p_paddr = phdr->p_vaddr; STDERR("Dump file \"%s\" is a user space core dump\n", @@ -80,6 +86,8 @@ static int nt_read(Elf64_Nhdr *note, void *buf) off_t buf_len = ROUNDUP(note->n_descsz, 4); char tmp_buf[buf_len]; + util_log_print(UTIL_LOG_TRACE, "DFI ELF n_descsz %u\n", buf_len); + nt_name_skip(note); if (zg_read(g.fh, tmp_buf, buf_len, ZG_CHECK_ERR) != buf_len) return -EINVAL; @@ -220,6 +228,8 @@ static int pt_notes_add(Elf64_Phdr *phdr) rc = zg_read(g.fh, ¬e, sizeof(note), ZG_CHECK_ERR); if (rc != sizeof(note)) return -EINVAL; + util_log_print(UTIL_LOG_DEBUG, "DFI ELF n_type 0x%x\n", + note.n_type); switch (note.n_type) { case NT_PRSTATUS: cpu_current = nt_prstatus_read(¬e); @@ -295,6 +305,8 @@ static int dfi_elf_init(void) Elf64_Phdr *phdr; int i; + util_log_print(UTIL_LOG_DEBUG, "DFI ELF initialization\n"); + if (read_elf_hdr(&ehdr) != 0) return -ENODEV; @@ -305,7 +317,10 @@ static int dfi_elf_init(void) phdr = util_malloc(sizeof(*phdr) * ehdr.e_phnum); zg_seek(g.fh, ehdr.e_phoff, ZG_CHECK); zg_read(g.fh, phdr, sizeof(*phdr) * ehdr.e_phnum, ZG_CHECK); + util_log_print(UTIL_LOG_DEBUG, "DFI ELF e_phnum %u\n", ehdr.e_phnum); for (i = 0; i < ehdr.e_phnum; i++) { + util_log_print(UTIL_LOG_DEBUG, "DFI ELF p_type[%d] 0x%lx\n", + i, phdr[i].p_type); switch (phdr[i].p_type) { case PT_LOAD: if (pt_load_add(&phdr[i])) { diff --git a/zdump/dfi_s390.c b/zdump/dfi_s390.c index 1734f0ba..dea672e4 100644 --- a/zdump/dfi_s390.c +++ b/zdump/dfi_s390.c @@ -18,6 +18,7 @@ #include #include +#include "lib/util_log.h" #include "zgetdump.h" /* @@ -70,6 +71,7 @@ static int read_s390_hdr(void) return -ENODEV; if (l.hdr.cpu_cnt > DF_S390_CPU_MAX) return -ENODEV; + util_log_print(UTIL_LOG_INFO, "DFI S390 version %u\n", l.hdr.version); df_s390_hdr_add(&l.hdr); return 0; } @@ -97,6 +99,9 @@ static int mem_chunks_add(void) { u64 rc; + util_log_print(UTIL_LOG_DEBUG, "DFI S390 mem_size 0x%016lx\n", + l.hdr.mem_size); + /* Single memory chunk for non-extended dump format */ dfi_mem_chunk_add(0, l.hdr.mem_size, NULL, dfi_s390_mem_chunk_read, @@ -124,6 +129,9 @@ static int mem_chunks_add_ext(void) rc = zg_read(g.fh, &dump_segm, PAGE_SIZE, ZG_CHECK_ERR); if (rc != PAGE_SIZE) return -EINVAL; + util_log_print(UTIL_LOG_DEBUG, + "DFI S390 dump segment start 0x%016lx size 0x%016lx stop marker %d\n", + dump_segm.start, dump_segm.len, dump_segm.stop_marker); off += PAGE_SIZE; /* Add zero memory chunk */ dfi_mem_chunk_add(old, dump_segm.start - old, NULL, @@ -159,6 +167,9 @@ int dfi_s390_init_gen(bool extended) { int rc; + util_log_print(UTIL_LOG_DEBUG, "DFI S390 %sinitialization\n", + extended ? "extended " : ""); + l.extended = extended; if (read_s390_hdr() != 0) return -ENODEV; diff --git a/zdump/dfi_vmcoreinfo.c b/zdump/dfi_vmcoreinfo.c index 682f8bf2..6c53df63 100644 --- a/zdump/dfi_vmcoreinfo.c +++ b/zdump/dfi_vmcoreinfo.c @@ -12,6 +12,7 @@ #include #include "lib/zt_common.h" +#include "lib/util_log.h" #include "zgetdump.h" @@ -62,6 +63,8 @@ static struct os_info *os_info_get(void) static struct os_info os_info; unsigned long addr; + util_log_print(UTIL_LOG_TRACE, "DFI get osinfo\n"); + if (dfi_mem_read_rc(LC_OS_INFO, &addr, sizeof(addr))) return NULL; if (addr % 0x1000) @@ -84,9 +87,12 @@ void dfi_vmcoreinfo_init(void) Elf64_Nhdr note; char str[128]; + util_log_print(UTIL_LOG_TRACE, "DFI vmcoreinfo initialization\n"); + l.os_info = os_info_get(); if (l.os_info && l.os_info->vmcoreinfo_size) { + util_log_print(UTIL_LOG_DEBUG, "DFI found valid osinfo\n"); addr = l.os_info->vmcoreinfo_addr; size = l.os_info->vmcoreinfo_size; } else { @@ -106,6 +112,9 @@ void dfi_vmcoreinfo_init(void) size = note.n_descsz; addr += 24; } + util_log_print(UTIL_LOG_DEBUG, + "DFI vmcoreinfo addr 0x%016lx size 0x%016lx\n", + addr, size); l.vmcoreinfo = zg_alloc(size + 1); if (dfi_mem_read_rc(addr, l.vmcoreinfo, size)) { zg_free(l.vmcoreinfo); @@ -113,6 +122,7 @@ void dfi_vmcoreinfo_init(void) return; } l.vmcoreinfo[size] = 0; + util_log_print(UTIL_LOG_INFO, "DFI found valid vmcoreinfo\n"); } /* diff --git a/zdump/opts.c b/zdump/opts.c index 81ff7aa6..0bedb44a 100644 --- a/zdump/opts.c +++ b/zdump/opts.c @@ -15,6 +15,7 @@ #include #include "lib/zt_common.h" +#include "lib/util_log.h" #include "zgetdump.h" /* @@ -46,7 +47,10 @@ static char help_text[] = "-s, --select Select system data SYS (\"kdump\", \"prod\", or \"all\")\n" "-d, --device Print DUMPDEV (dump device) information\n" "-v, --version Print version information, then exit\n" -"-V, --verbose Show detailed layout of memory map on printing DUMP information\n" +"-V, --verbose Print verbose messages to stdout. Repeat this option\n" +" for increased verbosity from just error messages to\n" +" also include warning, information, debug, and trace\n" +" messages. This option is intended for debugging\n" "-h, --help Print this help, then exit\n"; static const char copyright_str[] = "Copyright IBM Corp. 2001, 2018"; @@ -71,6 +75,9 @@ static void init_defaults(void) g.opts.fmt = "s390"; #endif dfo_set(g.opts.fmt); + /* Verbose logging */ + g.opts.verbose = UTIL_LOG_ERROR; + util_log_set_level(g.opts.verbose); } /* @@ -265,7 +272,8 @@ void opts_parse(int argc, char *argv[]) case 'v': print_version_exit(); case 'V': - g.opts.verbose_specified = 1; + g.opts.verbose++; + util_log_set_level(g.opts.verbose); break; case 'i': action_set(ZG_ACTION_DUMP_INFO); diff --git a/zdump/zgetdump.h b/zdump/zgetdump.h index 7e711f00..9edc8e09 100644 --- a/zdump/zgetdump.h +++ b/zdump/zgetdump.h @@ -35,7 +35,7 @@ struct options { int argc_fuse; const char *select; int select_specified; - int verbose_specified; + int verbose; }; extern const char *OPTS_SELECT_KDUMP;