shell: Add handling of CONFIG_LOG_INPLACE_PROCESS option

Extended shell to be able to process logs in place
(in the context of a log call). In order to achieve that,
shell was extended to  support for TX blocking operations. If
CONFIG_LOG_INPLACE_PROCESS is enabled then shell instance
attempts to be initialized in blocking TX mode. If fails to
do so, shell log backend is disabled. If successfully enabled
logs are processed and printed in the context of the call.

Due to that change, user may expirience interleaved output as
shell has no means to multiplex shell output with logger output.
In extreme, huge amount of log messages may prevent shell thread
execution and shell may become unresponsive.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>

include/shell/shell.h

@@ -292,16 +292,19 @@ struct shell_transport_api {
 	int (*uninit)(const struct shell_transport *transport);
 
 	/**
-	 * @brief Function for reconfiguring the transport to work in blocking
+	 * @brief Function for enabling transport in given TX mode.
-	 * mode.
+	 *
+	 * Function can be used to reconfigure TX to work in blocking mode.
 	 *
 	 * @param transport   Pointer to the transfer instance.
-	 * @param blocking   If true, the transport is enabled in blocking mode.
+	 * @param blocking_tx If true, the transport TX is enabled in blocking
+	 *		      mode.
 	 *
 	 * @return NRF_SUCCESS on successful enabling, error otherwise (also if
 	 * not supported).
 	 */
-	int (*enable)(const struct shell_transport *transport, bool blocking);
+	int (*enable)(const struct shell_transport *transport,
+		      bool blocking_tx);
 
 	/**
 	 * @brief Function for writing data to the transport interface.

include/shell/shell_uart.h

@@ -26,7 +26,7 @@ struct shell_uart_ctrl_blk {
 	shell_transport_handler_t handler;
 	void *context;
 	atomic_t tx_busy;
-	bool blocking;
+	bool blocking_tx;
 #ifdef CONFIG_MCUMGR_SMP_SHELL
 	struct smp_shell_data smp;
 #endif /* CONFIG_MCUMGR_SMP_SHELL */

subsys/shell/shell.c

@@ -1035,14 +1035,16 @@ static void transport_evt_handler(enum shell_transport_evt evt_type, void *ctx)
 
 static void shell_log_process(const struct shell *shell)
 {
-	bool processed;
+	bool processed = false;
 	int signaled = 0;
 	int result;
 
 	do {
+		if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
 			shell_cmd_line_erase(shell);
 
 			processed = shell_log_backend_process(shell->log_backend);
+		}
 
 		struct k_poll_signal *signal =
 			&shell->ctx->signals[SHELL_SIGNAL_RXRDY];
@@ -1167,7 +1169,7 @@ void shell_thread(void *shell_handle, void *arg_log_backend,
 				  &shell->ctx->signals[i]);
 	}
 
-	err = shell_start(shell);
+	err = shell->iface->api->enable(shell->iface, false);
 	if (err != 0) {
 		return;
 	}
@@ -1177,6 +1179,12 @@ void shell_thread(void *shell_handle, void *arg_log_backend,
 					 log_level);
 	}
 
+	/* Enable shell and print prompt. */
+	err = shell_start(shell);
+	if (err != 0) {
+		return;
+	}
+
 	while (true) {
 		/* waiting for all signals except SHELL_SIGNAL_TXDONE */
 		err = k_poll(shell->ctx->events, SHELL_SIGNAL_TXDONE,
@@ -1250,17 +1258,10 @@ int shell_start(const struct shell *shell)
 	__ASSERT_NO_MSG(shell);
 	__ASSERT_NO_MSG(shell->ctx && shell->iface && shell->prompt);
 
-	int err;
-
 	if (shell->ctx->state != SHELL_STATE_INITIALIZED) {
 		return -ENOTSUP;
 	}
 
-	err = shell->iface->api->enable(shell->iface, false);
-	if (err != 0) {
-		return err;
-	}
-
 	if (IS_ENABLED(CONFIG_SHELL_VT100_COLORS)) {
 		shell_vt100_color_set(shell, SHELL_NORMAL);
 	}

subsys/shell/shell_log_backend.c

@@ -18,10 +18,23 @@ int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx)
 void shell_log_backend_enable(const struct shell_log_backend *backend,
 			      void *ctx, u32_t init_log_level)
 {
+	int err = 0;
+
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
+		const struct shell *shell;
+
+		shell = (const struct shell *)ctx;
+
+		/* Reenable transport in blocking mode */
+		err = shell->iface->api->enable(shell->iface, true);
+	}
+
+	if (err == 0) {
 		log_backend_enable(backend->backend, ctx, init_log_level);
 		log_output_ctx_set(backend->log_output, ctx);
 	backend->control_block->dropped_cnt = 0;
 		backend->control_block->state = SHELL_LOG_BACKEND_ENABLED;
+	}
 }
 
 static struct log_msg *msg_from_fifo(const struct shell_log_backend *backend)
