zdump: Introduce multi-level message logging

Use util_log from libutil to output various log messages that can be helpful
during problem analysis.

Signed-off-by: Alexander Egorenkov <egorenar@linux.ibm.com>
Signed-off-by: Jan Höppner <hoeppner@linux.ibm.com>

zdump/dfi.c

@@ -10,6 +10,8 @@
  */
 
 #include <time.h>
+
+#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();
 }

zdump/dfi_elf.c

@@ -17,6 +17,7 @@
 #include <unistd.h>
 
 #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, &note, 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(&note);
@@ -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])) {

zdump/dfi_s390.c

@@ -18,6 +18,7 @@
 #include <time.h>
 #include <unistd.h>
 
+#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;

zdump/dfi_vmcoreinfo.c

@@ -12,6 +12,7 @@
 #include <elf.h>
 
 #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");
 }
 
 /*

zdump/opts.c

@@ -15,6 +15,7 @@
 #include <string.h>
 
 #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);

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;