log: add a way to turn on and off stack unwinding in logs

As a side effect, if SPDK_LOG_DISABLED is used in spdk_log() as log
level then no message will be printed.

Change-Id: I2d57b60a5a310a9ef2a1187a81088d0acf828742
Signed-off-by: Pawel Wodkowski <pawelx.wodkowski@intel.com>
Reviewed-on: https://review.gerrithub.io/425105
Chandler-Test-Pool: SPDK Automated Test System <sys_sgsw@intel.com>
Reviewed-by: Darek Stojaczyk <dariusz.stojaczyk@intel.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Ben Walker <benjamin.walker@intel.com>
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>

CONFIG

@@ -37,8 +37,8 @@ CONFIG_PREFIX?=/usr/local
 # Build with debug logging. Turn off for performance testing and normal usage
 CONFIG_DEBUG?=n
 
-# Show backtrace when logging message at level <= lvl (ERROR, WARN, NOTICE, DEBUG)
+# Build with support of backtrace printing in log messages. Requires libunwind.
-#CONFIG_LOG_BACKTRACE?=lvl
+#CONFIG_LOG_BACKTRACE?=n
 
 # Treat warnings as errors (fail the build on any warning).
 CONFIG_WERROR?=n

configure

@@ -16,8 +16,7 @@ function usage()
 	echo " --prefix=path             Configure installation prefix (default: /usr/local)"
 	echo ""
 	echo " --enable-debug            Configure for debug builds"
-	echo " --enable-log-bt=lvl       Show backtrace using libunwind when logging message at level <= lvl."
+	echo " --enable-log-bt           Enable support of backtrace printing in SPDK logs (requires libunwind)."
-	echo "                           Valid values are: ERROR, WARN, NOTICE, DEBUG."
 	echo " --enable-werror           Treat compiler warnings as errors"
 	echo " --enable-asan             Enable address sanitizer"
 	echo " --enable-ubsan            Enable undefined behavior sanitizer"
@@ -91,8 +90,11 @@ for i in "$@"; do
 		--disable-debug)
 			CONFIG_DEBUG=n
 			;;
-		--enable-log-bt=*)
+		--enable-log-bt)
-			CONFIG_LOG_BACKTRACE=${i#*=}
+			CONFIG_LOG_BACKTRACE=y
+			;;
+		--disable-log-bt)
+			CONFIG_LOG_BACKTRACE=n
 			;;
 		--enable-asan)
 			CONFIG_ASAN=y
@@ -244,15 +246,6 @@ for i in "$@"; do
 	esac
 done
 
-case "$CONFIG_LOG_BACKTRACE" in
-	""|ERROR|WARN|NOTICE|DEBUG)
-		;;
-	*)
-		echo "Invalid '--enable-log-bt=$CONFIG_LOG_BACKTRACE' option. Valid levels are ERROR, WARN, NOTICE or DEBUG"
-		exit 1
-		;;
-esac
-
 if [ -z "$CONFIG_ENV" ]; then
 	if [ -z "$CONFIG_DPDK_DIR" ]; then
 		rootdir=$(readlink -f $(dirname $0))

include/spdk/log.h

