[PATCH v2 0/3] log: allow for message continuation

[PATCH v2 0/3] log: allow for message continuation

[Heinrich Schuchardt]

The first patch move a static variable to the global data.

With the second patch it becomes possible to continue a log message with
the same log level and category as the previous messages.

We need this facility to convert pr_cont() to use our logging drivers.

The third patch provides a unit test.

v2:
	move static variables to global data

Heinrich Schuchardt (3):
  log: move processing_msg to global data
  log: allow for message continuation
  test: log: test message continuation

 common/log.c                      | 30 ++++++++++++------
 doc/develop/logging.rst           |  6 ++++
 include/asm-generic/global_data.h | 20 ++++++++++++
 include/log.h                     |  2 ++
 test/log/Makefile                 |  4 ++-
 test/log/cont_test.c              | 52 +++++++++++++++++++++++++++++++
 6 files changed, 104 insertions(+), 10 deletions(-)
 create mode 100644 test/log/cont_test.c

--
2.28.0

[PATCH v2 1/3] log: move processing_msg to global data

[Heinrich Schuchardt]

Replace the static variable processing_msg by a field in the global data.
Make the field bool at it can only be true or false.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
v2:
	new patch
---
 common/log.c                      | 7 +++----
 include/asm-generic/global_data.h | 8 ++++++++
 2 files changed, 11 insertions(+), 4 deletions(-)

diff --git a/common/log.c b/common/log.c
index 1b10f6f180..f95f09c1b6 100644
--- a/common/log.c
+++ b/common/log.c
@@ -194,24 +194,23 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec)
 static int log_dispatch(struct log_rec *rec)
 {
 	struct log_device *ldev;
-	static int processing_msg;

 	/*
 	 * When a log driver writes messages (e.g. via the network stack) this
 	 * may result in further generated messages. We cannot process them here
 	 * as this might result in infinite recursion.
 	 */
-	if (processing_msg)
+	if (gd->processing_msg)
 		return 0;

 	/* Emit message */
-	processing_msg = 1;
+	gd->processing_msg = true;
 	list_for_each_entry(ldev, &gd->log_head, sibling_node) {
 		if ((ldev->flags & LOGDF_ENABLE) &&
 		    log_passes_filters(ldev, rec))
 			ldev->drv->emit(ldev, rec);
 	}
-	processing_msg = 0;
+	gd->processing_msg = false;
 	return 0;
 }

diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h
index ebb740d34f..db83f59ceb 100644
--- a/include/asm-generic/global_data.h
+++ b/include/asm-generic/global_data.h
@@ -363,6 +363,14 @@ struct global_data {
 	 * &enum log_fmt defines the bits of the bit mask.
 	 */
 	int log_fmt;
+
+	/**
+	 * @processing_msg: a log message is being processed
+	 *
+	 * This flag is used to suppress the creation of additional messages
+	 * while another message is being processed.
+	 */
+	bool processing_msg;
 #endif
 #if CONFIG_IS_ENABLED(BLOBLIST)
 	/**
--
2.28.0

[PATCH v2 2/3] log: allow for message continuation

[Heinrich Schuchardt]

Some drivers use macro pr_cont() for continuing a message sent via printk.
Hence if we want to convert printk messaging to using the logging system,
we must support continuation of log messages too.

As pr_cont() does not provide a message level we need a means of
remembering the last log level.

With the patch a pseudo log level LOGL_CONT as well as a pseudo log
category LOGC_CONT are introduced. Using these results in the application
of the same log level and category as in the previous log message.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
---
v2:
	replace static variables by global data
---
 common/log.c                      | 23 ++++++++++++++++++-----
 doc/develop/logging.rst           |  6 ++++++
 include/asm-generic/global_data.h | 12 ++++++++++++
 include/log.h                     |  2 ++
 4 files changed, 38 insertions(+), 5 deletions(-)

diff --git a/common/log.c b/common/log.c
index f95f09c1b6..58be9f7440 100644
--- a/common/log.c
+++ b/common/log.c
@@ -186,10 +186,12 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec)
  * log_dispatch() - Send a log record to all log devices for processing
  *
  * The log record is sent to each log device in turn, skipping those which have
- * filters which block the record
+ * filters which block the record.
  *
- * @rec: Log record to dispatch
- * @return 0 (meaning success)
+ * All log messages created while processing log record @rec are ignored.
+ *
+ * @rec:	log record to dispatch
+ * Return:	0 msg sent, 1 msg not sent while already dispatching another msg
  */
 static int log_dispatch(struct log_rec *rec)
 {
@@ -201,7 +203,7 @@ static int log_dispatch(struct log_rec *rec)
 	 * as this might result in infinite recursion.
 	 */
 	if (gd->processing_msg)
-		return 0;
+		return 1;

 	/* Emit message */
 	gd->processing_msg = true;
@@ -221,6 +223,12 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	struct log_rec rec;
 	va_list args;

+	/* Check for message continuation */
+	if (cat == LOGC_CONT)
+		cat = gd->logc_prev;
+	if (level == LOGL_CONT)
+		level = gd->logl_prev;
+
 	rec.cat = cat;
 	rec.level = level & LOGL_LEVEL_MASK;
 	rec.force_debug = level & LOGL_FORCE_DEBUG;
@@ -236,7 +244,10 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 			gd->log_drop_count++;
 		return -ENOSYS;
 	}
-	log_dispatch(&rec);
+	if (!log_dispatch(&rec)) {
+		gd->logc_prev = cat;
+		gd->logl_prev = level;
+	}

 	return 0;
 }
