shell: Extend shell as a log backend

Initial logger backend support added to shell.

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

include/shell/shell.h

@@ -11,7 +11,7 @@
 #include <shell/shell_types.h>
 #include <shell/shell_history.h>
 #include <shell/shell_fprintf.h>
-#include <logging/log_backend.h>
+#include <shell/shell_log_backend.h>
 #include <logging/log_instance.h>
 #include <logging/log.h>
 #include <misc/util.h>
@@ -266,6 +266,19 @@ struct shell_transport {
 	void *ctx;
 };
 
+/** @brief Shell statistics structure. */
+struct shell_stats {
+	u32_t log_lost_cnt; /*!< Lost log counter.*/
+};
+
+#if CONFIG_SHELL_STATS
+#define SHELL_STATS_DEFINE(_name) static struct shell_stats _name##_stats
+#define SHELL_STATS_PTR(_name) (&(_name##_stats))
+#else
+#define SHELL_STATS_DEFINE(_name)
+#define SHELL_STATS_PTR(_name) NULL
+#endif /* CONFIG_SHELL_STATS */
+
 /*
  * @internal @brief Flags for internal shell usage.
  */
@@ -292,6 +305,7 @@ union shell_internal {
 enum shell_signal {
 	SHELL_SIGNAL_RXRDY,
 	SHELL_SIGNAL_TXDONE,
+	SHELL_SIGNAL_LOG_MSG,
 	SHELL_SIGNAL_KILL,
 	SHELL_SIGNALS
 };
@@ -344,6 +358,10 @@ struct shell {
 
 	const struct shell_fprintf *fprintf_ctx;
 
+	struct shell_stats *stats;
+
+	const struct shell_log_backend *log_backend;
+
 	LOG_INSTANCE_PTR_DECLARE(log);
 
 	/*!< New line character, only allowed values: \\n and \\r.*/
@@ -368,11 +386,14 @@ struct shell {
 	static const struct shell _name;				     \
 	static struct shell_ctx UTIL_CAT(_name, _ctx);			     \
 	static u8_t _name##_out_buffer[CONFIG_SHELL_PRINTF_BUFF_SIZE];	     \
+	SHELL_LOG_BACKEND_DEFINE(_name, _name##_out_buffer,		     \
+					 CONFIG_SHELL_PRINTF_BUFF_SIZE);     \
 	SHELL_HISTORY_DEFINE(_name, 128, 8);/*todo*/			     \
 	SHELL_FPRINTF_DEFINE(_name## _fprintf, &_name, _name##_out_buffer,   \
 			     CONFIG_SHELL_PRINTF_BUFF_SIZE,		     \
 			     true, shell_print_stream);			     \
 	LOG_INSTANCE_REGISTER(shell, _name, CONFIG_SHELL_LOG_LEVEL);	      \
+	SHELL_STATS_DEFINE(_name);					     \
 	static K_THREAD_STACK_DEFINE(_name##_stack, CONFIG_SHELL_STACK_SIZE);\
 	static struct k_thread _name##_thread;				     \
 	static const struct shell _name = {				     \
@@ -381,6 +402,8 @@ struct shell {
 		.ctx = &UTIL_CAT(_name, _ctx),				     \
 		.history = SHELL_HISTORY_PTR(_name),			     \
 		.fprintf_ctx = &_name##_fprintf,			     \
+		.stats = SHELL_STATS_PTR(_name),			     \
+		.log_backend = SHELL_LOG_BACKEND_PTR(_name),		     \
 		LOG_INSTANCE_PTR_INIT(log, shell, _name)		     \
 		.newline_char = newline_ch,				     \
 		.thread = &_name##_thread,				     \

include/shell/shell_log_backend.h

@@ -0,0 +1,104 @@
+/*
+ * Copyright (c) 2018 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef SHELL_LOG_BACKEND_H__
+#define SHELL_LOG_BACKEND_H__
+
+#include <zephyr.h>
+#include <logging/log_backend.h>
+#include <logging/log_output.h>
+#include <atomic.h>
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+extern const struct log_backend_api log_backend_shell_api;
+
+/** @brief Shell log backend states. */
+enum shell_log_backend_state {
+	SHELL_LOG_BACKEND_UNINIT,
+	SHELL_LOG_BACKEND_ENABLED,
+	SHELL_LOG_BACKEND_DISABLED,
+	SHELL_LOG_BACKEND_PANIC,
+};
+
+/** @brief Shell log backend control block (RW data). */
+struct shell_log_backend_control_block {
+	atomic_t cnt;
+	enum shell_log_backend_state state;
+};
+
+/** @brief Shell log backend instance structure (RO data). */
+struct shell_log_backend {
+	const struct log_backend *backend;
+	struct k_fifo *fifo;
+	const struct log_output *log_output;
+	struct shell_log_backend_control_block *control_block;
+};
+
+/** @brief Prototype of function outputing processed data. */
+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.
+ */
+/** @def SHELL_LOG_BACKEND_PTR
+ *  @brief Macro for retrieving pointer to the instance of shell log backend.
+ *
+ *  @param _name Shell name.
+ */
+#if CONFIG_LOG
+#define SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size)			     \
+	LOG_BACKEND_DEFINE(_name##_backend, log_backend_shell_api);	     \
+	K_FIFO_DEFINE(_name##_fifo);					     \
+	LOG_OUTPUT_DEFINE(_name##_log_output, shell_log_backend_output_func, \
+			  _buf, _size);					     \
+	static struct shell_log_backend_control_block _name##_control_block; \
+	static const struct shell_log_backend _name##_log_backend = {	     \
+		.backend = &_name##_backend,				     \
+		.fifo = &_name##_fifo,					     \
+		.log_output = &_name##_log_output,			     \
+		.control_block = &_name##_control_block			     \
+	}
+
+#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_PTR(_name) NULL
+#endif /* CONFIG_LOG */
+
+/** @brief Enable shell log backend.
+ *
+ * @param backend		Shell log backend instance.
+ * @param ctx			Pointer to shell instance.
+ * @param init_log_level	Initial log level set to all logging sources.
+ */
+void shell_log_backend_enable(const struct shell_log_backend *backend,
+			      void *ctx, u32_t init_log_level);
+
+/** @brief Disable shell log backend.
+ *
+ * @param backend Shell log backend instance.
+ */
+void shell_log_backend_disable(const struct shell_log_backend *backend);
+
+/** @brief Trigger processing of one log entry.
+ *
+ * @param backend Shell log backend instance.
+ *
+ * @return True if message was processed, false if FIFO was empty
+ */
+bool shell_log_backend_process(const struct shell_log_backend *backend);
+
+#ifdef __cplusplus
+}
+#endif
+
+#endif /* SHELL_LOG_BACKEND_H__ */

subsys/shell/CMakeLists.txt

@@ -19,12 +19,17 @@ zephyr_sources_ifdef(
   shell_uart.c
   )
 
+zephyr_sources_ifdef(
+  CONFIG_SHELL_CMDS
+  shell_cmds.c
+)
+
 zephyr_sources_ifdef(
   CONFIG_SHELL_HISTORY
   shell_history.c
 )
 
 zephyr_sources_ifdef(
-  CONFIG_SHELL_CMDS
+  CONFIG_LOG
-  shell_cmds.c
+  shell_log_backend.c
 )

subsys/shell/Kconfig

@@ -135,6 +135,17 @@ config SHELL_HISTORY_BUFFER
 
 endif #SHELL_HISTORY
 
+config SHELL_MAX_LOG_MSG_BUFFERED
+	int "Maximal number of  log messages in FIFO"
+	default 8
+	help
+	  When amount of buffered log messages exceeds this threshold oldest
+	  messages are discarded.
+
+config SHELL_STATS
+	bool "Enable shell statistics"
+	default y
+
 config SHELL_CMDS
 	bool "Enable built-in commands"
 	default y

subsys/shell/shell.c

@@ -1033,6 +1033,44 @@ static void shell_transport_evt_handler(enum shell_transport_evt evt_type,
 	k_poll_signal(signal, 0);
 }
 
+static void shell_current_command_erase(const struct shell *shell)
+{
+	shell_multiline_data_calc(&shell->ctx->vt100_ctx.cons,
+				  shell->ctx->cmd_buff_pos,
+				  shell->ctx->cmd_buff_len);
+	shell_op_cursor_horiz_move(shell, -shell->ctx->vt100_ctx.cons.cur_x);
+	shell_op_cursor_vert_move(shell, shell->ctx->vt100_ctx.cons.cur_y - 1);
+
+	clear_eos(shell);
+}
+
+static void shell_current_command_print(const struct shell *shell)
+{
+	shell_fprintf(shell, SHELL_INFO, "%s", shell->name);
+
+	if (flag_echo_is_set(shell)) {
+		shell_fprintf(shell, SHELL_NORMAL, "%s", shell->ctx->cmd_buff);
+		shell_op_cursor_position_synchronize(shell);
+	}
+}
+
+static void shell_log_process(const struct shell *shell)
+{
+	bool processed;
+	int signaled;
+	int result;
+
+	do {
+		shell_current_command_erase(shell);
+		processed = shell_log_backend_process(shell->log_backend);
+		shell_current_command_print(shell);
+
+		k_poll_signal_check(&shell->ctx->signals[SHELL_SIGNAL_RXRDY],
+						    &signaled, &result);
+
+	} while (processed && !signaled);
+}
+
 static int shell_instance_init(const struct shell *shell, const void *p_config,
 			       bool use_colors)
 {
@@ -1057,6 +1095,10 @@ static int shell_instance_init(const struct shell *shell, const void *p_config,
 		shell->ctx->internal.flags.mode_delete = 1;
 	}
 
+	if (IS_ENABLED(CONFIG_SHELL_STATS)) {
+		shell->stats->log_lost_cnt = 0;
+	}
+
 	shell->ctx->internal.flags.tx_rdy = 1;
 	shell->ctx->internal.flags.echo = CONFIG_SHELL_ECHO_STATUS;
 	shell->ctx->state = SHELL_STATE_INITIALIZED;
@@ -1106,13 +1148,23 @@ void shell_thread(void *shell_handle, void *dummy1, void *dummy2)
 			(void)shell_instance_uninit(shell);
 
 			k_thread_abort(k_current_get());
-		} else {
+		}
+
+		k_poll_signal_check(&shell->ctx->signals[SHELL_SIGNAL_LOG_MSG],
+						    &signaled, &result);
+
+		if (!signaled) {
 			/* Other signals handled together.*/
 			k_poll_signal_reset(
 				&shell->ctx->signals[SHELL_SIGNAL_RXRDY]);
 			k_poll_signal_reset(
 				&shell->ctx->signals[SHELL_SIGNAL_TXDONE]);
 			shell_process(shell);
+		} else if (IS_ENABLED(CONFIG_LOG)) {
+			k_poll_signal_reset(
+				&shell->ctx->signals[SHELL_SIGNAL_LOG_MSG]);
+			/* process log msg */
+			shell_log_process(shell);
 		}
 	}
 }
@@ -1128,6 +1180,13 @@ int shell_init(const struct shell *shell, const void *transport_config,
 		return err;
 	}
 
+	if (log_backend) {
+		if (IS_ENABLED(CONFIG_LOG)) {
+			shell_log_backend_enable(shell->log_backend,
+						 (void *)shell, init_log_level);
+		}
+	}
+
 	(void)k_thread_create(shell->thread,
 			      shell->stack, CONFIG_SHELL_STACK_SIZE,
 			      shell_thread, (void *)shell, NULL, NULL,
@@ -1146,6 +1205,11 @@ static int shell_instance_uninit(const struct shell *shell)
 		return -EBUSY;
 	}
 
+	if (IS_ENABLED(CONFIG_LOG)) {
+		/* todo purge log queue */
+		shell_log_backend_disable(shell->log_backend);
+	}
+
 	err = shell->iface->api->uninit(shell->iface);
 	if (err != 0) {
 		return err;

subsys/shell/shell_log_backend.c

@@ -0,0 +1,167 @@
+/*
+ * Copyright (c) 2018 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#include <shell/shell_log_backend.h>
+#include <shell/shell.h>
+#include "shell_ops.h"
+#include <logging/log_ctrl.h>
+
+int shell_log_backend_output_func(u8_t *data, size_t length, void *ctx)
+{
+	shell_print_stream(ctx, data, length);
+	return length;
+}
+
+void shell_log_backend_enable(const struct shell_log_backend *backend,
+			      void *ctx, u32_t init_log_level)
+{
+	log_backend_enable(backend->backend, ctx, init_log_level);
+	log_output_ctx_set(backend->log_output, ctx);
+	backend->control_block->cnt = 0;
+	backend->control_block->state = SHELL_LOG_BACKEND_ENABLED;
+}
+
+static struct log_msg *msg_from_fifo(const struct shell_log_backend *backend)
+{
+	struct log_msg *msg = k_fifo_get(backend->fifo, K_NO_WAIT);
+
+	if (msg) {
+		atomic_dec(&backend->control_block->cnt);
+	}
+
+	return msg;
+}
+
+static void fifo_flush(const struct shell_log_backend *backend)
+{
+	struct log_msg *msg = msg_from_fifo(backend);
+
+	/* Flush log messages. */
+	while (msg) {
+		log_msg_put(msg);
+		msg = msg_from_fifo(backend);
+	}
+}
+
+static void msg_to_fifo(const struct shell *shell,
+			struct log_msg *msg)
+{
+	atomic_val_t cnt;
+
+	k_fifo_put(shell->log_backend->fifo, msg);
+
+	cnt = atomic_inc(&shell->log_backend->control_block->cnt);
+
+	/* If there is too much queued free the oldest one. */
+	if (cnt >= CONFIG_SHELL_MAX_LOG_MSG_BUFFERED) {
+		log_msg_put(msg_from_fifo(shell->log_backend));
+		if (IS_ENABLED(CONFIG_SHELL_STATS)) {
+			shell->stats->log_lost_cnt++;
+		}
+	}
+}
+
+void shell_log_backend_disable(const struct shell_log_backend *backend)
+{
+	fifo_flush(backend);
+	log_backend_disable(backend->backend);
+	backend->control_block->state = SHELL_LOG_BACKEND_DISABLED;
+}
+
+static void msg_process(const struct log_output *log_output,
+			struct log_msg *msg)
+{
+	u32_t flags = 0;
+
+	if (IS_ENABLED(CONFIG_SHELL)) {
+		flags |= LOG_OUTPUT_FLAG_COLORS;
+	}
+
+	if (IS_ENABLED(CONFIG_SHELL)) {
+		flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
+	}
+
+	log_output_msg_process(log_output, msg, flags);
+	log_msg_put(msg);
+}
+
+bool shell_log_backend_process(const struct shell_log_backend *backend)
+{
+	const struct shell *shell =
+			(const struct shell *)backend->backend->cb->ctx;
+	struct log_msg *msg = msg_from_fifo(backend);
+
+	if (!msg) {
+		return false;
+	}
+
+	msg_process(shell->log_backend->log_output, msg);
+
+	return true;
+}
+
+static void put(const struct log_backend *const backend, struct log_msg *msg)
+{
+	const struct shell *shell = (const struct shell *)backend->cb->ctx;
+	struct k_poll_signal *signal;
+
+	log_msg_get(msg);
+
+	switch (shell->log_backend->control_block->state) {
+	case SHELL_LOG_BACKEND_ENABLED:
+		msg_to_fifo(shell, msg);
+
+		if (IS_ENABLED(CONFIG_MULTITHREADING)) {
+			signal = &shell->ctx->signals[SHELL_SIGNAL_LOG_MSG];
+			k_poll_signal(signal, 0);
+		}
+
+		break;
+
+	case SHELL_LOG_BACKEND_PANIC:
+		msg_process(shell->log_backend->log_output, msg);
+		break;
+
+	case SHELL_LOG_BACKEND_DISABLED:
+		/* fall through */
+		/* no break */
+	default:
+		/* Discard message. */
+		log_msg_put(msg);
+	}
+}
+
+static void panic(const struct log_backend *const backend)
+{
+	const struct shell *shell = (const struct shell *)backend->cb->ctx;
+	int err;
+
+	err = shell->iface->api->enable(shell->iface, true);
+
+	if (err == 0) {
+		shell->log_backend->control_block->state =
+							SHELL_LOG_BACKEND_PANIC;
+
+		/* Move to the start of next line. */
+		shell_multiline_data_calc(&shell->ctx->vt100_ctx.cons,
+						  shell->ctx->cmd_buff_pos,
+						  shell->ctx->cmd_buff_len);
+		shell_op_cursor_vert_move(shell, -1);
+		shell_op_cursor_horiz_move(shell,
+					   -shell->ctx->vt100_ctx.cons.cur_x);
+
+		while (shell_log_backend_process(shell->log_backend)) {
+			/* empty */
+		}
+	} else {
+		shell_log_backend_disable(shell->log_backend);
+	}
+}
+
+const struct log_backend_api log_backend_shell_api = {
+	.put = put,
+	.panic = panic
+};