Added new logging backend - for spinel protocol

subsys/logging/CMakeLists.txt

@@ -53,6 +53,18 @@ if(NOT CONFIG_LOG_MINIMAL)
     CONFIG_LOG_BACKEND_RB
     log_backend_rb.c
   )
+
+  if(CONFIG_LOG_BACKEND_SPINEL)
+    zephyr_library_include_directories(
+	    ${ZEPHYR_BASE}/subsys/net/lib/openthread/platform/
+    )
+  endif()
+
+  zephyr_sources_ifdef(
+    CONFIG_LOG_BACKEND_SPINEL
+    log_backend_spinel.c
+  )
+
 else()
   zephyr_sources(log_minimal.c)
 endif()

subsys/logging/Kconfig

@@ -424,6 +424,52 @@ config LOG_BACKEND_RTT_FORCE_PRINTK
 
 endif # LOG_BACKEND_RTT
 
+config LOG_BACKEND_SPINEL
+	bool "Enable OpenThread dedicated Spinel protocol backend"
+	depends on (OPENTHREAD_NCP_SPINEL_ON_UART_DEV_NAME!=UART_CONSOLE_ON_DEV_NAME || !LOG_BACKEND_UART)
+	depends on NET_L2_OPENTHREAD
+	help
+	  When enabled, backend will use OpenThread dedicated SPINEL protocol for logging. 
+	  This protocol is byte oriented and wrapps given messages into serial frames.Backend 
+	  should be enabled only to OpenThread purposes and when UART backend is disabled 
+	  or works on antoher UART device to avoid interference.
+
+if LOG_BACKEND_SPINEL
+
+config LOG_BACKEND_SPINEL_BUFFER_SIZE
+	int "Size of reserved up-buffer for logger output."
+	default 1024
+	help
+	  Specify reserved size of up-buffer used for logger output.
+
+choice
+	prompt "Spinel backend log level"
+	help
+	  This option selects log level for Spinel backend stack.
+
+config LOG_BACKEND_SPINEL_LEVEL_CRITICAL
+	bool "Critical"
+config LOG_BACKEND_SPINEL_LEVEL_WARNING
+	bool "Warning"
+config LOG_BACKEND_SPINEL_LEVEL_NOTE
+	bool "Note"
+config LOG_BACKEND_SPINEL_LEVEL_INFO
+	bool "Info"
+config LOG_BACKEND_SPINEL_LEVEL_DEBUG
+	bool "Debug"
+endchoice
+
+config LOG_BACKEND_SPINEL_LEVEL
+	int
+	default 1 if LOG_BACKEND_SPINEL_LEVEL_CRITICAL
+	default 2 if LOG_BACKEND_SPINEL_LEVEL_WARNING
+	default 3 if LOG_BACKEND_SPINEL_LEVEL_NOTE
+	default 4 if LOG_BACKEND_SPINEL_LEVEL_INFO
+	default 5 if LOG_BACKEND_SPINEL_LEVEL_DEBUG
+	default 0
+
+endif # LOG_BACKEND_SPINEL
+
 config LOG_BACKEND_NATIVE_POSIX
 	bool "Enable native backend"
 	depends on ARCH_POSIX

subsys/logging/log_backend_spinel.c

@@ -0,0 +1,109 @@
+/*
+ * Copyright (c) 2020 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#include <logging/log_backend.h>
+#include <logging/log_output.h>
+#include <openthread/platform/logging.h>
+#include <openthread/platform/uart.h>
+#include <platform-zephyr.h>
+#include "log_backend_std.h"
+
+#ifndef CONFIG_LOG_BACKEND_SPINEL_BUFFER_SIZE
+#define CONFIG_LOG_BACKEND_SPINEL_BUFFER_SIZE 0
+#endif
+
+static uint8_t char_buf[CONFIG_LOG_BACKEND_SPINEL_BUFFER_SIZE];
+static bool panic_mode;
+
+static int write(uint8_t *data, size_t length, void *ctx);
+
+LOG_OUTPUT_DEFINE(log_output, write, char_buf, sizeof(char_buf));
+
+static inline bool is_panic_mode(void)
+{
+	return panic_mode;
+}
+
+static void put(const struct log_backend *const backend,
+		struct log_msg *msg)
+{
+	/* prevent adding CRLF, which may crash spinel decoding */
+	uint32_t flag = LOG_OUTPUT_FLAG_CRLF_NONE;
+
+	log_backend_std_put(&log_output, flag, msg);
+}
+
+static void sync_string(const struct log_backend *const backend,
+		     struct log_msg_ids src_level, uint32_t timestamp,
+		     const char *fmt, va_list ap)
+{
+	/* prevent adding CRLF, which may crash spinel decoding */
+	uint32_t flag = LOG_OUTPUT_FLAG_CRLF_NONE;
+
+	log_backend_std_sync_string(&log_output, flag, src_level,
+				    timestamp, fmt, ap);
+}
+
+static void sync_hexdump(const struct log_backend *const backend,
+			 struct log_msg_ids src_level, uint32_t timestamp,
+			 const char *metadata, const uint8_t *data, uint32_t length)
+{
+	/* prevent adding CRLF, which may crash spinel decoding */
+	uint32_t flag = LOG_OUTPUT_FLAG_CRLF_NONE;
+
+	log_backend_std_sync_hexdump(&log_output, flag, src_level,
+				     timestamp, metadata, data, length);
+}
+
+static void log_backend_spinel_init(void)
+{
+	memset(char_buf, '\0', sizeof(char_buf));
+}
+
+static void panic(struct log_backend const *const backend)
+{
+	ARG_UNUSED(backend);
+	panic_mode = true;
+}
+
+static void dropped(const struct log_backend *const backend, uint32_t cnt)
+{
+	ARG_UNUSED(backend);
+
+	log_backend_std_dropped(&log_output, cnt);
+}
+
+static int write(uint8_t *data, size_t length, void *ctx)
+{
+	if(is_panic_mode()) {
+		/* In panic mode otPlatLog implemented for Spinel protocol
+		 * cannot be used, because it cannot be called from interrupt.
+		 * In such situation raw data bytes without encoding are send. 
+		 */
+		platformUartPanic();
+		otPlatUartSend(data, length);
+	} else {
+		otPlatLog(CONFIG_LOG_BACKEND_SPINEL_LEVEL, OT_LOG_REGION_PLATFORM,
+			"%s", data);
+	}
+
+	/* make sure that buffer will be clean in next attempt */
+	memset(char_buf, '\0', length);
+	return length;
+}
+
+const struct log_backend_api log_backend_spinel_api = {
+	.put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put,
+	.put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ?
+			sync_string : NULL,
+	.put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ?
+			sync_hexdump : NULL,
+	.panic = panic,
+	.init = log_backend_spinel_init,
+	.dropped = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : dropped,
+};
+
+LOG_BACKEND_DEFINE(log_backend_spinel, log_backend_spinel_api, true);

