logging: log_output: Improve immediate mode handling

When in immediate mode ensure that buffering is not used in log output.
Every byte is pushed to the transport.

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

include/logging/log_output.h

@@ -9,6 +9,7 @@
 #include <logging/log_msg.h>
 #include <sys/util.h>
 #include <stdarg.h>
+#include <sys/atomic.h>
 
 #ifdef __cplusplus
 extern "C" {
@@ -66,7 +67,7 @@ typedef int (*log_output_func_t)(u8_t *buf, size_t size, void *ctx);
 
 /* @brief Control block structure for log_output instance.  */
 struct log_output_control_block {
-	size_t offset;
+	atomic_t offset;
 	void *ctx;
 	const char *hostname;
 };

subsys/logging/Kconfig

@@ -127,6 +127,17 @@ config LOG_IMMEDIATE
 	  flawlessly in that mode because one log operation can be interrupted
 	  by another one in the higher priority context.
 
+if LOG_IMMEDIATE
+config LOG_IMMEDIATE_CLEAN_OUTPUT
+	bool "Enable clean log output"
+	help
+	  If enabled, interrupts are locked during whole log message processing.
+	  As a result, processing on one log message cannot be interrupted by
+	  another one and output is clean, not interleaved. However, enabling
+	  this option is causing interrupts locking for significant amount of
+	  time (up to multiple milliseconds).
+endif
+
 config LOG_ENABLE_FANCY_OUTPUT_FORMATTING
 	depends on MINIMAL_LIBC
 	bool "Format strings with minimal libc _prf() instead of _vprintk()"

subsys/logging/log_backend_std.h

@@ -8,7 +8,7 @@
 
 #include <logging/log_msg.h>
 #include <logging/log_output.h>
-#include <irq.h>
+#include <kernel.h>
 
 #ifdef __cplusplus
 extern "C" {
@@ -76,7 +76,7 @@ log_backend_std_sync_string(const struct log_output *const log_output,
 			    u32_t flags, struct log_msg_ids src_level,
 			    u32_t timestamp, const char *fmt, va_list ap)
 {
-	u32_t key;
+	int key;
 
 	flags |= LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP;
 	if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) {
@@ -87,16 +87,20 @@ log_backend_std_sync_string(const struct log_output *const log_output,
 		flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
 	}
 
-	key = irq_lock();
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
-	/* Even though interrupts are locked here there are still cases when
+		IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
-	 * it may lead to failure. Log output is not re-entrant and irq_lock
+		/* In order to ensure that one log processing is not interrupted
-	 * does not prevent NMI or ZLI (Zero latency interrupts). If context
+		 * by another one, lock context for whole log processing.
-	 * is interrupted by NMI it usually means fault scenario and best that
+		 */
-	 * can be done is to flush the output and process new data.
+		key = irq_lock();
-	 */
+	}
-	log_output_flush(log_output);
+
 	log_output_string(log_output, src_level, timestamp, fmt, ap, flags);
-	irq_unlock(key);
+
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
+		IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
+		irq_unlock(key);
+	}
 }
 
 /** @brief Synchronously process hexdump message by a standard logger backend.
@@ -115,7 +119,7 @@ log_backend_std_sync_hexdump(const struct log_output *const log_output,
 			     u32_t timestamp, const char *metadata,
 			     const u8_t *data, u32_t length)
 {
-	u32_t key;
+	int key;
 
 	flags |= LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP;
 	if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) {
@@ -126,17 +130,21 @@ log_backend_std_sync_hexdump(const struct log_output *const log_output,
 		flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP;
 	}
 
-	key = irq_lock();
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
-	/* Even though interrupts are locked here there are still cases when
+		IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
-	 * it may lead to failure. Log output is not re-entrant and irq_lock
+		/* In order to ensure that one log processing is not interrupted
-	 * does not prevent NMI or ZLI (Zero latency interrupts). If context
+		 * by another one, lock context for whole log processing.
-	 * is interrupted by NMI it usually means fault scenario and best that
+		 */
-	 * can be done is to flush the output and process new data.
+		key = irq_lock();
-	 */
+	}
-	log_output_flush(log_output);
+
 	log_output_hexdump(log_output, src_level, timestamp,
 			metadata, data, length, flags);
-	irq_unlock(key);
+
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
+		IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
+		irq_unlock(key);
+	}
 }
 
 #ifdef __cplusplus

subsys/logging/log_output.c

@@ -102,16 +102,23 @@ static int out_func(int c, void *ctx)
 {
 	const struct log_output *out_ctx =
 					(const struct log_output *)ctx;
+	int idx;
 
-	out_ctx->buf[out_ctx->control_block->offset] = (u8_t)c;
+	if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
-	out_ctx->control_block->offset++;
+		/* Backend must be thread safe in synchronous operation. */
-
+		out_ctx->func((u8_t *)&c, 1, out_ctx->control_block->ctx);
-	__ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size);
+		return 0;
+	}
 
 	if (out_ctx->control_block->offset == out_ctx->size) {
 		log_output_flush(out_ctx);
 	}
 
+	idx = atomic_inc(&out_ctx->control_block->offset);
+	out_ctx->buf[idx] = (u8_t)c;
+
+	__ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size);
+
 	return 0;
 }
 
@@ -145,6 +152,7 @@ static void buffer_write(log_output_func_t outf, u8_t *buf, size_t len,
 	} while (len != 0);
 }
 
+
 void log_output_flush(const struct log_output *log_output)
 {
 	buffer_write(log_output->func, log_output->buf,