@@ -179,9 +192,10 @@ static void put(const struct log_backend *const backend, struct log_msg *msg)
 		}
 
 		break;
-
 	case SHELL_LOG_BACKEND_PANIC:
+		shell_cmd_line_erase(shell);
 		msg_process(shell->log_backend->log_output, msg, colors);
+
 		break;
 
 	case SHELL_LOG_BACKEND_DISABLED:
@@ -193,11 +207,67 @@ static void put(const struct log_backend *const backend, struct log_msg *msg)
 	}
 }
 
+static void put_sync_string(const struct log_backend *const backend,
+			    struct log_msg_ids src_level, u32_t timestamp,
+			    const char *fmt, va_list ap)
+{
+	const struct shell *shell = (const struct shell *)backend->cb->ctx;
+	u32_t key;
+	u32_t flags = LOG_OUTPUT_FLAG_LEVEL |
+		      LOG_OUTPUT_FLAG_TIMESTAMP |
+		      LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
+
+	if (IS_ENABLED(CONFIG_SHELL_VT100_COLORS)) {
+		flags |= LOG_OUTPUT_FLAG_COLORS;
+	}
+
+	key = irq_lock();
+	shell_cmd_line_erase(shell);
+	log_output_string(shell->log_backend->log_output, src_level, timestamp,
+			  fmt, ap, flags);
+	shell_print_prompt_and_cmd(shell);
+	irq_unlock(key);
+}
+
+static void put_sync_hexdump(const struct log_backend *const backend,
+			 struct log_msg_ids src_level, u32_t timestamp,
+			 const char *metadata, const u8_t *data, u32_t length)
+{
+	const struct shell *shell = (const struct shell *)backend->cb->ctx;
+	struct k_poll_signal *signal;
+	u32_t key;
+	u32_t flags = LOG_OUTPUT_FLAG_LEVEL |
+		      LOG_OUTPUT_FLAG_TIMESTAMP |
+		      LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
+
+	if (IS_ENABLED(CONFIG_SHELL_VT100_COLORS)) {
+		flags |= LOG_OUTPUT_FLAG_COLORS;
+	}
+
+	key = irq_lock();
+	shell_cmd_line_erase(shell);
+	log_output_hexdump(shell->log_backend->log_output, src_level, timestamp,
+			   metadata, data, length, flags);
+	irq_unlock(key);
+
+	/* Even though log message is handled notify shell thread which
+	 * will print command buffer after the log message.
+	 */
+	if (IS_ENABLED(CONFIG_MULTITHREADING)) {
+		signal = &shell->ctx->signals[SHELL_SIGNAL_LOG_MSG];
+		k_poll_signal_raise(signal, 0);
+	}
+}
+
 static void panic(const struct log_backend *const backend)
 {
 	const struct shell *shell = (const struct shell *)backend->cb->ctx;
 	int err;
 
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
+		return;
+	}
+
 	err = shell->iface->api->enable(shell->iface, true);
 
 	if (err == 0) {
@@ -230,7 +300,11 @@ static void dropped(const struct log_backend *const backend, u32_t cnt)
 }
 
 const struct log_backend_api log_backend_shell_api = {
-	.put = put,
+	.put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put,
+	.put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ?
+			put_sync_string : NULL,
+	.put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ?
+			put_sync_hexdump : NULL,
+	.dropped = dropped,
 	.panic = panic,
-	.dropped = dropped
 };

subsys/shell/shell_uart.c

@@ -180,18 +180,14 @@ static int uninit(const struct shell_transport *transport)
 	return 0;
 }
 
-static int enable(const struct shell_transport *transport, bool blocking)
+static int enable(const struct shell_transport *transport, bool blocking_tx)
 {
 	const struct shell_uart *sh_uart = (struct shell_uart *)transport->ctx;
 
-	sh_uart->ctrl_blk->blocking = blocking;
+	sh_uart->ctrl_blk->blocking_tx = blocking_tx;
 
-	if (blocking) {
+	if (blocking_tx) {
-		if (!IS_ENABLED(CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN)) {
-			k_timer_stop(sh_uart->timer);
-		}
 #ifdef CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN
-		uart_irq_rx_disable(sh_uart->ctrl_blk->dev);
 		uart_irq_tx_disable(sh_uart->ctrl_blk->dev);
 #endif
 	}
@@ -218,7 +214,7 @@ static int write(const struct shell_transport *transport,
 	const u8_t *data8 = (const u8_t *)data;
 
 	if (IS_ENABLED(CONFIG_SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN) &&
-		!sh_uart->ctrl_blk->blocking) {
+		!sh_uart->ctrl_blk->blocking_tx) {
 		irq_write(sh_uart, data, length, cnt);
 	} else {
 		for (size_t i = 0; i < length; i++) {