logging: rpc: initial history support

Add initial code for supporting the log history, that is,
the mode of nRF RPC logging library in which log messages
are stored in a ring buffer, and nRF RPC commands can be
used for configuring and fetching the log history.

The rationale for supporting this mode is to reduce the
nRF RPC traffic so that the bandwidth is available for
higher priority tasks, while preserving the possibility
to analyse the logs when an issue occurs.

This commit adds the support for saving the log messages
in the ring buffer. Fetching the logs is still incomplete
though.

Signed-off-by: Damian Krolik <[email protected]>

include/logging/log_rpc.h

@@ -32,10 +32,26 @@ enum log_rpc_level {
 };
 
 /**
- * Sets the logging stream verbosity level.
+ * Log history handler.
  *
- * Configures the remote device to only stream log messages whose level is less
- * than or equal to the specified level.
+ * The type of a callback function that is invoked for each received log message
+ * while fetching the log history from the remote device.
+ *
+ * @param level		The message level, see @c log_rpc_level.
+ * @param msg		A pointer to the message payload.
+ * @param msg_len	The message payload length.
+ */
+typedef void (*log_rpc_history_handler_t)(enum log_rpc_level level, const char *msg,
+					  size_t msg_len);
+
+/**
+ * Sets the log streaming verbosity level.
+ *
+ * The log streaming is the feature of nRF RPC logging that allows receiving log
+ * messages as they are generated by the application running on the remote device.
+ *
+ * This function issues an nRF RPC command that configures the remote device to
+ * stream log messages whose level is less than or equal to the specified level.
  *
  * @param level		Logging level, see @c log_rpc_level.
  *
@@ -44,6 +60,37 @@ enum log_rpc_level {
  */
 int log_rpc_set_stream_level(enum log_rpc_level level);
 
