logging: Add an option for a custom log header

There are scenarios when it is necessary to globally redefine
a log macro. The existing logging frontend is not sufficient since
it redirects at the function level.

One example is using pigweed_tokenzier. The pigweed tokenizer depends
on intercepting log strings at the macro level to function.

Introduce an option to include a custom application provided header
named "zephyr_custom_log.h" at the end of log.h. This allows an
application to extend the LOG_* macros globally.

This change includes a simple test that redefines the core LOG macros
to include a custom prefix.

Signed-off-by: Rob Barnes <robbarnes@google.com>

doc/services/logging/index.rst

@@ -142,6 +142,8 @@ packet buffer.
 
 :kconfig:option:`CONFIG_LOG_FRONTEND_ONLY`: No backends are used when messages goes to frontend.
 
+:kconfig:option:`CONFIG_LOG_CUSTOM_HEADER`: Injects an application provided header into log.h
+
 :kconfig:option:`CONFIG_LOG_TIMESTAMP_64BIT`: 64 bit timestamp.
 
 Formatting options:
@@ -483,6 +485,10 @@ If option :kconfig:option:`CONFIG_LOG_FRONTEND_ONLY` is enabled then log message
 created and no backend is handled. Otherwise, custom frontend can coexist with
 backends.
 
+In some cases, logs need to be redirected at the macro level. For these cases,
+:kconfig:option:`CONFIG_LOG_CUSTOM_HEADER` can be used to inject an application provided
+header named `zephyr_custom_log.h` at the end of :zephyr_file:`include/zephyr/logging/log.h`.
+
 .. _logging_strings:
 
 Logging strings

include/zephyr/logging/log.h

@@ -427,6 +427,11 @@ void z_log_vprintk(const char *fmt, va_list ap);
 #define LOG_LEVEL_SET(level) static const uint32_t __log_level __unused = \
 				Z_LOG_RESOLVED_LEVEL(level, 0)
 