@@ -58,6 +58,8 @@ void spdk_log_open(void);
 void spdk_log_close(void);
 
 enum spdk_log_level {
+	/** All messages will be suppressed. */
+	SPDK_LOG_DISABLED = -1,
 	SPDK_LOG_ERROR,
 	SPDK_LOG_WARN,
 	SPDK_LOG_NOTICE,
@@ -80,10 +82,31 @@ void spdk_log_set_level(enum spdk_log_level level);
  */
 enum spdk_log_level spdk_log_get_level(void);
 
+/**
+ * Set the log level threshold to include stack trace in log messages.
+ * Messages with a higher level than this will not contain stack trace. You
+ * can use \c SPDK_LOG_DISABLED to completely disable stack trace printing
+ * even if it is supported.
+ *
+ * \note This function has no effect if SPDK is built without stack trace
+ *  printing support.
+ *
+ * \param level Log level threshold for stacktrace.
+ */
+void spdk_log_set_backtrace_level(enum spdk_log_level level);
+
+/**
+ * Get the current log level threshold for showing stack trace in log message.
+ *
+ * \return the current log level threshold for stack trace.
+ */
+enum spdk_log_level spdk_log_get_backtrace_level(void);
+
 /**
  * Set the current log level threshold for printing to stderr.
  * Messages with a level less than or equal to this level
- * are also printed to stderr.
+ * are also printed to stderr. You can use \c SPDK_LOG_DISABLED to completely
+ * suppress log printing.
  *
  * \param level Log level threshold for printing to stderr.
  */
@@ -104,7 +127,8 @@ enum spdk_log_level spdk_log_get_print_level(void);
 	spdk_log(SPDK_LOG_ERROR, __FILE__, __LINE__, __func__, __VA_ARGS__)
 
 /**
- * Write messages to the log file.
+ * Write messages to the log file. If \c level is set to \c SPDK_LOG_DISABLED,
+ * this log message won't be written.
  *
  * \param level Log level threshold.
  * \param file Name of the current source file.

include/spdk_internal/log.h

@@ -44,6 +44,7 @@
 
 extern enum spdk_log_level g_spdk_log_level;
 extern enum spdk_log_level g_spdk_log_print_level;
+extern enum spdk_log_level g_spdk_log_backtrace_level;
 
 struct spdk_trace_flag {
 	TAILQ_ENTRY(spdk_trace_flag) tailq;

lib/event/app.c

@@ -46,6 +46,7 @@
 
 #define SPDK_APP_DEFAULT_LOG_LEVEL		SPDK_LOG_NOTICE
 #define SPDK_APP_DEFAULT_LOG_PRINT_LEVEL	SPDK_LOG_INFO
+#define SPDK_APP_DEFAULT_BACKTRACE_LOG_LEVEL	SPDK_LOG_ERROR
 
 #define SPDK_APP_DPDK_DEFAULT_MEM_SIZE		-1
 #define SPDK_APP_DPDK_DEFAULT_MASTER_CORE	-1
@@ -591,6 +592,7 @@ spdk_app_start(struct spdk_app_opts *opts, spdk_event_fn start_fn,
 	}
 
 	spdk_log_set_level(SPDK_APP_DEFAULT_LOG_LEVEL);
+	spdk_log_set_backtrace_level(SPDK_APP_DEFAULT_BACKTRACE_LOG_LEVEL);
 
 	if (spdk_app_setup_env(opts) < 0) {
 		goto app_start_setup_conf_err;

lib/log/log.c

@@ -74,7 +74,7 @@ spdk_log_unwind_stack(FILE *fp, enum spdk_log_level level)
 	char f_name[64];
 	int frame;
 
-	if (level > SPDK_LOG_BACKTRACE_LVL) {
+	if (level > g_spdk_log_backtrace_level) {
 		return;
 	}
 
@@ -122,6 +122,8 @@ spdk_log(enum spdk_log_level level, const char *file, const int line, const char
 	case SPDK_LOG_DEBUG:
 		severity = LOG_INFO;
 		break;
+	case SPDK_LOG_DISABLED:
+		return;
 	}
 
 	va_start(ap, format);

lib/log/log_flags.c

@@ -39,6 +39,7 @@ static TAILQ_HEAD(, spdk_trace_flag) g_trace_flags = TAILQ_HEAD_INITIALIZER(g_tr
 
 enum spdk_log_level g_spdk_log_level = SPDK_LOG_NOTICE;
 enum spdk_log_level g_spdk_log_print_level = SPDK_LOG_NOTICE;
+enum spdk_log_level g_spdk_log_backtrace_level = SPDK_LOG_DISABLED;
 
 SPDK_LOG_REGISTER_COMPONENT("log", SPDK_LOG_LOG)
 
@@ -66,6 +67,17 @@ spdk_log_get_print_level(void) {
 	return g_spdk_log_print_level;
 }
 
+void
+spdk_log_set_backtrace_level(enum spdk_log_level level)
+{
+	g_spdk_log_backtrace_level = level;
+}
+
+enum spdk_log_level
+spdk_log_get_backtrace_level(void) {
+	return g_spdk_log_backtrace_level;
+}
+
 static struct spdk_trace_flag *
 get_trace_flag(const char *name)
 {

mk/spdk.common.mk

@@ -191,7 +191,6 @@ SYS_LIBS += -luuid
 SYS_LIBS += -lcrypto
 ifneq ($(CONFIG_LOG_BACKTRACE),)
 SYS_LIBS += -lunwind
-COMMON_CFLAGS += -DSPDK_LOG_BACKTRACE_LVL=SPDK_LOG_$(CONFIG_LOG_BACKTRACE)
 endif
 
 MAKEFLAGS += --no-print-directory

test/common/autotest_common.sh

@@ -80,7 +80,7 @@ config_params='--enable-debug --enable-werror'
 
 if echo -e "#include <libunwind.h>\nint main(int argc, char *argv[]) {return 0;}\n" | \
 	gcc -o /dev/null -lunwind -x c - 2>/dev/null; then
-	config_params+=' --enable-log-bt=ERROR'
+	config_params+=' --enable-log-bt'
 fi
 
 # RAID is marked experimental and not built by default currently, since it does not