log: Allow LOG_DEBUG to always enable log output

At present if CONFIG_LOG enabled, putting LOG_DEBUG at the top of a file
(before log.h inclusion) causes _log() to be executed for every log()
call, regardless of the build- or run-time logging level.

However there is no guarantee that the log record will actually be
displayed. If the current log level is lower than LOGL_DEBUG then it will
not be.

Add a way to signal that the log record should always be displayed and
update log_passes_filters() to handle this.

With the new behaviour, log_debug() will always log if LOG_DEBUG is
enabled.

Move log_test_syslog_nodebug() into its own file since it cannot be made
to work where it is, with LOG_DEBUG defined.

Signed-off-by: Simon Glass <sjg@chromium.org>

common/log.c

@@ -157,6 +157,9 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec)
 {
 	struct log_filter *filt;
 
+	if (rec->force_debug)
+		return true;
+
 	/* If there are no filters, filter on the default log level */
 	if (list_empty(&ldev->filter_head)) {
 		if (rec->level > gd->default_log_level)
@@ -219,7 +222,8 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	va_list args;
 
 	rec.cat = cat;
-	rec.level = level;
+	rec.level = level & LOGL_LEVEL_MASK;
+	rec.force_debug = level & LOGL_FORCE_DEBUG;
 	rec.file = file;
 	rec.line = line;
 	rec.func = func;

doc/README.log

@@ -78,11 +78,8 @@ Sometimes it is useful to turn on logging just in one file. You can use this:
    #define LOG_DEBUG
 
 to enable building in of all logging statements in a single file. Put it at
-the top of the file, before any #includes.
+the top of the file, before any #includes. This overrides any log-level setting
-
+in U-Boot, including CONFIG_LOG_DEFAULT_LEVEL, but just for that file.
-To actually get U-Boot to output this you need to also set the default logging
-level - e.g. set CONFIG_LOG_DEFAULT_LEVEL to 7 (LOGL_DEBUG) or more. Otherwise
-debug output is suppressed and will not be generated.
 
 
 Convenience functions

include/log.h

@@ -33,6 +33,9 @@ enum log_level_t {
 	LOGL_COUNT,
 	LOGL_NONE,
 
+	LOGL_LEVEL_MASK = 0xf,	/* Mask for valid log levels */
+	LOGL_FORCE_DEBUG = 0x10, /* Mask to force output due to LOG_DEBUG */
+
 	LOGL_FIRST = LOGL_EMERG,
 	LOGL_MAX = LOGL_DEBUG_IO,
 };
@@ -133,7 +136,7 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level,
 
 #if CONFIG_IS_ENABLED(LOG)
 #ifdef LOG_DEBUG
-#define _LOG_DEBUG	1
+#define _LOG_DEBUG	LOGL_FORCE_DEBUG
 #else
 #define _LOG_DEBUG	0
 #endif
@@ -141,9 +144,11 @@ static inline int _log_nop(enum log_category_t cat, enum log_level_t level,
 /* Emit a log record if the level is less that the maximum */
 #define log(_cat, _level, _fmt, _args...) ({ \
 	int _l = _level; \
-	if (CONFIG_IS_ENABLED(LOG) && (_l <= _LOG_MAX_LEVEL || _LOG_DEBUG)) \
+	if (CONFIG_IS_ENABLED(LOG) && \
-		_log((enum log_category_t)(_cat), _l, __FILE__, __LINE__, \
+	    (_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \
-		      __func__, \
+		_log((enum log_category_t)(_cat), \
+		     (enum log_level_t)(_l | _LOG_DEBUG), __FILE__, \
+		     __LINE__, __func__, \
 		      pr_fmt(_fmt), ##_args); \
 	})
 #else
@@ -279,8 +284,12 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line,
  * Memebers marked as 'allocated' are allocated (e.g. via strdup()) by the log
  * system.
  *
+ * TODO(sjg@chromium.org): Compress this struct down a bit to reduce space, e.g.
+ * a single u32 for cat, level, line and force_debug
+ *
  * @cat: Category, representing a uclass or part of U-Boot
  * @level: Severity level, less severe is higher
+ * @force_debug: Force output of debug
  * @file: Name of file where the log record was generated (not allocated)
  * @line: Line number where the log record was generated
  * @func: Function where the log record was generated (not allocated)
@@ -289,6 +298,7 @@ void __assert_fail(const char *assertion, const char *file, unsigned int line,
 struct log_rec {
 	enum log_category_t cat;
 	enum log_level_t level;
+	bool force_debug;
 	const char *file;
 	int line;
 	const char *func;

test/log/Makefile

@@ -10,6 +10,7 @@ obj-y += test-main.o
 
 ifdef CONFIG_SANDBOX
 obj-$(CONFIG_LOG_SYSLOG) += syslog_test.o
+obj-$(CONFIG_LOG_SYSLOG) += syslog_test_ndebug.o
 endif
 
 ifndef CONFIG_LOG

test/log/syslog_test.c

@@ -18,48 +18,11 @@
 #include <test/suites.h>
 #include <test/ut.h>
 #include <asm/eth.h>
+#include <syslog_test.h>
 
 DECLARE_GLOBAL_DATA_PTR;
 
-#define LOGF_TEST (BIT(LOGF_FUNC) | BIT(LOGF_MSG))
+int sb_log_tx_handler(struct udevice *dev, void *packet, unsigned int len)
-
-/**
- * struct sb_log_env - private data for sandbox ethernet driver
- *
- * This structure is used for the private data of the sandbox ethernet
- * driver.
- *
- * @expected:	string expected to be written by the syslog driver
- * @uts:	unit test state
- */
-struct sb_log_env {
-	const char *expected;
-	struct unit_test_state *uts;
-};
-
-/**
- * sb_log_tx_handler() - transmit callback function
- *
- * This callback function is invoked when a network package is sent using the
- * sandbox Ethernet driver. The private data of the driver holds a sb_log_env
- * structure with the unit test state and the expected UDP payload.
- *
- * The following checks are executed:
- *
- * * the Ethernet packet indicates a IP broadcast message
- * * the IP header is for a local UDP broadcast message to port 514
- * * the UDP payload matches the expected string
- *
- * After testing the pointer to the expected string is set to NULL to signal
- * that the callback function has been called.
- *
- * @dev:	sandbox ethernet device
- * @packet:	Ethernet packet
- * @len:	length of Ethernet packet
- * Return:	0 = success
- */
-static int sb_log_tx_handler(struct udevice *dev, void *packet,
-			     unsigned int len)
 {
 	struct eth_sandbox_priv *priv = dev_get_priv(dev);
 	struct sb_log_env *env = priv->priv;
@@ -251,38 +214,3 @@ static int log_test_syslog_debug(struct unit_test_state *uts)
 	return 0;
 }
 LOG_TEST(log_test_syslog_debug);
-
-/**
- * log_test_syslog_nodebug() - test logging level filter
- *
- * Verify that log_debug() does not lead to a log message if the logging level
- * is set to LOGL_INFO.
- *
- * @uts:	unit test state
- * Return:	0 = success
- */
-static int log_test_syslog_nodebug(struct unit_test_state *uts)
-{
-	int old_log_level = gd->default_log_level;
-	struct sb_log_env env;
-
-	gd->log_fmt = LOGF_TEST;
-	gd->default_log_level = LOGL_INFO;
-	env_set("ethact", "eth@10002000");
-	env_set("log_hostname", "sandbox");
-	env.expected = "<7>sandbox uboot: log_test_syslog_nodebug() "
-		       "testing log_debug\n";
-	env.uts = uts;
-	sandbox_eth_set_tx_handler(0, sb_log_tx_handler);
-	/* Used by ut_assert macros in the tx_handler */
-	sandbox_eth_set_priv(0, &env);
-	log_debug("testing %s\n", "log_debug");
-	sandbox_eth_set_tx_handler(0, NULL);
-	/* Check that the callback function was not called */
-	ut_assertnonnull(env.expected);
-	gd->default_log_level = old_log_level;
-	gd->log_fmt = log_get_default_format();
-
-	return 0;
-}
-LOG_TEST(log_test_syslog_nodebug);

test/log/syslog_test.h

@@ -0,0 +1,50 @@
+/* SPDX-License-Identifier: GPL-2.0+ */
+/*
+ * Copyright (c) 2020, Heinrich Schuchardt <xypron.glpk@gmx.de>
+ *
+ * Header file for logging tests
+ */
+
+#ifndef __SYSLOG_TEST_H
+#define __SYSLOG_TEST_H
+
+#define LOGF_TEST (BIT(LOGF_FUNC) | BIT(LOGF_MSG))
+
+/**
+ * struct sb_log_env - private data for sandbox ethernet driver
+ *
+ * This structure is used for the private data of the sandbox ethernet
+ * driver.
+ *
+ * @expected:	string expected to be written by the syslog driver
+ * @uts:	unit test state
+ */
+struct sb_log_env {
+	const char *expected;
+	struct unit_test_state *uts;
+};
+
+/**
+ * sb_log_tx_handler() - transmit callback function
+ *
+ * This callback function is invoked when a network package is sent using the
+ * sandbox Ethernet driver. The private data of the driver holds a sb_log_env
+ * structure with the unit test state and the expected UDP payload.
+ *
+ * The following checks are executed:
+ *
+ * * the Ethernet packet indicates a IP broadcast message
+ * * the IP header is for a local UDP broadcast message to port 514
+ * * the UDP payload matches the expected string
+ *
+ * After testing the pointer to the expected string is set to NULL to signal
+ * that the callback function has been called.
+ *
+ * @dev:	sandbox ethernet device
+ * @packet:	Ethernet packet
+ * @len:	length of Ethernet packet
+ * Return:	0 = success
+ */
+int sb_log_tx_handler(struct udevice *dev, void *packet, unsigned int len);
+
+#endif

test/log/syslog_test_ndebug.c

@@ -0,0 +1,55 @@
+// SPDX-License-Identifier: GPL-2.0+
+/*
+ * Copyright (c) 2020, Heinrich Schuchardt <xypron.glpk@gmx.de>
+ *
+ * Logging function tests for CONFIG_LOG_SYSLOG=y.
+ *
+ * Invoke the test with: ./u-boot -d arch/sandbox/dts/test.dtb
+ */
+
+#include <common.h>
+#include <dm/device.h>
+#include <hexdump.h>
+#include <test/log.h>
+#include <test/test.h>
+#include <test/suites.h>
+#include <test/ut.h>
+#include <asm/eth.h>
+#include <syslog_test.h>
+
+DECLARE_GLOBAL_DATA_PTR;
+
+/**
+ * log_test_syslog_nodebug() - test logging level filter
+ *
+ * Verify that log_debug() does not lead to a log message if the logging level
+ * is set to LOGL_INFO.
+ *
+ * @uts:	unit test state
+ * Return:	0 = success
+ */
+static int log_test_syslog_nodebug(struct unit_test_state *uts)
+{
+	int old_log_level = gd->default_log_level;
+	struct sb_log_env env;
+
+	gd->log_fmt = LOGF_TEST;
+	gd->default_log_level = LOGL_INFO;
+	env_set("ethact", "eth@10002000");
+	env_set("log_hostname", "sandbox");
+	env.expected = "<7>sandbox uboot: log_test_syslog_nodebug() "
+		       "testing log_debug\n";
+	env.uts = uts;
+	sandbox_eth_set_tx_handler(0, sb_log_tx_handler);
+	/* Used by ut_assert macros in the tx_handler */
+	sandbox_eth_set_priv(0, &env);
+	log_debug("testing %s\n", "log_debug");
+	sandbox_eth_set_tx_handler(0, NULL);
+	/* Check that the callback function was not called */
+	ut_assertnonnull(env.expected);
+	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();
+
+	return 0;
+}
+LOG_TEST(log_test_syslog_nodebug);