+#ifdef CONFIG_LOG_CUSTOM_HEADER
+/* This include must always be at the end of log.h */
+#include <zephyr_custom_log.h>
+#endif
+
 /*
  * Eclipse CDT or JetBrains Clion parser is sometimes confused by logging API
  * code and freezes the whole IDE. Following lines hides LOG_x macros from them.

subsys/logging/Kconfig.mode

@@ -43,7 +43,8 @@ config LOG_FRONTEND
 	bool "Frontend"
 	help
 	  When enabled, logs are redirected to a custom frontend which is the
-	  fastest way of getting logs out.
+	  fastest way of getting logs out. The logs are redirected at the function
+	  level. To redirect logs at the macro level, see LOG_CUSTOM_HEADER.
 
 config LOG_FRONTEND_ONLY
 	bool "No backends"
@@ -52,6 +53,14 @@ config LOG_FRONTEND_ONLY
 	  Option indicates that there are no backends intended to be used.
 	  Code asserts if any backend is enabled.
 
+config LOG_CUSTOM_HEADER
+	bool "Include Custom Log Header"
+	help
+	  When enabled, a custom application provided header, named
+	  "zephyr_custom_log.h", is included at the end of log.h. This enables
+	  extension of the LOG_* APIs at the macro level. Please use cautiously!
+	  The internal LOG API may change in future releases.
+
 config LOG_DEFAULT_MINIMAL
 	bool
 

tests/subsys/logging/log_custom_header/CMakeLists.txt

@@ -0,0 +1,10 @@
+# SPDX-License-Identifier: Apache-2.0
+
+cmake_minimum_required(VERSION 3.20.0)
+find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
+project(log_custom_header)
+
+FILE(GLOB app_sources src/*.c)
+target_sources(app PRIVATE ${app_sources})
+
+zephyr_include_directories(src)

tests/subsys/logging/log_custom_header/prj.conf

@@ -0,0 +1,8 @@
+CONFIG_ZTEST=y
+CONFIG_ZTEST_NEW_API=y
+CONFIG_LOG=y
+CONFIG_LOG_OUTPUT=y
+CONFIG_LOG_PRINTK=n
+CONFIG_LOG_CUSTOM_HEADER=y
+CONFIG_LOG_MODE_IMMEDIATE=y
+CONFIG_LOG_FUNC_NAME_PREFIX_DBG=n

tests/subsys/logging/log_custom_header/src/log_custom_header.c

@@ -0,0 +1,95 @@
+/*
+ * Copyright (c) 2018 Nordic Semiconductor
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+/**
+ * @file
+ * @brief Test Custom Log Header
+ */
+
+#include <zephyr/kernel.h>
+#include <zephyr/toolchain.h>
+#include <zephyr/ztest.h>
+#include <zephyr/logging/log_backend.h>
+#include <zephyr/logging/log_ctrl.h>
+#include <zephyr/logging/log.h>
+
+LOG_MODULE_REGISTER(test, LOG_LEVEL_DBG);
+
+static uint32_t count;
+static char output[512];
+
+static int cbprintf_callback(int c, void *ctx)
+{
+	char **p = ctx;
+	**p = c;
+	(*p)++;
+	return c;
+}
+
+static void backend_process(const struct log_backend *const backend, union log_msg_generic *msg)
+{
+	char *pstr = output;
+	size_t len;
+	uint8_t *p = log_msg_get_package(&msg->log, &len);
+
+	int slen = cbpprintf(cbprintf_callback, &pstr, p);
+
+	output[slen] = '\0';
+
+	count += 1;
+}
+
+static const struct log_backend_api backend_api = {
+	.process = backend_process,
+};
+
+LOG_BACKEND_DEFINE(backend, backend_api, false);
+
+ZTEST(log_custom_header, test_macro_prefix)
+{
+	zassert_equal(count, 0);
+
+	LOG_DBG("DBG %d", 0);
+	LOG_PROCESS();
+	zassert_equal(count, 1);
+	zassert_mem_equal(output, CUSTOM_LOG_PREFIX "DBG 0", strlen(output));
+
+	LOG_INF("INF %s", "foo");
+	LOG_PROCESS();
+	zassert_equal(count, 2);
+	zassert_mem_equal(output, CUSTOM_LOG_PREFIX "INF foo", strlen(output));
+
+	LOG_WRN("WRN %x", 0xff);
+	LOG_PROCESS();
+	zassert_equal(count, 3);
+	zassert_mem_equal(output, CUSTOM_LOG_PREFIX "WRN ff", strlen(output));
+
+	LOG_ERR("ERR %d %d %d", 1, 2, 3);
+	LOG_PROCESS();
+	zassert_equal(count, 4);
+	zassert_mem_equal(output, CUSTOM_LOG_PREFIX "ERR 1 2 3", strlen(output));
+}
+
+static void *setup(void)
+{
+	log_init();
+	return NULL;
+}
+
+static void before(void *notused)
+{
+	count = 0;
+	output[0] = '\0';
+
+	log_backend_enable(&backend, NULL, LOG_LEVEL_DBG);
+}
+
+static void after(void *notused)
+{
+	log_backend_disable(&backend);
+}
+
+ZTEST_SUITE(log_custom_header, NULL, setup, before, after, NULL);

tests/subsys/logging/log_custom_header/src/zephyr_custom_log.h

@@ -0,0 +1,22 @@
+/*
+ * Copyright (c) 2022 Google, Inc.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef __ZEPHYR_CUSTOM_LOG_H__
+#define __ZEPHYR_CUSTOM_LOG_H__
+
+#define CUSTOM_LOG_PREFIX "[CUSTOM_PREFIX]"
+
+#undef LOG_DBG
+#undef LOG_INF
+#undef LOG_WRN
+#undef LOG_ERR
+
+#define LOG_DBG(...) Z_LOG(LOG_LEVEL_DBG, CUSTOM_LOG_PREFIX __VA_ARGS__)
+#define LOG_INF(...) Z_LOG(LOG_LEVEL_INF, CUSTOM_LOG_PREFIX __VA_ARGS__)
+#define LOG_WRN(...) Z_LOG(LOG_LEVEL_WRN, CUSTOM_LOG_PREFIX __VA_ARGS__)
+#define LOG_ERR(...) Z_LOG(LOG_LEVEL_ERR, CUSTOM_LOG_PREFIX __VA_ARGS__)
+
+#endif /* __ZEPHYR_CUSTOM_LOG_H__ */

tests/subsys/logging/log_custom_header/testcase.yaml

@@ -0,0 +1,7 @@
+common:
+  integration_platforms:
+    - native_posix
+
+tests:
+  logging.log_custom_header:
+    tags: log_custom_header logging