From ab4c009e3d0cf794bbe84aff3b9ac203eaed03c7 Mon Sep 17 00:00:00 2001 From: Tom Caputi Date: Mon, 15 Oct 2018 15:14:22 -0400 Subject: [PATCH] Fix dbgmsg printing in ztest and zdb This patch resolves a problem where the -G option in both zdb and ztest would cause the code to call __dprintf() to print zfs_dbgmsg output. This function was not properly wired to add messages to the dbgmsg log as it is in userspace and so the messages were simply dropped. This patch also tries to add some degree of distinction to dprintf() (which now prints directly to stdout) and zfs_dbgmsg() (which adds messages to an internal list that can be dumped with zfs_dbgmsg_print()). In addition, this patch corrects an issue where ztest used a global variable to decide whether to dump the dbgmsg buffer on a crash. This did not work because ztest spins up more instances of itself using execv(), which did not copy the global variable to the new process. The option has been moved to the ztest_shared_opts_t which already exists for interprocess communication. This patch also changes zfs_dbgmsg_print() to use write() calls instead of printf() so that it will not fail when used in a signal handler. Reviewed-by: Brian Behlendorf Reviewed-by: Serapheim Dimitropoulos Reviewed-by: Matthew Ahrens Signed-off-by: Tom Caputi Closes #8010 --- cmd/zdb/zdb.c | 1 + cmd/ztest/ztest.c | 19 +++++++++++------ include/sys/zfs_debug.h | 7 ++++--- lib/libzpool/kernel.c | 35 ++++++++++++++++++++++++++----- module/zfs/zfs_debug.c | 46 ++++++++++++++++++++++++++++++----------- 5 files changed, 82 insertions(+), 26 deletions(-) diff --git a/cmd/zdb/zdb.c b/cmd/zdb/zdb.c index 389bd7820a..cdea1e5843 100644 --- a/cmd/zdb/zdb.c +++ b/cmd/zdb/zdb.c @@ -225,6 +225,7 @@ dump_debug_buffer(void) { if (dump_opt['G']) { (void) printf("\n"); + (void) fflush(stdout); zfs_dbgmsg_print("zdb"); } } diff --git a/cmd/ztest/ztest.c b/cmd/ztest/ztest.c index 47f3cdf126..44d4e97403 100644 --- a/cmd/ztest/ztest.c +++ b/cmd/ztest/ztest.c @@ -178,6 +178,7 @@ typedef struct ztest_shared_opts { uint64_t zo_metaslab_force_ganging; int zo_mmp_test; int zo_special_vdevs; + int zo_dump_dbgmsg; } ztest_shared_opts_t; static const ztest_shared_opts_t ztest_opts_defaults = { @@ -484,7 +485,6 @@ static kmutex_t ztest_checkpoint_lock; static pthread_rwlock_t ztest_name_lock; static boolean_t ztest_dump_core = B_TRUE; -static boolean_t ztest_dump_debug_buffer = B_FALSE; static boolean_t ztest_exiting; /* Global commit callback list */ @@ -533,10 +533,16 @@ _umem_logging_init(void) static void dump_debug_buffer(void) { - if (!ztest_dump_debug_buffer) + ssize_t ret __attribute__((unused)); + + if (!ztest_opts.zo_dump_dbgmsg) return; - (void) printf("\n"); + /* + * We use write() instead of printf() so that this function + * is safe to call from a signal handler. + */ + ret = write(STDOUT_FILENO, "\n", 1); zfs_dbgmsg_print("ztest"); } @@ -591,10 +597,11 @@ fatal(int do_perror, char *message, ...) (void) fprintf(stderr, "%s\n", buf); fatal_msg = buf; /* to ease debugging */ - dump_debug_buffer(); - if (ztest_dump_core) abort(); + else + dump_debug_buffer(); + exit(3); } @@ -866,7 +873,7 @@ process_options(int argc, char **argv) usage(B_FALSE); break; case 'G': - ztest_dump_debug_buffer = B_TRUE; + zo->zo_dump_dbgmsg = 1; break; case 'h': usage(B_TRUE); diff --git a/include/sys/zfs_debug.h b/include/sys/zfs_debug.h index f3a936ae7b..f60932b5a8 100644 --- a/include/sys/zfs_debug.h +++ b/include/sys/zfs_debug.h @@ -55,11 +55,12 @@ extern int zfs_dbgmsg_enable; #define ZFS_DEBUG_SET_ERROR (1 << 9) #define ZFS_DEBUG_INDIRECT_REMAP (1 << 10) -extern void __dprintf(const char *file, const char *func, +extern void __zfs_dbgmsg(char *buf); +extern void __dprintf(boolean_t dprint, const char *file, const char *func, int line, const char *fmt, ...); #define zfs_dbgmsg(...) \ if (zfs_dbgmsg_enable) \ - __dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__) + __dprintf(B_FALSE, __FILE__, __func__, __LINE__, __VA_ARGS__) #ifdef ZFS_DEBUG /* @@ -69,7 +70,7 @@ extern void __dprintf(const char *file, const char *func, */ #define dprintf(...) \ if (zfs_flags & ZFS_DEBUG_DPRINTF) \ - __dprintf(__FILE__, __func__, __LINE__, __VA_ARGS__) + __dprintf(B_TRUE, __FILE__, __func__, __LINE__, __VA_ARGS__) #else #define dprintf(...) ((void)0) #endif /* ZFS_DEBUG */ diff --git a/lib/libzpool/kernel.c b/lib/libzpool/kernel.c index 5baf52514a..f5eafb9172 100644 --- a/lib/libzpool/kernel.c +++ b/lib/libzpool/kernel.c @@ -783,7 +783,8 @@ dprintf_setup(int *argc, char **argv) * ========================================================================= */ void -__dprintf(const char *file, const char *func, int line, const char *fmt, ...) +__dprintf(boolean_t dprint, const char *file, const char *func, + int line, const char *fmt, ...) { const char *newfile; va_list adx; @@ -798,9 +799,14 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) newfile = file; } - if (dprintf_print_all || - dprintf_find_string(newfile) || - dprintf_find_string(func)) { + if (dprint) { + /* dprintf messages are printed immediately */ + + if (!dprintf_print_all && + !dprintf_find_string(newfile) && + !dprintf_find_string(func)) + return; + /* Print out just the function name if requested */ flockfile(stdout); if (dprintf_find_string("pid")) @@ -813,11 +819,30 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) (void) printf("%llu ", gethrtime()); if (dprintf_find_string("long")) (void) printf("%s, line %d: ", newfile, line); - (void) printf("%s: ", func); + (void) printf("dprintf: %s: ", func); va_start(adx, fmt); (void) vprintf(fmt, adx); va_end(adx); funlockfile(stdout); + } else { + /* zfs_dbgmsg is logged for dumping later */ + size_t size; + char *buf; + int i; + + size = 1024; + buf = umem_alloc(size, UMEM_NOFAIL); + i = snprintf(buf, size, "%s:%d:%s(): ", newfile, line, func); + + if (i < size) { + va_start(adx, fmt); + (void) vsnprintf(buf + i, size - i, fmt, adx); + va_end(adx); + } + + __zfs_dbgmsg(buf); + + umem_free(buf, size); } } diff --git a/module/zfs/zfs_debug.c b/module/zfs/zfs_debug.c index b5f93fd9be..62c59e0209 100644 --- a/module/zfs/zfs_debug.c +++ b/module/zfs/zfs_debug.c @@ -124,11 +124,10 @@ __set_error(const char *file, const char *func, int line, int err) * $ echo 512 >/sys/module/zfs/parameters/zfs_flags */ if (zfs_flags & ZFS_DEBUG_SET_ERROR) - __dprintf(file, func, line, "error %lu", err); + __dprintf(B_FALSE, file, func, line, "error %lu", err); } -#ifdef _KERNEL -static void +void __zfs_dbgmsg(char *buf) { int size = sizeof (zfs_dbgmsg_t) + strlen(buf); @@ -144,8 +143,11 @@ __zfs_dbgmsg(char *buf) mutex_exit(&zfs_dbgmsgs.pl_lock); } +#ifdef _KERNEL + void -__dprintf(const char *file, const char *func, int line, const char *fmt, ...) +__dprintf(boolean_t dprint, const char *file, const char *func, + int line, const char *fmt, ...) { const char *newfile; va_list adx; @@ -153,6 +155,7 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) char *buf; char *nl; int i; + char *prefix = (dprint) ? "dprintf: " : ""; size = 1024; buf = kmem_alloc(size, KM_SLEEP); @@ -167,7 +170,7 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) newfile = file; } - i = snprintf(buf, size, "%s:%d:%s(): ", newfile, line, func); + i = snprintf(buf, size, "%s%s:%d:%s(): ", prefix, newfile, line, func); if (i < size) { va_start(adx, fmt); @@ -176,11 +179,13 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) } /* - * Get rid of trailing newline. + * Get rid of trailing newline for dprintf logs. */ - nl = strrchr(buf, '\n'); - if (nl != NULL) - *nl = '\0'; + if (dprint && buf[0] != '\0') { + nl = &buf[strlen(buf) - 1]; + if (*nl == '\n') + *nl = '\0'; + } /* * To get this data enable the zfs__dprintf trace point as shown: @@ -212,11 +217,28 @@ __dprintf(const char *file, const char *func, int line, const char *fmt, ...) void zfs_dbgmsg_print(const char *tag) { - (void) printf("ZFS_DBGMSG(%s):\n", tag); + ssize_t ret __attribute__((unused)); + + /* + * We use write() in this function instead of printf() + * so it is safe to call from a signal handler. + */ + ret = write(STDOUT_FILENO, "ZFS_DBGMSG(", 11); + ret = write(STDOUT_FILENO, tag, strlen(tag)); + ret = write(STDOUT_FILENO, ") START:\n", 9); + mutex_enter(&zfs_dbgmsgs.pl_lock); for (zfs_dbgmsg_t *zdm = list_head(&zfs_dbgmsgs.pl_list); zdm != NULL; - zdm = list_next(&zfs_dbgmsgs.pl_list, zdm)) - (void) printf("%s\n", zdm->zdm_msg); + zdm = list_next(&zfs_dbgmsgs.pl_list, zdm)) { + ret = write(STDOUT_FILENO, zdm->zdm_msg, + strlen(zdm->zdm_msg)); + ret = write(STDOUT_FILENO, "\n", 1); + } + + ret = write(STDOUT_FILENO, "ZFS_DBGMSG(", 11); + ret = write(STDOUT_FILENO, tag, strlen(tag)); + ret = write(STDOUT_FILENO, ") END\n", 6); + mutex_exit(&zfs_dbgmsgs.pl_lock); } #endif /* _KERNEL */