tests: logging: Add test for log backend prolong init

Add test for handling of autostarting backends which have
prolonged initialization and implements function for polling
for readiness.

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

tests/subsys/logging/log_backend_init/CMakeLists.txt

@@ -0,0 +1,8 @@
+# SPDX-License-Identifier: Apache-2.0
+
+cmake_minimum_required(VERSION 3.20.0)
+find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
+project(log_backend_initialization)
+
+FILE(GLOB app_sources src/*.c)
+target_sources(app PRIVATE ${app_sources})

tests/subsys/logging/log_backend_init/prj.conf

@@ -0,0 +1,14 @@
+CONFIG_MAIN_THREAD_PRIORITY=5
+CONFIG_ZTEST=y
+CONFIG_TEST_LOGGING_DEFAULTS=n
+CONFIG_LOG=y
+CONFIG_LOG_PRINTK=n
+CONFIG_LOG_RUNTIME_FILTERING=y
+CONFIG_LOG_BACKEND_UART=n
+CONFIG_LOG_BUFFER_SIZE=768
+CONFIG_KERNEL_LOG_LEVEL_OFF=y
+CONFIG_SOC_LOG_LEVEL_OFF=y
+CONFIG_ARCH_LOG_LEVEL_OFF=y
+CONFIG_LOG_FUNC_NAME_PREFIX_DBG=n
+CONFIG_LOG_PROCESS_THREAD=y
+CONFIG_ASSERT=y

tests/subsys/logging/log_backend_init/src/main.c

@@ -0,0 +1,149 @@
+/*
+ * Copyright (c) 2021 Nordic Semiconductor
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+
+#include <tc_util.h>
+#include <stdbool.h>
+#include <zephyr.h>
+#include <ztest.h>
+#include <logging/log_backend.h>
+#include <logging/log_ctrl.h>
+#include <logging/log.h>
+
+#define LOG_MODULE_NAME test
+LOG_MODULE_REGISTER(LOG_MODULE_NAME);
+
+struct backend_context {
+	uint32_t cnt;
+	const char *exp_str[10];
+	uint32_t delay;
+	bool active;
+	struct k_timer timer;
+};
+
+static int cbprintf_callback(int c, void *ctx)
+{
+	char **p = ctx;
+
+	**p = c;
+	(*p)++;
+
+	return c;
+}
+
+static void backend_process(const struct log_backend *const backend,
+			    union log_msg2_generic *msg)
+{
+	char str[100];
+	char *pstr = str;
+	struct backend_context *context = (struct backend_context *)backend->cb->ctx;
+	size_t len;
+	uint8_t *p = log_msg2_get_package(&msg->log, &len);
+
+	(void)len;
+	int slen = cbpprintf(cbprintf_callback, &pstr, p);
+
+	str[slen] = '\0';
+
+	zassert_equal(strcmp(str, context->exp_str[context->cnt]), 0,
+			"Unexpected string %s (exp:%s)", str, context->exp_str[context->cnt]);
+
+	context->cnt++;
+}
+
+static void expire_cb(struct k_timer *timer)
+{
+	void *ctx = k_timer_user_data_get(timer);
+	struct backend_context *context = (struct backend_context *)ctx;
+
+	context->active = true;
+}
+
+static void backend_init(const struct log_backend *const backend)
+{
+	struct backend_context *context = (struct backend_context *)backend->cb->ctx;
+
+	k_timer_init(&context->timer, expire_cb, NULL);
+	k_timer_user_data_set(&context->timer, (void *)context);
+	k_timer_start(&context->timer, K_MSEC(context->delay), K_NO_WAIT);
+}
+
+static int backend_is_ready(const struct log_backend *const backend)
+{
+	struct backend_context *context = (struct backend_context *)backend->cb->ctx;
+
+	return context->active ? 0 : -EBUSY;
+}
+
+static const struct log_backend_api backend_api = {
+	.process = backend_process,
+	.init = backend_init,
+	.is_ready = backend_is_ready
+};
+
+static struct backend_context context1 = {
+	.delay = 500
+};
+
+static struct backend_context context2 = {
+	.delay = 1000,
+};
+
+LOG_BACKEND_DEFINE(backend1, backend_api, true, &context1);
+LOG_BACKEND_DEFINE(backend2, backend_api, true, &context2);
+
+/* Test is using two backends which are configured to be autostarted but have
+ * prolonged initialization. Backend1 starts earlier.
+ *
+ * Logging does not process logs until at least one backend is ready so once
+ * backend1 is ready first log message is processed. Since backend2 is not yet
+ * ready it will not receive this message. Second message is created when
+ * both backends are initialized so both receives the message.
+ */
+void test_log_backends_initialization(void)
+{
+	if (log_backend_count_get() != 2) {
+		/* Other backends should not be enabled. */
+		ztest_test_skip();
+	}
+
+	context1.cnt = 0;
+	context2.cnt = 0;
+
+	context1.exp_str[0] = "test1";
+	context1.exp_str[1] = "test2";
+
+	context2.exp_str[0] = "test2";
+
+	LOG_INF("test1");
+
+	/* Backends are not yet active. */
+	zassert_false(context1.active, NULL);
+	zassert_false(context2.active, NULL);
+
+	k_msleep(context2.delay + 100);
+
+	zassert_true(context1.active, NULL);
+	zassert_true(context2.active, NULL);
+
+	LOG_INF("test2");
+
+	k_msleep(1100);
+
+	/* Backend1 gets both messages but backend2 gets only second message
+	 * because when first was processed it was not yet active.
+	 */
+	zassert_equal(context1.cnt, 2, "Unexpected value:%d (exp: %d)", context1.cnt, 2);
+	zassert_equal(context2.cnt, 1, NULL);
+}
+
+void test_main(void)
+{
+	ztest_test_suite(test_log_backend_init,
+			 ztest_unit_test(test_log_backends_initialization)
+			 );
+	ztest_run_test_suite(test_log_backend_init);
+}

tests/subsys/logging/log_backend_init/testcase.yaml

@@ -0,0 +1,6 @@
+tests:
+  logging.log_backend_initialization:
+    integration_platforms:
+      - native_posix
+    tags: log_core logging
+    filter: not CONFIG_LOG_MODE_IMMEDIATE