+/**
+ * Sets the log history verbosity level.
+ *
+ * The log history is the feature of nRF RPC logging that allows saving log
+ * messages generated by the application running on the remote device into
+ * a ring buffer, and then retrieving the log history when needed.
+ *
+ * The function issues an nRF RPC command that configures the remote device to
+ * save log messages whose level is less than or equal to the specified level.
+ *
+ * @param level		Logging level, see @c log_rpc_level.
+ *
+ * @retval 0		On success.
+ * @retval -errno	On failure.
+ */
+int log_rpc_set_history_level(enum log_rpc_level level);
+
+/**
+ * Fetches the log history.
+ *
+ * The function issues an nRF RPC command that starts the log history transfer
+ * from the remote device. Each received log message is passed to the provided
+ * callback function.
+ *
+ * @param handler	History handler, see @c log_rpc_history_handler_t.
+ *
+ * @retval 0		On success.
+ * @retval -errno	On failure.
+ */
+int log_rpc_fetch_history(log_rpc_history_handler_t handler);
+
 /**
  * @brief Retrieves the crash log retained on the remote device.
  *

samples/nrf_rpc/protocols_serialization/client/src/log_rpc_shell.c

@@ -33,6 +33,72 @@ static int cmd_log_rpc_stream_level(const struct shell *sh, size_t argc, char *a
 	return 0;
 }
 
+static int cmd_log_rpc_history_level(const struct shell *sh, size_t argc, char *argv[])
+{
+	int rc = 0;
+	enum log_rpc_level level;
+
+	level = (enum log_rpc_level)shell_strtol(argv[1], 10, &rc);
+
+	if (rc) {
+		shell_error(sh, "Invalid argument: %d", rc);
+		return -EINVAL;
+	}
+
+	rc = log_rpc_set_history_level(level);
+
+	if (rc) {
+		shell_error(sh, "Error: %d", rc);
+		return -ENOEXEC;
+	}
+
+	return 0;
+}
+
+static const struct shell *shell;
+
+static void history_handler(enum log_rpc_level level, const char *msg, size_t msg_len)
+{
+	enum shell_vt100_color color;
+
+	if (!msg) {
+		shell_print(shell, "Done");
+		return;
+	}
+
+	switch (level) {
+	case LOG_RPC_LEVEL_INF:
+		color = SHELL_INFO;
+		break;
+	case LOG_RPC_LEVEL_WRN:
+		color = SHELL_WARNING;
+		break;
+	case LOG_RPC_LEVEL_ERR:
+		color = SHELL_ERROR;
+		break;
+	default:
+		color = SHELL_NORMAL;
+		break;
+	}
+
+	shell_fprintf(shell, color, "%.*s", msg_len, msg);
+}
+
+static int cmd_log_rpc_history_fetch(const struct shell *sh, size_t argc, char *argv[])
+{
+	int rc = 0;
+
+	shell = sh;
+	rc = log_rpc_fetch_history(history_handler);
+
+	if (rc) {
+		shell_error(sh, "Error: %d", rc);
+		return -ENOEXEC;
+	}
+
+	return 0;
+}
+
 static int cmd_log_rpc_crash(const struct shell *sh, size_t argc, char *argv[])
 {
 	int rc;
@@ -60,8 +126,12 @@ static int cmd_log_rpc_crash(const struct shell *sh, size_t argc, char *argv[])
 }
 
 SHELL_STATIC_SUBCMD_SET_CREATE(log_rpc_cmds,
-			       SHELL_CMD_ARG(stream_level, NULL, "Set stream logging level",
+			       SHELL_CMD_ARG(stream_level, NULL, "Set log streaming level",
 					     cmd_log_rpc_stream_level, 2, 0),
+			       SHELL_CMD_ARG(history_level, NULL, "Set log history level",
+					     cmd_log_rpc_history_level, 2, 0),
+			       SHELL_CMD_ARG(history_fetch, NULL, "Fetch log history",
+					     cmd_log_rpc_history_fetch, 1, 0),
 			       SHELL_CMD_ARG(crash, NULL, "Retrieve remote device crash log",
 					     cmd_log_rpc_crash, 1, 0),
 			       SHELL_SUBCMD_SET_END);

samples/nrf_rpc/protocols_serialization/server/snippets/log_rpc/log_rpc.conf

@@ -7,6 +7,7 @@
 CONFIG_LOG=y
 CONFIG_LOG_BACKEND_RPC=y
 CONFIG_LOG_BACKEND_RPC_CRASH_LOG=y
+CONFIG_LOG_BACKEND_RPC_HISTORY=y
 
 # nRF RPC requires slightly bigger stack than default
 CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=1024

subsys/logging/CMakeLists.txt

@@ -8,4 +8,5 @@ if (CONFIG_LOG_FORWARDER_RPC OR CONFIG_LOG_BACKEND_RPC)
     zephyr_library()
     zephyr_library_sources_ifdef(CONFIG_LOG_FORWARDER_RPC log_forwarder_rpc.c)
     zephyr_library_sources_ifdef(CONFIG_LOG_BACKEND_RPC log_backend_rpc.c)
+    zephyr_library_sources_ifdef(CONFIG_LOG_BACKEND_RPC_HISTORY_STORAGE_RAM log_backend_rpc_history_ram.c)
 endif()

subsys/logging/Kconfig

@@ -31,15 +31,38 @@ menuconfig LOG_BACKEND_RPC
 
 if LOG_BACKEND_RPC
 
-config LOG_BACKEND_RPC_BUFFER_SIZE
-	int "nRF RPC logging backend buffer size"
+config LOG_BACKEND_RPC_HISTORY
+	bool "Log history support"
+	help
+	  Enables the feature to continuously store logs in a large ring buffer,
+	  and adds nRF RPC commands for configuring and fetching the log history.
+
+choice LOG_BACKEND_RPC_HISTORY_STORAGE_CHOICE
+	prompt "Log history storage type"
+	depends on LOG_BACKEND_RPC_HISTORY
+	default LOG_BACKEND_RPC_HISTORY_STORAGE_RAM
+
+config LOG_BACKEND_RPC_HISTORY_STORAGE_RAM
+	bool "RAM buffer"
+
+endchoice
+
+config LOG_BACKEND_RPC_HISTORY_SIZE
+	int "Log history size"
+	depends on LOG_BACKEND_RPC_HISTORY_STORAGE_RAM
+	default 16384
+	help
+	  Size of the ring buffer used to store the log history, in bytes.
+
+config LOG_BACKEND_RPC_OUTPUT_BUFFER_SIZE
+	int "Output buffer size"
 	default 256
 	help
 	  Defines the maximum log line length that can be sent to the log forwarder
 	  over nRF RPC without fragmentation.
 
 config LOG_BACKEND_RPC_CRASH_LOG
-	bool "nRF RPC crash log"
+	bool "Crash log support"
 	select RETENTION
 	select RETENTION_MUTEX_FORCE_DISABLE
 	select RETAINED_MEM

subsys/logging/log_backend_rpc.c

@@ -11,6 +11,7 @@
  */
 
 #include "log_rpc_group.h"
