[PATCH v4 0/2] log: Allow multiple lines and conversion to printf()

[PATCH v4 0/2] log: Allow multiple lines and conversion to printf()

[Simon Glass]

At present when logging is not enabled, all log() calls become nops. This
does not seem right, since if the log level is high enough then there
should be some sort of message. So in that case, this series updates it to
print the message if the log level is above LOGL_INFO.

This mimics the behaviour for the log_...() macros like log_debug() and
log_info(), so we can drop the special case for these.

Also the current implementation does not support multiple log calls on the
same line nicely. The tags are repeated so the line is very hard to read.
This series adds that as a new feature.

Changes in v4:
- Fix missing header for SPL

Changes in v3:
- Rebase on hexdump series
  http://patchwork.ozlabs.org/project/uboot/list/?series=242818

Changes in v2:
- Update commit message and cover letter to mention log_...() macros
- Add a test for !CONFIG_LOG
- Update log() to (effectively) call debug() for log_level == LOGL_DEBUG

Simon Glass (2):
  sandbox: log: Avoid build error with !CONFIG_LOG
  log: Convert log values to printf() if not enabled

 configs/sandbox_defconfig |  1 +
 doc/develop/logging.rst   |  6 ++++--
 include/log.h             | 34 +++++++++++++++-------------------
 test/log/Makefile         |  2 ++
 test/log/nolog_ndebug.c   | 39 +++++++++++++++++++++++++++++++++++++++
 test/log/nolog_test.c     |  3 +++
 6 files changed, 64 insertions(+), 21 deletions(-)
 create mode 100644 test/log/nolog_ndebug.c

-- 
2.31.1.607.g51e8a6a459-goog

[PATCH v4 1/2] sandbox: log: Avoid build error with !CONFIG_LOG

[Simon Glass]

The pr_cont_test.c test requires CONFIG_LOG since it directly accesses
fields in global_data that require it. Move the test into the CONFIG_LOG
condition to avoid build errors.

Enable CONFIG_LOG on sandbox (not sandbox_spl, etc.) so that we still run
this test. This requires resyncing of the configs.

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

(no changes since v1)

 configs/sandbox_defconfig | 1 +
 test/log/Makefile         | 1 +
 2 files changed, 2 insertions(+)

diff --git a/configs/sandbox_defconfig b/configs/sandbox_defconfig
index bdbf714e2bd..60cdad10848 100644
--- a/configs/sandbox_defconfig
+++ b/configs/sandbox_defconfig
@@ -21,6 +21,7 @@ CONFIG_BOOTSTAGE_STASH_SIZE=0x4096
 CONFIG_CONSOLE_RECORD=y
 CONFIG_CONSOLE_RECORD_OUT_SIZE=0x1000
 CONFIG_PRE_CONSOLE_BUFFER=y
+CONFIG_LOG=y
 CONFIG_DISPLAY_BOARDINFO_LATE=y
 CONFIG_MISC_INIT_F=y
 CONFIG_STACKPROTECTOR=y
diff --git a/test/log/Makefile b/test/log/Makefile
index a3dedace043..09f8689d070 100644
--- a/test/log/Makefile
+++ b/test/log/Makefile
@@ -17,6 +17,7 @@ endif
 ifdef CONFIG_LOG
 obj-y += pr_cont_test.o
 obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o
+obj-y += pr_cont_test.o
 else
 obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o
 endif
-- 
2.31.1.607.g51e8a6a459-goog

[PATCH v4 2/2] log: Convert log values to printf() if not enabled

[Simon Glass]

At present if logging not enabled, log_info() becomes a nop. But we want
log output at the 'info' level to be akin to printf(). Update the macro to
pass the output straight to printf() in this case.

This mimics the behaviour for the log_...() macros like log_debug() and
log_info(), so we can drop the special case for these.

Add new tests to cover this case.
Signed-off-by: Simon Glass <sjg@chromium.org>
---

Changes in v4:
- Fix missing header for SPL

Changes in v3:
- Rebase on hexdump series
  http://patchwork.ozlabs.org/project/uboot/list/?series=242818

