[PATCH v3 0/2] log: don't show function by default

[PATCH v3 0/2] log: don't show function by default

[Heinrich Schuchardt]

When replacing printf() by log function calls it is not desirable to output
calling function name. So we should adjust the default log format to show
the message only.

Using the BIT() macro makes the log format related coding more readable.

Heinrich Schuchardt (2):
  log: don't show function by default
  log: use BIT() instead of 1 <<

 cmd/log.c                 |  4 ++--
 common/Kconfig            | 18 ++++++++++++++++++
 common/log.c              |  2 +-
 common/log_console.c      | 14 +++++++-------
 common/log_syslog.c       | 14 +++++++-------
 include/log.h             | 19 +++++++++++++++++--
 test/log/syslog_test.c    | 20 ++++++++++++++------
 test/py/tests/test_log.py |  2 ++
 8 files changed, 68 insertions(+), 25 deletions(-)

--
2.27.0

[PATCH v3 1/2] log: don't show function by default

[Heinrich Schuchardt]

The name of the function emitting a log message may be of interest for a
developer but is distracting for normal users. See the example below:

    try_load_entry() Booting: Debian

Make the default format for log messages customizable. By default show
only the message text.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
v3:
	replace #ifdef by IS_ENABLED()
---
 cmd/log.c                 |  4 ++--
 common/Kconfig            | 18 ++++++++++++++++++
 common/log.c              |  2 +-
 include/log.h             | 19 +++++++++++++++++--
 test/log/syslog_test.c    | 20 ++++++++++++++------
 test/py/tests/test_log.py |  2 ++
 6 files changed, 54 insertions(+), 11 deletions(-)

diff --git a/cmd/log.c b/cmd/log.c
index 78352b2cb9..6afe6ead25 100644
--- a/cmd/log.c
+++ b/cmd/log.c
@@ -39,7 +39,7 @@ static int do_log_format(struct cmd_tbl *cmdtp, int flag, int argc,
 		const char *str = argv[1];

 		if (!strcmp(str, "default")) {
-			gd->log_fmt = LOGF_DEFAULT;
+			gd->log_fmt = log_get_default_format();
 		} else if (!strcmp(str, "all")) {
 			gd->log_fmt = LOGF_ALL;
 		} else {
@@ -139,7 +139,7 @@ static char log_help_text[] =
 	"log format <fmt> - set log output format. <fmt> is a string where\n"
 	"\teach letter indicates something that should be displayed:\n"
 	"\tc=category, l=level, F=file, L=line number, f=function, m=msg\n"
-	"\tor 'default', equivalent to 'fm', or 'all' for all\n"
+	"\tor 'default', or 'all' for all\n"
 	"log rec <category> <level> <file> <line> <func> <message> - "
 		"output a log record"
 	;
diff --git a/common/Kconfig b/common/Kconfig
index 7872bc46cd..60cae77f20 100644
--- a/common/Kconfig
+++ b/common/Kconfig
@@ -792,6 +792,24 @@ config TPL_LOG_CONSOLE

 endif

+config LOGF_FILE
+	bool "Show source file name in log messages by default"
+	help
+	  Show the source file name in log messages by default. This value
+	  can be overridden using the 'log format' command.
+
+config LOGF_LINE
+	bool "Show source line number in log messages by default"
+	help
+	  Show the source line number in log messages by default. This value
+	  can be overridden using the 'log format' command.
+
+config LOGF_FUNC
+	bool "Show function name in log messages by default"
+	help
+	  Show the function name in log messages by default. This value can
+	  be overridden using the 'log format' command.
+
 config LOG_ERROR_RETURN
 	bool "Log all functions which return an error"
 	help
diff --git a/common/log.c b/common/log.c
index c5b9b489ca..9005b3afb2 100644
--- a/common/log.c
+++ b/common/log.c
@@ -317,7 +317,7 @@ int log_init(void)
 	gd->flags |= GD_FLG_LOG_READY;
 	if (!gd->default_log_level)
 		gd->default_log_level = CONFIG_LOG_DEFAULT_LEVEL;
-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
diff --git a/include/log.h b/include/log.h
index df65398c04..21f9b75278 100644
--- a/include/log.h
+++ b/include/log.h
@@ -12,6 +12,7 @@
 #include <stdio.h>
 #include <linker_lists.h>
 #include <dm/uclass-id.h>
+#include <linux/bitops.h>
 #include <linux/list.h>

 struct cmd_tbl;
@@ -409,9 +410,7 @@ enum log_fmt {
 	LOGF_LINE,
 	LOGF_FUNC,
 	LOGF_MSG,
-
 	LOGF_COUNT,
-	LOGF_DEFAULT = (1 << LOGF_FUNC) | (1 << LOGF_MSG),
 	LOGF_ALL = 0x3f,
 };

@@ -460,4 +459,20 @@ static inline int log_init(void)
 }
 #endif

+/**
+ * log_get_default_format() - get default log format
+ *
+ * The default log format is configurable via
+ * CONFIG_LOGF_FILE, CONFIG_LOGF_LINE, CONFIG_LOGF_FUNC.
+ *
+ * Return:	default log format
+ */
+static inline int log_get_default_format(void)
+{
+	return BIT(LOGF_MSG) |
+	       (IS_ENABLED(CONFIG_LOGF_FILE) ? BIT(LOGF_FILE) : 0) |
+	       (IS_ENABLED(CONFIG_LOGF_LINE) ? BIT(LOGF_LINE) : 0) |
+	       (IS_ENABLED(CONFIG_LOGF_FUNC) ? BIT(LOGF_FUNC) : 0);
+}
+
 #endif
diff --git a/test/log/syslog_test.c b/test/log/syslog_test.c
index 26536ebca7..120a8b2537 100644
--- a/test/log/syslog_test.c
+++ b/test/log/syslog_test.c
@@ -21,6 +21,8 @@

 DECLARE_GLOBAL_DATA_PTR;

+#define LOGF_TEST (BIT(LOGF_FUNC) | BIT(LOGF_MSG))
+
 /**
  * struct sb_log_env - private data for sandbox ethernet driver
  *
@@ -102,7 +104,7 @@ static int log_test_syslog_err(struct unit_test_state *uts)
 	int old_log_level = gd->default_log_level;
 	struct sb_log_env env;

-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_INFO;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -116,6 +118,7 @@ static int log_test_syslog_err(struct unit_test_state *uts)
 	/* Check that the callback function was called */
 	sandbox_eth_set_tx_handler(0, NULL);
 	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
@@ -132,7 +135,7 @@ static int log_test_syslog_warning(struct unit_test_state *uts)
 	int old_log_level = gd->default_log_level;
 	struct sb_log_env env;

-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_INFO;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -147,6 +150,7 @@ static int log_test_syslog_warning(struct unit_test_state *uts)
 	/* Check that the callback function was called */
 	ut_assertnull(env.expected);
 	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
@@ -163,7 +167,7 @@ static int log_test_syslog_notice(struct unit_test_state *uts)
 	int old_log_level = gd->default_log_level;
 	struct sb_log_env env;

-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_INFO;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -178,6 +182,7 @@ static int log_test_syslog_notice(struct unit_test_state *uts)
 	/* Check that the callback function was called */
 	ut_assertnull(env.expected);
 	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
@@ -194,7 +199,7 @@ static int log_test_syslog_info(struct unit_test_state *uts)
 	int old_log_level = gd->default_log_level;
 	struct sb_log_env env;

-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_INFO;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -209,6 +214,7 @@ static int log_test_syslog_info(struct unit_test_state *uts)
 	/* Check that the callback function was called */
 	ut_assertnull(env.expected);
 	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
@@ -225,7 +231,7 @@ static int log_test_syslog_debug(struct unit_test_state *uts)
 	int old_log_level = gd->default_log_level;
 	struct sb_log_env env;

-	gd->log_fmt = LOGF_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_DEBUG;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -240,6 +246,7 @@ static int log_test_syslog_debug(struct unit_test_state *uts)
 	/* Check that the callback function was called */
 	ut_assertnull(env.expected);
 	gd->default_log_level = old_log_level;
+	gd->log_fmt = log_get_default_format();

 	return 0;
 }
