logging: rpc: log 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 log history, and setting
the maximum level of saved messages.

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

Author: Damian-Nordic

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,42 @@ 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. The @c handler callback function is invoked for each
+ * received log message. Additionally, it is invoked with @c msg argument set to
+ * NULL after all log messages have been received.
+ *
+ * @note If the function is called while the previous log history transfer is
+ *       still is in progress, the process is restarted from the current oldest
+ *       log message saved in the log history on the remote device.
+ *
+ * @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\n", 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

@@ -38,8 +38,42 @@ config LOG_BACKEND_RPC_OUTPUT_BUFFER_SIZE
 	  Defines the size of stack buffer that is used by the RPC logging backend
 	  while formatting a log message.
 
+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.
+
+if LOG_BACKEND_RPC_HISTORY
+
+choice LOG_BACKEND_RPC_HISTORY_STORAGE_CHOICE
+	prompt "Log history storage type"
+	default LOG_BACKEND_RPC_HISTORY_STORAGE_RAM
+
+config LOG_BACKEND_RPC_HISTORY_STORAGE_RAM
+	bool "RAM buffer"
+
+endchoice # LOG_BACKEND_RPC_HISTORY_STORAGE_CHOICE
+
+config LOG_BACKEND_RPC_HISTORY_UPLOAD_THREAD_STACK_SIZE
+	int "Log history upload thread stack size"
+	default 1024
+
+config LOG_BACKEND_RPC_HISTORY_UPLOAD_CHUNK_SIZE
+	int "Log history upload chunk size"
+	default 1024
+
+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.
+
+endif # LOG_BACKEND_RPC_HISTORY
+
 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,12 +11,14 @@
  */
 
 #include "log_rpc_group.h"
+#include "log_backend_rpc_history.h"
 
 #include <logging/log_rpc.h>
 #include <nrf_rpc/nrf_rpc_serialize.h>
 
 #include <nrf_rpc_cbor.h>
 
+#include <zephyr/kernel.h>
 #include <zephyr/logging/log.h>
 #include <zephyr/logging/log_backend.h>
 #include <zephyr/logging/log_backend_std.h>
@@ -45,6 +47,18 @@ static bool panic_mode;
 static uint32_t log_format = LOG_OUTPUT_TEXT;
 static enum log_rpc_level stream_level = LOG_RPC_LEVEL_NONE;
 
+#ifdef CONFIG_LOG_BACKEND_RPC_HISTORY
+static enum log_rpc_level history_level = LOG_RPC_LEVEL_NONE;
+static void history_transfer_task(struct k_work *work);
+static K_MUTEX_DEFINE(history_transfer_mtx);
+static uint32_t history_transfer_id;
+static union log_msg_generic *history_cur_msg;
+static K_WORK_DEFINE(history_transfer_work, history_transfer_task);
+static K_THREAD_STACK_DEFINE(history_transfer_workq_stack,
+			     CONFIG_LOG_BACKEND_RPC_HISTORY_UPLOAD_THREAD_STACK_SIZE);
+static struct k_work_q history_transfer_workq;
+#endif
+
 /*
  * Verify that Zephyr logging level can be used as the nRF RPC logging level without translation.
  */
@@ -341,6 +355,14 @@ static void process(const struct log_backend *const backend, union log_msg_gener
 		 */
 		stream_message(msg);
 	}
+
+#ifdef CONFIG_LOG_BACKEND_RPC_HISTORY
+	max_level = history_level;
+
+	if (max_level != LOG_RPC_LEVEL_NONE && level <= max_level) {
+		log_rpc_history_push(msg_generic);
+	}
+#endif
 }
 
 static void panic(struct log_backend const *const backend)
@@ -354,6 +376,14 @@ static void panic(struct log_backend const *const backend)
 static void init(struct log_backend const *const backend)
 {
 	ARG_UNUSED(backend);
+
+#ifdef CONFIG_LOG_BACKEND_RPC_HISTORY
+	log_rpc_history_init();
+	k_work_queue_init(&history_transfer_workq);
+	k_work_queue_start(&history_transfer_workq, history_transfer_workq_stack,
+			   K_THREAD_STACK_SIZEOF(history_transfer_workq_stack),
+			   K_LOWEST_APPLICATION_THREAD_PRIO, NULL);
+#endif
 }
 
 static void dropped(const struct log_backend *const backend, uint32_t cnt)
@@ -410,3 +440,114 @@ 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 history_transfer_task(struct k_work *work)
+{
+	const uint32_t flags = common_output_flags | LOG_OUTPUT_FLAG_CRLF_NONE;
+
+	struct nrf_rpc_cbor_ctx ctx;
+	bool any_msg_consumed = false;
+	struct log_msg *msg;
+	size_t length;
+	size_t max_length;
+
+	NRF_RPC_CBOR_ALLOC(&log_rpc_group, ctx, CONFIG_LOG_BACKEND_RPC_HISTORY_UPLOAD_CHUNK_SIZE);
+
+	k_mutex_lock(&history_transfer_mtx, K_FOREVER);
+	nrf_rpc_encode_uint(&ctx, history_transfer_id);
+
+	while (true) {
+		if (!history_cur_msg) {
+			history_cur_msg = log_rpc_history_pop();
+		}
+
+		if (!history_cur_msg) {
+			break;
+		}
+
+		msg = &history_cur_msg->log;
+		length = 6 + format_message_to_buf(msg, flags, NULL, 0);
+		max_length = ctx.zs[0].payload_end - ctx.zs[0].payload_mut;
+
+		/* Check if there is enough buffer space to fit in the current message. */
+		if (length > max_length) {
+			break;
+		}
+
+		nrf_rpc_encode_uint(&ctx, log_msg_get_level(msg));
+
+		if (zcbor_bstr_start_encode(ctx.zs)) {
+			max_length = ctx.zs[0].payload_end - ctx.zs[0].payload_mut;
+			length = format_message_to_buf(msg, flags, ctx.zs[0].payload_mut,
+						       max_length);
+			ctx.zs[0].payload_mut += MIN(length, max_length);
+			zcbor_bstr_end_encode(ctx.zs, NULL);
+		}
+
+		log_rpc_history_free(history_cur_msg);
+		history_cur_msg = NULL;
+		any_msg_consumed = true;
+	}
+
+	/* Determine if the work should be resubmitted to continue the transfer. */
+	if (any_msg_consumed) {
+		k_work_submit_to_queue(&history_transfer_workq, work);
+	} else {
+		log_rpc_history_free(history_cur_msg);
+		history_cur_msg = NULL;
+	}
+
+	k_mutex_unlock(&history_transfer_mtx);
+
+	nrf_rpc_cbor_cmd_no_err(&log_rpc_group, LOG_RPC_CMD_PUT_HISTORY_CHUNK, &ctx,
+				nrf_rpc_rsp_decode_void, NULL);
+}
+
+static void log_rpc_fetch_history_handler(const struct nrf_rpc_group *group,
+					  struct nrf_rpc_cbor_ctx *ctx, void *handler_data)
+{
+	uint32_t transfer_id;
+
+	transfer_id = 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_FETCH_HISTORY,
+			    NRF_RPC_PACKET_TYPE_CMD);
+		return;
+	}
+
+	k_mutex_lock(&history_transfer_mtx, K_FOREVER);
+	history_transfer_id = transfer_id;
+	k_work_submit_to_queue(&history_transfer_workq, &history_transfer_work);
+	k_mutex_unlock(&history_transfer_mtx);
+
+	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