Changes in v2:
- Update commit message and cover letter to mention log_...() macros
- Add a test for !CONFIG_LOG
- Update log() to (effectively) call debug() for log_level == LOGL_DEBUG

 doc/develop/logging.rst |  6 ++++--
 include/log.h           | 34 +++++++++++++++-------------------
 test/log/Makefile       |  1 +
 test/log/nolog_ndebug.c | 39 +++++++++++++++++++++++++++++++++++++++
 test/log/nolog_test.c   |  3 +++
 5 files changed, 62 insertions(+), 21 deletions(-)
 create mode 100644 test/log/nolog_ndebug.c

diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst
index f4e925048e8..51095b05ba9 100644
--- a/doc/develop/logging.rst
+++ b/doc/develop/logging.rst
@@ -52,6 +52,10 @@ If CONFIG_LOG is not set, then no logging will be available.
 The above have SPL and TPL versions also, e.g. CONFIG_SPL_LOG_MAX_LEVEL and
 CONFIG_TPL_LOG_MAX_LEVEL.
 
+If logging is disabled, the default behaviour is to output any message at
+level LOGL_INFO and below. If logging is disabled and DEBUG is defined (at
+the very top of a C file) then any message at LOGL_DEBUG will be written.
+
 Temporary logging within a single file
 --------------------------------------
 
@@ -291,8 +295,6 @@ More logging destinations:
 
 Convert debug() statements in the code to log() statements
 
-Support making printf() emit log statements at L_INFO level
-
 Convert error() statements in the code to log() statements
 
 Figure out what to do with BUG(), BUG_ON() and warn_non_spl()