+#include "log_backend_rpc_history.h"
 
 #include <logging/log_rpc.h>
 #include <nrf_rpc/nrf_rpc_serialize.h>
@@ -42,7 +43,8 @@ static bool panic_mode;
 static uint32_t log_format = LOG_OUTPUT_TEXT;
 static enum log_rpc_level current_level;
 static enum log_rpc_level stream_level = LOG_RPC_LEVEL_NONE;
-static uint8_t log_output_buffer[CONFIG_LOG_BACKEND_RPC_BUFFER_SIZE];
+static enum log_rpc_level history_level = LOG_RPC_LEVEL_NONE;
+static uint8_t log_output_buffer[CONFIG_LOG_BACKEND_RPC_OUTPUT_BUFFER_SIZE];
 
 /*
  * Verify that Zephyr logging level can be used as the nRF RPC logging level without translation.
@@ -281,6 +283,13 @@ static void process(const struct log_backend *const backend, union log_msg_gener
 		current_level = level;
 		log_formatter(&log_output_rpc, &msg->log, flags);
 	}
+
+	max_level = history_level;
+
+	if (IS_ENABLED(CONFIG_LOG_BACKEND_RPC_HISTORY) && max_level != LOG_RPC_LEVEL_NONE &&
+	    level <= max_level) {
+		log_rpc_history_push(msg);
+	}
 }
 
 static void panic(struct log_backend const *const backend)
@@ -294,6 +303,10 @@ static void panic(struct log_backend const *const backend)
 static void init(struct log_backend const *const backend)
 {
 	ARG_UNUSED(backend);
+
+	if (IS_ENABLED(CONFIG_LOG_BACKEND_RPC_HISTORY)) {
+		log_rpc_history_init();
+	}
 }
 
 static void dropped(const struct log_backend *const backend, uint32_t cnt)
@@ -350,3 +363,50 @@ static void log_rpc_set_stream_level_handler(const struct nrf_rpc_group *group,
 
 NRF_RPC_CBOR_CMD_DECODER(log_rpc_group, log_rpc_set_stream_level_handler,
 			 LOG_RPC_CMD_SET_STREAM_LEVEL, log_rpc_set_stream_level_handler, NULL);
+
+#ifdef CONFIG_LOG_BACKEND_RPC_HISTORY
+static void log_rpc_set_history_level_handler(const struct nrf_rpc_group *group,
+					      struct nrf_rpc_cbor_ctx *ctx, void *handler_data)
+{
+	enum log_rpc_level level;
+
+	level = (enum log_rpc_level)nrf_rpc_decode_uint(ctx);
+
+	if (!nrf_rpc_decoding_done_and_check(group, ctx)) {
+		nrf_rpc_err(-EBADMSG, NRF_RPC_ERR_SRC_RECV, group, LOG_RPC_CMD_SET_HISTORY_LEVEL,
+			    NRF_RPC_PACKET_TYPE_CMD);
+		return;
+	}
+
+	history_level = level;
+
+	nrf_rpc_rsp_send_void(group);
+}
+
+NRF_RPC_CBOR_CMD_DECODER(log_rpc_group, log_rpc_set_history_level_handler,
+			 LOG_RPC_CMD_SET_HISTORY_LEVEL, log_rpc_set_history_level_handler, NULL);
+
+static void log_rpc_fetch_history_handler(const struct nrf_rpc_group *group,
+					  struct nrf_rpc_cbor_ctx *ctx, void *handler_data)
+{
+	if (!nrf_rpc_decoding_done_and_check(group, ctx)) {
+		nrf_rpc_err(-EBADMSG, NRF_RPC_ERR_SRC_RECV, group, LOG_RPC_CMD_FETCH_HISTORY,
+			    NRF_RPC_PACKET_TYPE_CMD);
+		return;
+	}
+
+	/* TODO: implement log upload:
+	 * const union log_msg_generic *msg;
+	 * while ((msg = log_rpc_history_pop()) != NULL) {
+	 *   format_and_upload(msg);
+	 *   log_rpc_history_pop(msg);
+	 * }
+	 */
+
+	nrf_rpc_rsp_send_void(group);
+}
+
+NRF_RPC_CBOR_CMD_DECODER(log_rpc_group, log_rpc_fetch_history_handler, LOG_RPC_CMD_FETCH_HISTORY,
+			 log_rpc_fetch_history_handler, NULL);
+
+#endif