subsys/net/lib/openthread/platform/CMakeLists.txt

@@ -4,13 +4,13 @@ zephyr_library_named(openthread_platform)
 zephyr_library_sources(
   alarm.c
   entropy.c
-  logging.c
   misc.c
   platform.c
   radio.c
   settings.c
   spi.c
   )
 
+zephyr_library_sources_ifndef(CONFIG_LOG_BACKEND_SPINEL logging.c)
 zephyr_library_sources_ifdef(CONFIG_OPENTHREAD_NCP uart.c)
 zephyr_library_sources_ifdef(CONFIG_OPENTHREAD_SHELL shell.c)

subsys/net/lib/openthread/platform/platform-zephyr.h

@@ -54,6 +54,12 @@ void platformRadioProcess(otInstance *aInstance);
  */
 void platformUartProcess(otInstance *aInstance);
 
+/**
+ * Outer component calls this method to notify UART driver that it should 
+ * switch to panic mode and work in synchronous way.
+ */
+void platformUartPanic(void);
+
 /**
  * Get current channel from radio driver.
  *

subsys/net/lib/openthread/platform/uart.c

@@ -48,6 +48,8 @@ OT_UART_DEFINE(ot_uart, CONFIG_OPENTHREAD_NCP_UART_RING_BUFFER_SIZE);
 
 #define RX_FIFO_SIZE 128
 
+static bool is_panic_mode;
+
 static void uart_rx_handle(void)
 {
 	u8_t *data;
@@ -208,7 +210,14 @@ otError otPlatUartSend(const u8_t *aBuf, u16_t aBufLength)
 	size_t cnt = ring_buf_put(ot_uart.tx_ringbuf, aBuf, aBufLength);
 
 	if (atomic_set(&(ot_uart.tx_busy), 1) == 0) {
-		uart_irq_tx_enable(ot_uart.dev);
+		if(is_panic_mode) {
+			/* In panic mode all data have to be send immediately
+			 * without using interrupts
+		 	 */
+			otPlatUartFlush();
+		} else {
+			uart_irq_tx_enable(ot_uart.dev);
+		}
 	}
 
 	if (cnt == aBufLength) {
@@ -217,3 +226,38 @@ otError otPlatUartSend(const u8_t *aBuf, u16_t aBufLength)
 		return OT_ERROR_BUSY;
 	}
 };
+
+otError otPlatUartFlush(void)
+{
+	u32_t len;
+	const u8_t *data;
+	otError result = OT_ERROR_NONE;
+
+	do {
+		len = ring_buf_get_claim(ot_uart.tx_ringbuf, (u8_t **)&data,
+				 	ot_uart.tx_ringbuf->size);
+
+		if (len) {
+			for (size_t i = 0; i < len; i++) {
+				uart_poll_out(ot_uart.dev, data[i]);
+			}
+
+			ring_buf_get_finish(ot_uart.rx_ringbuf, len);
+		}
+	} while (len);
+
+	ot_uart.tx_busy = 0;
+	atomic_set(&(ot_uart.tx_finished), 1);
+	otSysEventSignalPending();
+	return result;
+}
+
+void platformUartPanic(void)
+{
+	is_panic_mode = true;
+	/* In panic mode data are send without using interrupts.
+	 * Reception in this mode is not supported.
+	 */
+	uart_irq_tx_disable(ot_uart.dev);
+	uart_irq_rx_disable(ot_uart.dev);
+}