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>

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.

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] _transport_iface	Pointer to the transport interface.
- * @param[in] log_queue_size	Logger processing queue size.
+ * @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,			      \
+#define SHELL_DEFINE(_name, _prompt, _transport_iface,			      \
-		     log_queue_size, _shell_flag)			      \
+		     _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,				      \

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 _name	Shell name.
- *  @param _buf  Output buffer.
+ *  @param _buf		Output buffer.
- *  @param _size Output buffer size.
+ *  @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 */
 

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

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.
+

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.
+

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,

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
+			/* Unexpected case as we just freed one element and
-			 * and there is no other context that puts into the
+			 * there is no other context that puts into the msgq.
-			 * mesq. */
+			 */
 			__ASSERT_NO_MSG(0);
 		}
 		break;

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);

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