@@ -259,7 +266,7 @@ 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_DEFAULT;
+	gd->log_fmt = LOGF_TEST;
 	gd->default_log_level = LOGL_INFO;
 	env_set("ethact", "eth at 10002000");
 	env_set("log_hostname", "sandbox");
@@ -274,6 +281,7 @@ static int log_test_syslog_nodebug(struct unit_test_state *uts)
 	/* 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;
 }
diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py
index 75325fad61..ddc28f19ee 100644
--- a/test/py/tests/test_log.py
+++ b/test/py/tests/test_log.py
@@ -39,6 +39,8 @@ def test_log(u_boot_console):
         Returns:
             iterator containing the lines output from the command
         """
+        output = u_boot_console.run_command('log format fm')
+        assert output == ''
         with cons.log.section('basic'):
            output = u_boot_console.run_command('log test %d' % testnum)
         split = output.replace('\r', '').splitlines()
--
2.27.0

[PATCH v3 2/2] log: use BIT() instead of 1 <<

[Heinrich Schuchardt]

Use the BIT() macro when creating a bitmask for the logging fields.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
v3:
	new patch
---
 common/log_console.c | 14 +++++++-------
 common/log_syslog.c  | 14 +++++++-------
 2 files changed, 14 insertions(+), 14 deletions(-)

diff --git a/common/log_console.c b/common/log_console.c
index 0b5b7089af..bb3f8464b9 100644
--- a/common/log_console.c
+++ b/common/log_console.c
@@ -25,18 +25,18 @@ static int log_console_emit(struct log_device *ldev, struct log_rec *rec)
 	 *    - function is an identifier and ends with ()
 	 *    - message has a space before it unless it is on its own
 	 */
-	if (fmt & (1 << LOGF_LEVEL))
+	if (fmt & BIT(LOGF_LEVEL))
 		printf("%s.", log_get_level_name(rec->level));
-	if (fmt & (1 << LOGF_CAT))
+	if (fmt & BIT(LOGF_CAT))
 		printf("%s,", log_get_cat_name(rec->cat));
