shell: Improve handling of log messages
If burst of log messages was passed to the shell log
backend, it was likely that messages were lost because
shell had no means to control arrivals of log messages.
Added log message enqueueing timeout to the shell instance
to allow blocking logger thread if short-term arrival rate
exceeded shell capabilities.
Added kconfig option for setting log message queue size
and timeout in RTT and UART instances. Added section in
shell documentation which explains interaction between
the logger and shell instance acting as a logger backend.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
diff --git a/doc/subsystems/shell/shell.rst b/doc/subsystems/shell/shell.rst
index be62658..d1e2156 100644
--- a/doc/subsystems/shell/shell.rst
+++ b/doc/subsystems/shell/shell.rst
@@ -435,4 +435,21 @@
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 d0c0dd5..7776991 100644
--- a/include/shell/shell.h
+++ b/include/shell/shell.h
@@ -452,18 +452,23 @@
*
* @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 @@
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 5b35090..6be97d9 100644
--- a/include/shell/shell_log_backend.h
+++ b/include/shell/shell_log_backend.h
@@ -37,6 +37,7 @@
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 @@
/** @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 @@
* @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 @@
.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 de8e3d2..2702b62 100644
--- a/subsys/shell/Kconfig.backends
+++ b/subsys/shell/Kconfig.backends
@@ -65,6 +65,13 @@
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 @@
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 0000000..95adf7b
--- /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 0000000..69e09cb
--- /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 d6d01b4..1424d95 100644
--- a/subsys/shell/shell_dummy.c
+++ b/subsys/shell/shell_dummy.c
@@ -8,7 +8,7 @@
#include <init.h>
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 8423852..69ca030 100644
--- a/subsys/shell/shell_log_backend.c
+++ b/subsys/shell/shell_log_backend.c
@@ -49,11 +49,13 @@
{
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 @@
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 7be2eb3..1a37175 100644
--- a/subsys/shell/shell_rtt.c
+++ b/subsys/shell/shell_rtt.c
@@ -10,7 +10,9 @@
#include <logging/log.h>
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 4e88402..15e5f80 100644
--- a/subsys/shell/shell_uart.c
+++ b/subsys/shell/shell_uart.c
@@ -21,7 +21,9 @@
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