@@ -376,6 +387,8 @@ int log_init(void)
 	if (!gd->default_log_level)
 		gd->default_log_level = CONFIG_LOG_DEFAULT_LEVEL;
 	gd->log_fmt = log_get_default_format();
+	gd->logc_prev = LOGC_NONE;
+	gd->logl_prev = LOGL_INFO;

 	return 0;
 }
diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst
index 7ce8482ab6..c36f6bbbe4 100644
--- a/doc/develop/logging.rst
+++ b/doc/develop/logging.rst
@@ -38,6 +38,9 @@ There are a number logging levels available, in increasing order of verbosity:
 * LOGL_DEBUG_CONTENT - Debug message showing full message content
 * LOGL_DEBUG_IO - Debug message showing hardware I/O access

+To continue a log message in a separate call of function log() use
+
+* LOGL_CONT - Use same log level as in previous call

 Logging category
 ----------------
@@ -56,6 +59,9 @@ The following main categories are defined:
 * LOGC_DT - Related to device tree control
 * LOGC_EFI - Related to EFI implementation

+To continue a log message in a separate call of function log() use
+
+* LOGC_CONT - Use same category as in previous call

 Enabling logging
 ----------------
diff --git a/include/asm-generic/global_data.h b/include/asm-generic/global_data.h
index db83f59ceb..0157af1aa4 100644
--- a/include/asm-generic/global_data.h
+++ b/include/asm-generic/global_data.h
@@ -371,6 +371,18 @@ struct global_data {
 	 * while another message is being processed.
 	 */
 	bool processing_msg;
+	/**
+	 * @logc_prev: logging category of previous message
+	 *
+	 * This value is used as logging category for continuation messages.
+	 */
+	int logc_prev;
+	/**
+	 * @logl_pref: logging level of the previous message
+	 *
+	 * This value is used as logging level for continuation messages.
+	 */
+	int logl_prev;
 #endif
 #if CONFIG_IS_ENABLED(BLOBLIST)
 	/**
diff --git a/include/log.h b/include/log.h
index 4acc087b2e..73cfb6153c 100644
--- a/include/log.h
+++ b/include/log.h
@@ -38,6 +38,7 @@ enum log_level_t {

 	LOGL_FIRST = LOGL_EMERG,
 	LOGL_MAX = LOGL_DEBUG_IO,
+	LOGL_CONT = -1,		/* Use same log level as in previous call */
 };

 /**
@@ -63,6 +64,7 @@ enum log_category_t {

 	LOGC_COUNT,	/* Number of log categories */
 	LOGC_END,	/* Sentinel value for a list of log categories */
+	LOGC_CONT = -1,	/* Use same category as in previous call */
 };

 /* Helper to cast a uclass ID to a log category */
--
2.28.0

[PATCH v2 3/3] test: log: test message continuation

[Heinrich Schuchardt]

Provide a unit test checking that a continuation message will use the same
log level and log category as the previous message.

Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
Reviewed-by: Simon Glass <sjg@chromium.org>
---
v2:
	rebased
---
 test/log/Makefile    |  4 +++-
 test/log/cont_test.c | 52 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 55 insertions(+), 1 deletion(-)
 create mode 100644 test/log/cont_test.c

diff --git a/test/log/Makefile b/test/log/Makefile
index 52e2f7b41c..fdf529582d 100644
--- a/test/log/Makefile
+++ b/test/log/Makefile
@@ -13,7 +13,9 @@ obj-$(CONFIG_LOG_SYSLOG) += syslog_test.o
 obj-$(CONFIG_LOG_SYSLOG) += syslog_test_ndebug.o
 endif

-ifndef CONFIG_LOG
+ifdef CONFIG_LOG
+obj-$(CONFIG_CONSOLE_RECORD) += cont_test.o
+else
 obj-$(CONFIG_CONSOLE_RECORD) += nolog_test.o
 endif