subsys/logging/log_backend_rpc_history.h

@@ -0,0 +1,19 @@
+/*
+ * Copyright (c) 2024 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
+ */
+
+#ifndef LOG_RPC_HISTORY_H_
+#define LOG_RPC_HISTORY_H_
+
+#include <zephyr/logging/log_msg.h>
+
+void log_rpc_history_init(void);
+
+void log_rpc_history_push(const union log_msg_generic *msg);
+
+const union log_msg_generic *log_rpc_history_pop(void);
+void log_rpc_history_free(const union log_msg_generic *msg);
+
+#endif /* LOG_RPC_HISTORY_H_ */

subsys/logging/log_backend_rpc_history_ram.c

@@ -0,0 +1,58 @@
+/*
+ * Copyright (c) 2024 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
+ */
+
+#include "log_backend_rpc_history.h"
+
+#include <zephyr/sys/mpsc_pbuf.h>
+#include <zephyr/sys/util.h>
+
+#define HISTORY_WLEN (CONFIG_LOG_BACKEND_RPC_HISTORY_SIZE / sizeof(uint32_t))
+
+static uint32_t __aligned(Z_LOG_MSG_ALIGNMENT) log_history_raw[HISTORY_WLEN];
+static struct mpsc_pbuf_buffer log_history_pbuf;
+
+void log_rpc_history_init(void)
+{
+	const struct mpsc_pbuf_buffer_config log_history_config = {
+		.buf = log_history_raw,
+		.size = ARRAY_SIZE(log_history_raw),
+		.get_wlen = log_msg_generic_get_wlen,
+		.flags = MPSC_PBUF_MODE_OVERWRITE,
+	};
+
+	mpsc_pbuf_init(&log_history_pbuf, &log_history_config);
+}
+
+void log_rpc_history_push(const union log_msg_generic *msg)
+{
+	uint32_t wlen;
+	union log_msg_generic *copy;
+	int len;
+
+	wlen = log_msg_generic_get_wlen(&msg->buf);
+	copy = (union log_msg_generic *)mpsc_pbuf_alloc(&log_history_pbuf, wlen, K_NO_WAIT);
+
+	if (!copy) {
+		return;
+	}
+
+	copy->log.hdr = msg->log.hdr;
+	len = cbprintf_package_copy((void *)msg->log.data, msg->log.hdr.desc.package_len,
+				    copy->log.data, msg->log.hdr.desc.package_len, 0, NULL, 0);
+	__ASSERT_NO_MSG(len == msg->log.hdr.desc.package_len);
+
+	mpsc_pbuf_commit(&log_history_pbuf, &copy->buf);
+}
+
+const union log_msg_generic *log_rpc_history_pop(void)
+{
+	return (const union log_msg_generic *)mpsc_pbuf_claim(&log_history_pbuf);
+}
+
+void log_rpc_history_free(const union log_msg_generic *msg)
+{
+	mpsc_pbuf_free(&log_history_pbuf, &msg->buf);
+}