diff --git a/include/log.h b/include/log.h
index feb0204855a..e0e12ce1944 100644
--- a/include/log.h
+++ b/include/log.h
@@ -174,6 +174,10 @@ int _log_buffer(enum log_category_t cat, enum log_level_t level,
  */
 #if CONFIG_IS_ENABLED(LOG)
 #define _LOG_MAX_LEVEL CONFIG_VAL(LOG_MAX_LEVEL)
+#else
+#define _LOG_MAX_LEVEL LOGL_INFO
+#endif
+
 #define log_emer(_fmt...)	log(LOG_CATEGORY, LOGL_EMERG, ##_fmt)
 #define log_alert(_fmt...)	log(LOG_CATEGORY, LOGL_ALERT, ##_fmt)
 #define log_crit(_fmt...)	log(LOG_CATEGORY, LOGL_CRIT, ##_fmt)
@@ -185,34 +189,19 @@ int _log_buffer(enum log_category_t cat, enum log_level_t level,
 #define log_content(_fmt...)	log(LOG_CATEGORY, LOGL_DEBUG_CONTENT, ##_fmt)
 #define log_io(_fmt...)		log(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt)
 #define log_cont(_fmt...)	log(LOGC_CONT, LOGL_CONT, ##_fmt)
-#else
-#define _LOG_MAX_LEVEL LOGL_INFO
-#define log_emerg(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_alert(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_crit(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_err(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_warning(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_notice(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_info(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_cont(_fmt, ...)	printf(_fmt, ##__VA_ARGS__)
-#define log_debug(_fmt, ...)	debug(_fmt, ##__VA_ARGS__)
-#define log_content(_fmt...)	log_nop(LOG_CATEGORY, \
-					LOGL_DEBUG_CONTENT, ##_fmt)
-#define log_io(_fmt...)		log_nop(LOG_CATEGORY, LOGL_DEBUG_IO, ##_fmt)
-#endif
 
-#if CONFIG_IS_ENABLED(LOG)
 #ifdef LOG_DEBUG
 #define _LOG_DEBUG	LOGL_FORCE_DEBUG
 #else
 #define _LOG_DEBUG	0
 #endif
 
+#if CONFIG_IS_ENABLED(LOG)
+
 /* 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) && \
-	    (_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL)) \
+	if (_LOG_DEBUG != 0 || _l <= _LOG_MAX_LEVEL) \
 		_log((enum log_category_t)(_cat), \
 		     (enum log_level_t)(_l | _LOG_DEBUG), __FILE__, \
 		     __LINE__, __func__, \
@@ -229,7 +218,14 @@ int _log_buffer(enum log_category_t cat, enum log_level_t level,
 			    _width, _count, _linelen); \
 	})
 #else
-#define log(_cat, _level, _fmt, _args...)
+
+/* Note: _LOG_DEBUG != 0 avoids a warning with clang */
+#define log(_cat, _level, _fmt, _args...) ({ \
+	int _l = _level; \
+	if (_LOG_DEBUG != 0 || _l <= LOGL_INFO || \
+	    (_DEBUG && _l == LOGL_DEBUG)) \
+		printf(_fmt, ##_args); \
+	})
 
 #define log_buffer(_cat, _level, _addr, _data, _width, _count, _linelen)  ({ \
 	int _l = _level; \
diff --git a/test/log/Makefile b/test/log/Makefile
index 09f8689d070..08eea70e344 100644
--- a/test/log/Makefile
+++ b/test/log/Makefile
@@ -20,6 +20,7 @@ obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o
 obj-y += pr_cont_test.o
 else
 obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o
+obj-$(CONFIG_CONSOLE_RECORD) += nolog_ndebug.o
 endif
 
 endif # CONFIG_UT_LOG
diff --git a/test/log/nolog_ndebug.c b/test/log/nolog_ndebug.c
new file mode 100644
index 00000000000..bd9a4f408e7
--- /dev/null
+++ b/test/log/nolog_ndebug.c
@@ -0,0 +1,39 @@
+// SPDX-License-Identifier: GPL-2.0+
+/*
+ * Copyright 2021 Google LLC
+ *
+ * Logging function tests for CONFIG_LOG=n without #define DEBUG
+ */
+
+#include <common.h>
+#include <console.h>
+#include <log.h>
+#include <asm/global_data.h>
+#include <test/log.h>
+#include <test/ut.h>
+
+DECLARE_GLOBAL_DATA_PTR;
+
+#define BUFFSIZE 32
+
+static int log_test_log_disabled_ndebug(struct unit_test_state *uts)
+{
+	char buf[BUFFSIZE];
+	int i;
+
+	memset(buf, 0, BUFFSIZE);
+	console_record_reset_enable();
+
+	/* Output a log record at every level */
+	for (i = LOGL_EMERG; i < LOGL_COUNT; i++)
+		log(LOGC_NONE, i, "testing level %i\n", i);
+	gd->flags &= ~GD_FLG_RECORD;
+
+	/* Since DEBUG is not defined, we expect to not get debug output */
+	for (i = LOGL_EMERG; i < LOGL_DEBUG; i++)
+		ut_assertok(ut_check_console_line(uts, "testing level %d", i));
+	ut_assertok(ut_check_console_end(uts));
+
+	return 0;
+}
+LOG_TEST(log_test_log_disabled_ndebug);
diff --git a/test/log/nolog_test.c b/test/log/nolog_test.c
index cb4fb3db9a2..4e52e5bed82 100644
--- a/test/log/nolog_test.c
+++ b/test/log/nolog_test.c
@@ -10,6 +10,7 @@
 
 #include <common.h>
 #include <console.h>
+#include <log.h>
 #include <asm/global_data.h>
 #include <test/log.h>
 #include <test/test.h>
@@ -128,8 +129,10 @@ static int log_test_nolog_debug(struct unit_test_state *uts)
 	memset(buf, 0, BUFFSIZE);
 	console_record_reset_enable();
 	log_debug("testing %s\n", "log_debug");
+	log(LOGC_NONE, LOGL_DEBUG, "more %s\n", "log_debug");
 	gd->flags &= ~GD_FLG_RECORD;
 	ut_assertok(ut_check_console_line(uts, "testing log_debug"));
+	ut_assertok(ut_check_console_line(uts, "more log_debug"));
 	ut_assertok(ut_check_console_end(uts));
 	return 0;
 }
-- 
2.31.1.607.g51e8a6a459-goog

Re: [PATCH v4 0/2] log: Allow multiple lines and conversion to printf()

[Tom Rini]

[-- Attachment #1: Type: text/plain, Size: 752 bytes --]

On Sat, May 08, 2021 at 01:46:52PM -0600, Simon Glass wrote:

> At present when logging is not enabled, all log() calls become nops. This
> does not seem right, since if the log level is high enough then there
> should be some sort of message. So in that case, this series updates it to
> print the message if the log level is above LOGL_INFO.
> 
> This mimics the behaviour for the log_...() macros like log_debug() and
> log_info(), so we can drop the special case for these.
> 
> Also the current implementation does not support multiple log calls on the
> same line nicely. The tags are repeated so the line is very hard to read.
> This series adds that as a new feature.

For the series, applied to u-boot/next, thanks!

-- 
Tom

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 659 bytes --]