diff --git a/test/log/cont_test.c b/test/log/cont_test.c
new file mode 100644
index 0000000000..68ca1d262c
--- /dev/null
+++ b/test/log/cont_test.c
@@ -0,0 +1,52 @@
+// SPDX-License-Identifier: GPL-2.0+
+/*
+ * Copyright (c) 2020, Heinrich Schuchardt <xypron.glpk@gmx.de>
+ *
+ * Test continuation of log messages.
+ */
+
+#include <common.h>
+#include <console.h>
+#include <test/log.h>
+#include <test/test.h>
+#include <test/suites.h>
+#include <test/ut.h>
+
+DECLARE_GLOBAL_DATA_PTR;
+
+#define BUFFSIZE 64
+
+static int log_test_cont(struct unit_test_state *uts)
+{
+	int log_fmt;
+	int log_level;
+
+	log_fmt = gd->log_fmt;
+	log_level = gd->default_log_level;
+
+	/* Write two messages, the second continuing the first */
+	gd->log_fmt = (1 << LOGF_CAT) | (1 << LOGF_LEVEL) | (1 << LOGF_MSG);
+	gd->default_log_level = LOGL_INFO;
+	console_record_reset_enable();
+	log(LOGC_ARCH, LOGL_ERR, "ea%d ", 1);
+	log(LOGC_CONT, LOGL_CONT, "cc%d\n", 2);
+	gd->default_log_level = log_level;
+	gd->log_fmt = log_fmt;
+	gd->flags &= ~GD_FLG_RECORD;
+	ut_assertok(ut_check_console_line(uts, "ERR.arch, ea1 ERR.arch, cc2"));
+	ut_assertok(ut_check_console_end(uts));
+
+	/* Write a third message which is not a continuation */
+	gd->log_fmt = (1 << LOGF_CAT) | (1 << LOGF_LEVEL) | (1 << LOGF_MSG);
+	gd->default_log_level = LOGL_INFO;
+	console_record_reset_enable();
+	log(LOGC_EFI, LOGL_INFO, "ie%d\n", 3);
+	gd->default_log_level = log_level;
+	gd->log_fmt = log_fmt;
+	gd->flags &= ~GD_FLG_RECORD;
+	ut_assertok(ut_check_console_line(uts, "INFO.efi, ie3"));
+	ut_assertok(ut_check_console_end(uts));
+
+	return 0;
+}
+LOG_TEST(log_test_cont);
--
2.28.0

[PATCH v2 1/3] log: move processing_msg to global data

[Simon Glass]

On Sat, 17 Oct 2020 at 06:32, Heinrich Schuchardt <xypron.glpk@gmx.de> wrote:
>
> Replace the static variable processing_msg by a field in the global data.
> Make the field bool at it can only be true or false.
>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
> v2:
>         new patch
> ---
>  common/log.c                      | 7 +++----
>  include/asm-generic/global_data.h | 8 ++++++++
>  2 files changed, 11 insertions(+), 4 deletions(-)
>

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

[PATCH v2 2/3] log: allow for message continuation

[Simon Glass]

On Sat, 17 Oct 2020 at 06:32, Heinrich Schuchardt <xypron.glpk@gmx.de> wrote:
>
> Some drivers use macro pr_cont() for continuing a message sent via printk.
> Hence if we want to convert printk messaging to using the logging system,
> we must support continuation of log messages too.
>
> As pr_cont() does not provide a message level we need a means of
> remembering the last log level.
>
> With the patch a pseudo log level LOGL_CONT as well as a pseudo log
> category LOGC_CONT are introduced. Using these results in the application
> of the same log level and category as in the previous log message.
>
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> ---
> v2:
>         replace static variables by global data
> ---
>  common/log.c                      | 23 ++++++++++++++++++-----
>  doc/develop/logging.rst           |  6 ++++++
>  include/asm-generic/global_data.h | 12 ++++++++++++
>  include/log.h                     |  2 ++
>  4 files changed, 38 insertions(+), 5 deletions(-)
>

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

[PATCH v2 1/3] log: move processing_msg to global data

[Tom Rini]

On Sat, Oct 17, 2020 at 02:31:57PM +0200, Heinrich Schuchardt wrote:

> Replace the static variable processing_msg by a field in the global data.
> Make the field bool at it can only be true or false.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20201028/6d13e118/attachment.sig>

[PATCH v2 2/3] log: allow for message continuation

[Tom Rini]

On Sat, Oct 17, 2020 at 02:31:58PM +0200, Heinrich Schuchardt wrote:

> Some drivers use macro pr_cont() for continuing a message sent via printk.
> Hence if we want to convert printk messaging to using the logging system,
> we must support continuation of log messages too.
> 
> As pr_cont() does not provide a message level we need a means of
> remembering the last log level.
> 
> With the patch a pseudo log level LOGL_CONT as well as a pseudo log
> category LOGC_CONT are introduced. Using these results in the application
> of the same log level and category as in the previous log message.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20201028/47ad9eab/attachment.sig>

[PATCH v2 3/3] test: log: test message continuation

[Tom Rini]

On Sat, Oct 17, 2020 at 02:31:59PM +0200, Heinrich Schuchardt wrote:

> Provide a unit test checking that a continuation message will use the same
> log level and log category as the previous message.
> 
> Signed-off-by: Heinrich Schuchardt <xypron.glpk@gmx.de>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20201028/dd535214/attachment.sig>