diff --git a/include/logging/log_rpc.h b/include/logging/log_rpc.h index c0e1c68169a5..a1d821e31623 100644 --- a/include/logging/log_rpc.h +++ b/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. * diff --git a/samples/nrf_rpc/protocols_serialization/client/src/log_rpc_shell.c b/samples/nrf_rpc/protocols_serialization/client/src/log_rpc_shell.c index 90b536dae24d..a51b89be8c54 100644 --- a/samples/nrf_rpc/protocols_serialization/client/src/log_rpc_shell.c +++ b/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); diff --git a/samples/nrf_rpc/protocols_serialization/server/snippets/log_rpc/log_rpc.conf b/samples/nrf_rpc/protocols_serialization/server/snippets/log_rpc/log_rpc.conf index de18731088ce..cbcb628318ba 100644 --- a/samples/nrf_rpc/protocols_serialization/server/snippets/log_rpc/log_rpc.conf +++ b/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 diff --git a/subsys/logging/CMakeLists.txt b/subsys/logging/CMakeLists.txt index 055a8372abc1..eb806e7825a2 100644 --- a/subsys/logging/CMakeLists.txt +++ b/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() diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index 0a05be455ae9..122068179b36 100644 --- a/subsys/logging/Kconfig +++ b/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 diff --git a/subsys/logging/log_backend_rpc.c b/subsys/logging/log_backend_rpc.c index 23f9cee0e9ba..49c42cdcac5c 100644 --- a/subsys/logging/log_backend_rpc.c +++ b/subsys/logging/log_backend_rpc.c @@ -11,12 +11,14 @@ */ #include "log_rpc_group.h" +#include "log_backend_rpc_history.h" #include #include #include +#include #include #include #include @@ -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 diff --git a/subsys/logging/log_backend_rpc_history.h b/subsys/logging/log_backend_rpc_history.h new file mode 100644 index 000000000000..7dde6e908d47 --- /dev/null +++ b/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 + +void log_rpc_history_init(void); + +void log_rpc_history_push(const union log_msg_generic *msg); + +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_ */ diff --git a/subsys/logging/log_backend_rpc_history_ram.c b/subsys/logging/log_backend_rpc_history_ram.c new file mode 100644 index 000000000000..03aa25e4db86 --- /dev/null +++ b/subsys/logging/log_backend_rpc_history_ram.c @@ -0,0 +1,62 @@ +/* + * Copyright (c) 2024 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: LicenseRef-Nordic-5-Clause + */ + +#include "log_backend_rpc_history.h" + +#include +#include + +#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, ©->buf); +} + +union log_msg_generic *log_rpc_history_pop(void) +{ + return (union log_msg_generic *)mpsc_pbuf_claim(&log_history_pbuf); +} + +void log_rpc_history_free(const union log_msg_generic *msg) +{ + if (!msg) { + return; + } + + mpsc_pbuf_free(&log_history_pbuf, &msg->buf); +} diff --git a/subsys/logging/log_forwarder_rpc.c b/subsys/logging/log_forwarder_rpc.c index 50436b18bba9..1b60c6ae707d 100644 --- a/subsys/logging/log_forwarder_rpc.c +++ b/subsys/logging/log_forwarder_rpc.c @@ -17,11 +17,16 @@ #include +#include #include #include LOG_MODULE_REGISTER(remote); +static K_MUTEX_DEFINE(history_transfer_mtx); +static uint32_t history_transfer_id; +static log_rpc_history_handler_t history_handler; + static void log_rpc_msg_handler(const struct nrf_rpc_group *group, struct nrf_rpc_cbor_ctx *ctx, void *handler_data) { @@ -72,6 +77,94 @@ int log_rpc_set_stream_level(enum log_rpc_level level) return 0; } +int log_rpc_set_history_level(enum log_rpc_level level) +{ + struct nrf_rpc_cbor_ctx ctx; + + NRF_RPC_CBOR_ALLOC(&log_rpc_group, ctx, 1 + sizeof(level)); + nrf_rpc_encode_uint(&ctx, level); + nrf_rpc_cbor_cmd_no_err(&log_rpc_group, LOG_RPC_CMD_SET_HISTORY_LEVEL, &ctx, + nrf_rpc_rsp_decode_void, NULL); + + return 0; +} + +int log_rpc_fetch_history(log_rpc_history_handler_t handler) +{ + struct nrf_rpc_cbor_ctx ctx; + uint32_t transfer_id; + + k_mutex_lock(&history_transfer_mtx, K_FOREVER); + transfer_id = ++history_transfer_id; + history_handler = handler; + k_mutex_unlock(&history_transfer_mtx); + + NRF_RPC_CBOR_ALLOC(&log_rpc_group, ctx, 1 + sizeof(transfer_id)); + nrf_rpc_encode_uint(&ctx, transfer_id); + nrf_rpc_cbor_cmd_no_err(&log_rpc_group, LOG_RPC_CMD_FETCH_HISTORY, &ctx, + nrf_rpc_rsp_decode_void, NULL); + + return 0; +} + +static void log_rpc_put_history_chunk_handler(const struct nrf_rpc_group *group, + struct nrf_rpc_cbor_ctx *ctx, void *handler_data) +{ + uint32_t transfer_id; + enum log_rpc_level level; + const char *message; + size_t message_size; + + k_mutex_lock(&history_transfer_mtx, K_FOREVER); + + transfer_id = nrf_rpc_decode_uint(ctx); + + if (!nrf_rpc_decode_valid(ctx)) { + goto out; + } + + if (transfer_id != history_transfer_id) { + /* Received outdated history chunk. */ + goto out; + } + + if (nrf_rpc_decode_is_null(ctx)) { + /* An empty history chunk indicates the end of history. */ + if (history_handler != NULL) { + log_rpc_history_handler_t handler = history_handler; + + history_handler = NULL; + handler(LOG_RPC_LEVEL_NONE, NULL, 0); + } + + goto out; + } + + while (nrf_rpc_decode_valid(ctx) && !nrf_rpc_decode_is_null(ctx)) { + level = nrf_rpc_decode_uint(ctx); + message = nrf_rpc_decode_buffer_ptr_and_size(ctx, &message_size); + + if (history_handler != NULL && message != NULL) { + history_handler(level, message, message_size); + } + } + +out: + + k_mutex_unlock(&history_transfer_mtx); + + if (!nrf_rpc_decoding_done_and_check(group, ctx)) { + nrf_rpc_err(-EBADMSG, NRF_RPC_ERR_SRC_RECV, group, LOG_RPC_CMD_PUT_HISTORY_CHUNK, + NRF_RPC_PACKET_TYPE_CMD); + return; + } + + nrf_rpc_rsp_send_void(group); +} + +NRF_RPC_CBOR_CMD_DECODER(log_rpc_group, log_rpc_put_history_chunk_handler, + LOG_RPC_CMD_PUT_HISTORY_CHUNK, log_rpc_put_history_chunk_handler, NULL); + int log_rpc_get_crash_log(size_t offset, char *buffer, size_t buffer_length) { struct nrf_rpc_cbor_ctx ctx; diff --git a/subsys/logging/log_rpc_group.h b/subsys/logging/log_rpc_group.h index 0272ffcad011..3f68696b5e54 100644 --- a/subsys/logging/log_rpc_group.h +++ b/subsys/logging/log_rpc_group.h @@ -31,9 +31,15 @@ enum log_rpc_evt_forwarder { LOG_RPC_EVT_MSG = 0, }; +enum log_rpc_cmd_forwarder { + LOG_RPC_CMD_PUT_HISTORY_CHUNK = 0, +}; + enum log_rpc_cmd_backend { LOG_RPC_CMD_SET_STREAM_LEVEL = 0, - LOG_RPC_CMD_GET_CRASH_LOG = 1, + LOG_RPC_CMD_SET_HISTORY_LEVEL = 1, + LOG_RPC_CMD_FETCH_HISTORY = 2, + LOG_RPC_CMD_GET_CRASH_LOG = 3, }; #ifdef __cplusplus