-	if (fmt & (1 << LOGF_FILE))
+	if (fmt & BIT(LOGF_FILE))
 		printf("%s:", rec->file);
-	if (fmt & (1 << LOGF_LINE))
+	if (fmt & BIT(LOGF_LINE))
 		printf("%d-", rec->line);
-	if (fmt & (1 << LOGF_FUNC))
+	if (fmt & BIT(LOGF_FUNC))
 		printf("%s()", rec->func);
-	if (fmt & (1 << LOGF_MSG))
-		printf("%s%s", fmt != (1 << LOGF_MSG) ? " " : "", rec->msg);
+	if (fmt & BIT(LOGF_MSG))
+		printf("%s%s", fmt != BIT(LOGF_MSG) ? " " : "", rec->msg);

 	return 0;
 }
diff --git a/common/log_syslog.c b/common/log_syslog.c
index 698c585fa1..149ff5af31 100644
--- a/common/log_syslog.c
+++ b/common/log_syslog.c
@@ -82,21 +82,21 @@ static int log_syslog_emit(struct log_device *ldev, struct log_rec *rec)
 	if (log_hostname)
 		append(&ptr, msg_end, "%s ", log_hostname);
 	append(&ptr, msg_end, "uboot: ");
-	if (fmt & (1 << LOGF_LEVEL))
+	if (fmt & BIT(LOGF_LEVEL))
 		append(&ptr, msg_end, "%s.",
 		       log_get_level_name(rec->level));
-	if (fmt & (1 << LOGF_CAT))
+	if (fmt & BIT(LOGF_CAT))
 		append(&ptr, msg_end, "%s,",
 		       log_get_cat_name(rec->cat));
-	if (fmt & (1 << LOGF_FILE))
+	if (fmt & BIT(LOGF_FILE))
 		append(&ptr, msg_end, "%s:", rec->file);
-	if (fmt & (1 << LOGF_LINE))
+	if (fmt & BIT(LOGF_LINE))
 		append(&ptr, msg_end, "%d-", rec->line);
-	if (fmt & (1 << LOGF_FUNC))
+	if (fmt & BIT(LOGF_FUNC))
 		append(&ptr, msg_end, "%s()", rec->func);
-	if (fmt & (1 << LOGF_MSG))
+	if (fmt & BIT(LOGF_MSG))
 		append(&ptr, msg_end, "%s%s",
-		       fmt != (1 << LOGF_MSG) ? " " : "", rec->msg);
+		       fmt != BIT(LOGF_MSG) ? " " : "", rec->msg);
 	/* Consider trailing 0x00 */
 	ptr++;

--
2.27.0

[PATCH v3 1/2] log: don't show function by default

[Simon Glass]

Hi Heinrich,

On Mon, 15 Jun 2020 at 13:24, Heinrich Schuchardt <xypron.glpk@gmx.de> wrote:
>
> The name of the function emitting a log message may be of interest for a
> developer but is distracting for normal users. See the example below:
>
>     try_load_entry() Booting: Debian
>
> Make the default format for log messages customizable. By default show
> only the message text.
>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
> v3:
>         replace #ifdef by IS_ENABLED()
> ---
>  cmd/log.c                 |  4 ++--
>  common/Kconfig            | 18 ++++++++++++++++++
>  common/log.c              |  2 +-
>  include/log.h             | 19 +++++++++++++++++--
>  test/log/syslog_test.c    | 20 ++++++++++++++------
>  test/py/tests/test_log.py |  2 ++
>  6 files changed, 54 insertions(+), 11 deletions(-)
>

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

nit below

[..]

> diff --git a/include/log.h b/include/log.h
> index df65398c04..21f9b75278 100644
> --- a/include/log.h
> +++ b/include/log.h
> @@ -12,6 +12,7 @@
>  #include <stdio.h>
>  #include <linker_lists.h>
>  #include <dm/uclass-id.h>
> +#include <linux/bitops.h>
>  #include <linux/list.h>
>
>  struct cmd_tbl;
> @@ -409,9 +410,7 @@ enum log_fmt {
>         LOGF_LINE,
>         LOGF_FUNC,
>         LOGF_MSG,
> -

Can we keep that? I makes it easier to see the 'real' enum values and
the ones that are used for maintenance below:

>         LOGF_COUNT,
> -       LOGF_DEFAULT = (1 << LOGF_FUNC) | (1 << LOGF_MSG),
>         LOGF_ALL = 0x3f,
>  };
>
> @@ -460,4 +459,20 @@ static inline int log_init(void)
>  }
>  #endif
>

Regards,
Simon

[PATCH v3 2/2] log: use BIT() instead of 1 <<

[Simon Glass]

On Mon, 15 Jun 2020 at 13:24, Heinrich Schuchardt <xypron.glpk@gmx.de> wrote:
>
> Use the BIT() macro when creating a bitmask for the logging fields.
>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
> v3:
>         new patch
> ---
>  common/log_console.c | 14 +++++++-------
>  common/log_syslog.c  | 14 +++++++-------
>  2 files changed, 14 insertions(+), 14 deletions(-)
>

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