diff --git a/doc/subsystems/shell/shell.rst b/doc/subsystems/shell/shell.rst index be626583cc5..d1e21565f6a 100644 --- a/doc/subsystems/shell/shell.rst +++ b/doc/subsystems/shell/shell.rst @@ -435,4 +435,21 @@ the shell will only print the subcommands registered for this command: params ping +Shell as the logger backend +*************************** +Shell instance can act as the :ref:`logger` backend. Shell ensures that log +messages are correctly multiplexed with shell output. Log messages from logger +thread are enqueued and processed in the shell thread. Logger thread will block +for configurable amount of time if queue is full, blocking logger thread context +for that time. Oldest log message is removed from the queue after timeout and +new message is enqueued. Use the ``shell stats show`` command to retrieve +number of log messages dropped by the shell instance. Log queue size and timeout +are :c:macro:`SHELL_DEFINE` arguments. + +.. warning:: + Enqueuing timeout must be set carefully when multiple backends are used + in the system. The shell instance could have a slow transport or could + block, for example, by a UART with hardware flow control. If timeout is + set too high, the logger thread could be blocked and impact other logger + backends. diff --git a/include/shell/shell.h b/include/shell/shell.h index d0c0dd5baf4..77769910545 100644 --- a/include/shell/shell.h +++ b/include/shell/shell.h @@ -452,18 +452,23 @@ extern void shell_print_stream(const void *user_ctx, const char *data, * * @param[in] _name Instance name. * @param[in] _prompt Shell prompt string. - * @param[in] transport_iface Pointer to the transport interface. - * @param[in] log_queue_size Logger processing queue size. + * @param[in] _transport_iface Pointer to the transport interface. + * @param[in] _log_queue_size Logger processing queue size. + * @param[in] _log_timeout Logger thread timeout in milliseconds on full + * log queue. If queue is full logger thread is + * blocked for given amount of time before log + * message is dropped. * @param[in] _shell_flag Shell output newline sequence. */ -#define SHELL_DEFINE(_name, _prompt, transport_iface, \ - log_queue_size, _shell_flag) \ +#define SHELL_DEFINE(_name, _prompt, _transport_iface, \ + _log_queue_size, _log_timeout, _shell_flag) \ static const struct shell _name; \ static struct shell_ctx UTIL_CAT(_name, _ctx); \ static char _name##prompt[CONFIG_SHELL_PROMPT_LENGTH + 1] = _prompt; \ static u8_t _name##_out_buffer[CONFIG_SHELL_PRINTF_BUFF_SIZE]; \ SHELL_LOG_BACKEND_DEFINE(_name, _name##_out_buffer, \ - CONFIG_SHELL_PRINTF_BUFF_SIZE); \ + CONFIG_SHELL_PRINTF_BUFF_SIZE, \ + _log_queue_size, _log_timeout); \ SHELL_HISTORY_DEFINE(_name, 128, 8);/*todo*/ \ SHELL_FPRINTF_DEFINE(_name##_fprintf, &_name, _name##_out_buffer, \ CONFIG_SHELL_PRINTF_BUFF_SIZE, \ @@ -474,7 +479,7 @@ extern void shell_print_stream(const void *user_ctx, const char *data, static struct k_thread _name##_thread; \ static const struct shell _name = { \ .prompt = _name##prompt, \ - .iface = transport_iface, \ + .iface = _transport_iface, \ .ctx = &UTIL_CAT(_name, _ctx), \ .history = SHELL_HISTORY_PTR(_name), \ .shell_flag = _shell_flag, \ diff --git a/include/shell/shell_log_backend.h b/include/shell/shell_log_backend.h index 5b35090630c..6be97d96a19 100644 --- a/include/shell/shell_log_backend.h +++ b/include/shell/shell_log_backend.h @@ -37,6 +37,7 @@ struct shell_log_backend { struct k_msgq *msgq; const struct log_output *log_output; struct shell_log_backend_control_block *control_block; + u32_t timeout; }; /** @brief Prototype of function outputing processed data. */ @@ -45,9 +46,12 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); /** @def SHELL_LOG_BACKEND_DEFINE * @brief Macro for creating instance of shell log backend. * - * @param _name Shell name. - * @param _buf Output buffer. - * @param _size Output buffer size. + * @param _name Shell name. + * @param _buf Output buffer. + * @param _size Output buffer size. + * @param _queue_size Log message queue size. + * @param _timeout Timeout in milliseconds for pending on queue full. + * Message is dropped on timeout. */ /** @def SHELL_LOG_BACKEND_PTR * @brief Macro for retrieving pointer to the instance of shell log backend. @@ -55,10 +59,10 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); * @param _name Shell name. */ #if CONFIG_LOG -#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size) \ +#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) \ LOG_BACKEND_DEFINE(_name##_backend, log_backend_shell_api, false); \ K_MSGQ_DEFINE(_name##_msgq, sizeof(void *), \ - CONFIG_SHELL_MAX_LOG_MSG_BUFFERED, sizeof(void *)); \ + _queue_size, sizeof(void *)); \ LOG_OUTPUT_DEFINE(_name##_log_output, shell_log_backend_output_func, \ _buf, _size); \ static struct shell_log_backend_control_block _name##_control_block; \ @@ -66,12 +70,13 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx); .backend = &_name##_backend, \ .msgq = &_name##_msgq, \ .log_output = &_name##_log_output, \ - .control_block = &_name##_control_block \ + .control_block = &_name##_control_block, \ + .timeout = _timeout \ } #define SHELL_LOG_BACKEND_PTR(_name) (&_name##_log_backend) #else /* CONFIG_LOG */ -#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size) /* empty */ +#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) #define SHELL_LOG_BACKEND_PTR(_name) NULL #endif /* CONFIG_LOG */ diff --git a/subsys/shell/Kconfig.backends b/subsys/shell/Kconfig.backends index de8e3d2ba87..2702b620d5b 100644 --- a/subsys/shell/Kconfig.backends +++ b/subsys/shell/Kconfig.backends @@ -65,6 +65,13 @@ config SHELL_BACKEND_SERIAL_RX_POLL_PERIOD help Determines how often UART is polled for RX byte. +module = SHELL_BACKEND_SERIAL +default-timeout = 100 +source "subsys/shell/Kconfig.template.shell_log_queue_timeout" + +default-size = 10 +source "subsys/shell/Kconfig.template.shell_log_queue_size" + choice prompt "Initial log level limit" default SHELL_BACKEND_SERIAL_LOG_LEVEL_DEFAULT @@ -115,6 +122,13 @@ config SHELL_RTT_RX_POLL_PERIOD help Determines how often RTT is polled for RX byte. +module = SHELL_BACKEND_RTT +default-timeout = 100 +source "subsys/shell/Kconfig.template.shell_log_queue_timeout" + +default-size = 10 +source "subsys/shell/Kconfig.template.shell_log_queue_size" + choice prompt "Initial log level limit" default SHELL_RTT_INIT_LOG_LEVEL_DEFAULT diff --git a/subsys/shell/Kconfig.template.shell_log_queue_size b/subsys/shell/Kconfig.template.shell_log_queue_size new file mode 100644 index 00000000000..95adf7bd452 --- /dev/null +++ b/subsys/shell/Kconfig.template.shell_log_queue_size @@ -0,0 +1,10 @@ +config $(module)_LOG_MESSAGE_QUEUE_SIZE + int "Log message queue size" + default $(default-size) + help + Amount of messages that can enqueued in order to be processed by shell + thread. Too small queue may lead to logger thread being blocked + (see $(module)_LOG_MESSAGE_QUEUE_TIMEOUT). Too big queue on relatively + slow shell transport may lead to situation where logs are dropped + because all log messages are enqueued. + diff --git a/subsys/shell/Kconfig.template.shell_log_queue_timeout b/subsys/shell/Kconfig.template.shell_log_queue_timeout new file mode 100644 index 00000000000..69e09cb459a --- /dev/null +++ b/subsys/shell/Kconfig.template.shell_log_queue_timeout @@ -0,0 +1,10 @@ +config $(module)_LOG_MESSAGE_QUEUE_TIMEOUT + int "Log message drop timeout (in milliseconds)" + default $(default-timeout) + range -1 10000 + help + If queue with pending log messages is full, oldest log message is + dropped if queue is still full after requested time (-1 is forever). + Logger thread is blocked for that period, thus long timeout impacts + other logger backends and must be used with care. + diff --git a/subsys/shell/shell_dummy.c b/subsys/shell/shell_dummy.c index d6d01b4eeed..1424d95dc83 100644 --- a/subsys/shell/shell_dummy.c +++ b/subsys/shell/shell_dummy.c @@ -8,7 +8,7 @@ #include SHELL_DUMMY_DEFINE(shell_transport_dummy); -SHELL_DEFINE(shell_dummy, "~$ ", &shell_transport_dummy, 10, +SHELL_DEFINE(shell_dummy, "~$ ", &shell_transport_dummy, 1, 0, SHELL_FLAG_OLF_CRLF); static int init(const struct shell_transport *transport, diff --git a/subsys/shell/shell_log_backend.c b/subsys/shell/shell_log_backend.c index 8423852c667..69ca0300572 100644 --- a/subsys/shell/shell_log_backend.c +++ b/subsys/shell/shell_log_backend.c @@ -49,11 +49,13 @@ static void msg_to_fifo(const struct shell *shell, { int err; - err = k_msgq_put(shell->log_backend->msgq, &msg, K_NO_WAIT); + err = k_msgq_put(shell->log_backend->msgq, &msg, + shell->log_backend->timeout); switch (err) { case 0: break; + case -EAGAIN: case -ENOMSG: { struct log_msg *old_msg; @@ -71,9 +73,9 @@ static void msg_to_fifo(const struct shell *shell, err = k_msgq_put(shell->log_backend->msgq, &msg, K_NO_WAIT); if (err) { - /* Rather unusual sitaution as we just freed one element - * and there is no other context that puts into the - * mesq. */ + /* Unexpected case as we just freed one element and + * there is no other context that puts into the msgq. + */ __ASSERT_NO_MSG(0); } break; diff --git a/subsys/shell/shell_rtt.c b/subsys/shell/shell_rtt.c index 7be2eb3bc3f..1a371757481 100644 --- a/subsys/shell/shell_rtt.c +++ b/subsys/shell/shell_rtt.c @@ -10,7 +10,9 @@ #include SHELL_RTT_DEFINE(shell_transport_rtt); -SHELL_DEFINE(shell_rtt, "rtt:~$ ", &shell_transport_rtt, 10, +SHELL_DEFINE(shell_rtt, "rtt:~$ ", &shell_transport_rtt, + CONFIG_SHELL_BACKEND_RTT_LOG_MESSAGE_QUEUE_SIZE, + CONFIG_SHELL_BACKEND_RTT_LOG_MESSAGE_QUEUE_TIMEOUT, SHELL_FLAG_OLF_CRLF); LOG_MODULE_REGISTER(shell_rtt, CONFIG_SHELL_RTT_LOG_LEVEL); diff --git a/subsys/shell/shell_uart.c b/subsys/shell/shell_uart.c index 4e8840267ed..15e5f806966 100644 --- a/subsys/shell/shell_uart.c +++ b/subsys/shell/shell_uart.c @@ -21,7 +21,9 @@ LOG_MODULE_REGISTER(shell_uart); SHELL_UART_DEFINE(shell_transport_uart, CONFIG_SHELL_BACKEND_SERIAL_TX_RING_BUFFER_SIZE, CONFIG_SHELL_BACKEND_SERIAL_RX_RING_BUFFER_SIZE); -SHELL_DEFINE(shell_uart, "uart:~$ ", &shell_transport_uart, 10, +SHELL_DEFINE(shell_uart, "uart:~$ ", &shell_transport_uart, + CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_SIZE, + CONFIG_SHELL_BACKEND_SERIAL_LOG_MESSAGE_QUEUE_TIMEOUT, SHELL_FLAG_OLF_CRLF); #ifdef CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN