logging: Add log initialization to system startup

include/logging/log_ctrl.h

@@ -29,12 +29,18 @@ extern "C" {
 
 typedef u32_t (*timestamp_get_t)(void);
 
+/** @brief Function system initialization of the logger.
+ *
+ * Function is called during start up to allow logging before user can
+ * explicitly initialize the logger.
+ */
+void log_core_init(void);
+
 /**
- * @brief Function for initializing logger core.
+ * @brief Function for user initialization of the logger.
  *
- * @return 0 on success or error.
  */
-int log_init(void);
+void log_init(void);
 
 /**
  * @brief Function for providing timestamp function.
@@ -138,7 +144,7 @@ void log_backend_enable(struct log_backend const *const backend,
  */
 void log_backend_disable(struct log_backend const *const backend);
 
-#if defined(CONFIG_LOG) && CONFIG_LOG
+#if CONFIG_LOG
 #define LOG_INIT() log_init()
 #define LOG_PANIC() log_panic()
 #define LOG_PROCESS() log_process(false)

include/logging/log_msg.h

@@ -182,6 +182,9 @@ union log_msg_chunk {
 
 extern struct k_mem_slab log_msg_pool;
 
+/** @brief Function for initialization of the log message pool. */
+void log_msg_pool_init(void);
+
 /** @brief Function for indicating that message is in use.
  *
  *  @details Message can be used (read) by multiple users. Internal reference

kernel/init.c

@@ -30,6 +30,7 @@
 #include <kernel_internal.h>
 #include <kswap.h>
 #include <entropy.h>
+#include <logging/log_ctrl.h>
 
 /* kernel build timestamp items */
 #define BUILD_TIMESTAMP "BUILD: " __DATE__ " " __TIME__
@@ -459,6 +460,10 @@ FUNC_NORETURN void _Cstart(void)
 
 	_IntLibInit();
 
+	if (IS_ENABLED(CONFIG_LOG)) {
+		log_core_init();
+	}
+
 	/* perform any architecture-specific initialization */
 	kernel_arch_init();
 

samples/subsys/logging/logger/src/main.c

@@ -172,7 +172,8 @@ static void performance_showcase(void)
 	u32_t window = 2;
 
 	do {
-		LOG_INF("performance test - log message %d", cnt++);
+		LOG_INF("performance test - log message %d", cnt);
+		cnt++;
 		current_timestamp = timestamp_get();
 	} while (current_timestamp < (start_timestamp + window));
 
@@ -191,12 +192,9 @@ static void external_log_system_showcase(void)
 
 void main(void)
 {
-	int err = LOG_INIT();
-
-	if (err == 0) {
-		err = log_set_timestamp_func(timestamp_get, timestamp_freq());
-	}
+	LOG_INIT();
 
+	int err = log_set_timestamp_func(timestamp_get, timestamp_freq());
 	(void)err;
 
 	module_logging_showcase();

subsys/logging/log_core.c

@@ -11,6 +11,7 @@
 #include <logging/log_output.h>
 #include <misc/printk.h>
 #include <assert.h>
+#include <atomic.h>
 #include <stdio.h>
 
 #ifndef CONFIG_LOG_PRINTK_MAX_STRING_LENGTH
@@ -23,10 +24,16 @@ LOG_BACKEND_UART_DEFINE(log_backend_uart);
 #endif
 
 static struct log_list_t list;
+static atomic_t initialized;
 static bool panic_mode;
-static bool initialized;
 
-static timestamp_get_t timestamp_func;
+static u32_t dummy_timestamp(void);
+static timestamp_get_t timestamp_func = dummy_timestamp;
+
+static u32_t dummy_timestamp(void)
+{
+	return 0;
+}
 
 static inline void msg_finalize(struct log_msg *msg,
 				struct log_msg_ids src_level)
@@ -130,10 +137,6 @@ int log_printk(const char *fmt, va_list ap)
 		struct log_msg *msg;
 		int length;
 
-		if (!initialized) {
-			log_init();
-		}
-
 		length = vsnprintf(formatted_str,
 				   sizeof(formatted_str), fmt, ap);
 
@@ -173,25 +176,43 @@ static u32_t timestamp_get(void)
 	return k_cycle_get_32();
 }
 
-int log_init(void)
+void log_core_init(void)
+{
+	log_msg_pool_init();
+	log_list_init(&list);
+
+	/* No backends attached so far but set default level as a filter for
+	 * any source of logging in the system. When backends are attached later
+	 * logs will be filtered out during processing.
+	 */
+	if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
+		for (int i = 0; i < log_sources_count(); i++) {
+			u32_t *filters = log_dynamic_filters_get(i);
+
+			LOG_FILTER_SLOT_SET(filters,
+					    LOG_FILTER_AGGR_SLOT_IDX,
+					    CONFIG_LOG_DEFAULT_LEVEL);
+		}
+	}
+}
+
+void log_init(void)
 {
 	assert(log_backend_count_get() < LOG_FILTERS_NUM_OF_SLOTS);
+	int i;
+
+	if (atomic_inc(&initialized)) {
+		return;
+	}
 
 	/* Set default timestamp. */
 	timestamp_func = timestamp_get;
 	log_output_timestamp_freq_set(CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC);
 
-	if (!initialized) {
-		log_list_init(&list);
-
-		/* Assign ids to backends. */
-		for (int i = 0; i < log_backend_count_get(); i++) {
-			log_backend_id_set(log_backend_get(i),
-					 i + LOG_FILTER_FIRST_BACKEND_SLOT_IDX);
-		}
-
-		panic_mode = false;
-		initialized = true;
+	/* Assign ids to backends. */
+	for (i = 0; i < log_backend_count_get(); i++) {
+		log_backend_id_set(log_backend_get(i),
+				   i + LOG_FILTER_FIRST_BACKEND_SLOT_IDX);
 	}
 
 #ifdef CONFIG_LOG_BACKEND_UART
@@ -200,7 +221,6 @@ int log_init(void)
 			   NULL,
 			   CONFIG_LOG_DEFAULT_LEVEL);
 #endif
-	return 0;
 }
 
 int log_set_timestamp_func(timestamp_get_t timestamp_getter, u32_t freq)

subsys/logging/log_msg.c

@@ -11,7 +11,14 @@
 #define MSG_SIZE sizeof(union log_msg_chunk)
 #define NUM_OF_MSGS (CONFIG_LOG_BUFFER_SIZE / MSG_SIZE)
 
-K_MEM_SLAB_DEFINE(log_msg_pool, MSG_SIZE, NUM_OF_MSGS, sizeof(u32_t));
+struct k_mem_slab log_msg_pool;
+static u8_t __noinit __aligned(sizeof(u32_t))
+		log_msg_pool_buf[CONFIG_LOG_BUFFER_SIZE];
+
+void log_msg_pool_init(void)
+{
+	k_mem_slab_init(&log_msg_pool, log_msg_pool_buf, MSG_SIZE, NUM_OF_MSGS);
+}
 
 void log_msg_get(struct log_msg *msg)
 {

tests/subsys/logging/log_core/src/log_core_test.c

@@ -114,9 +114,8 @@ static void log_setup(bool backend2_enable)
 {
 	stamp = 0;
 
-	zassert_equal(0,
-		      log_init(),
-		      "Expects successful initialization.");
+	log_init();
+
 	zassert_equal(0, log_set_timestamp_func(timestamp_get, 0),
 		      "Expects successful timestamp function setting.");