tests/subsys/logging/log_core_additional/src/log_test.c

/*
 * Copyright (c) 2020 Intel Corporation
 *
 * SPDX-License-Identifier: Apache-2.0
 */

/**
 * @file
 * @brief Additional test case for log core
 *
 */

#include <zephyr/tc_util.h>
#include <stdbool.h>
#include <zephyr/kernel.h>
#include <zephyr/ztest.h>
#include <zephyr/logging/log_backend.h>
#include <zephyr/logging/log_backend_std.h>
#include <zephyr/logging/log_ctrl.h>
#include <zephyr/logging/log.h>
#include <zephyr/logging/log_output.h>

#define LOG_MODULE_NAME log_test
LOG_MODULE_REGISTER(LOG_MODULE_NAME, LOG_LEVEL_INF);
static K_SEM_DEFINE(log_sem, 0, 1);

#define TIMESTAMP_FREC (2000000)
ZTEST_BMEM uint32_t source_id;
/* used when log_msg create in user space */
ZTEST_BMEM uint8_t domain, level;
ZTEST_DMEM uint32_t msg_data = 0x1234;
ZTEST_DMEM char *test_msg_usr = "test msg";

static uint8_t buf;
static int char_out(uint8_t *data, size_t length, void *ctx)
{
	ARG_UNUSED(data);
	ARG_UNUSED(ctx);
	return length;
}
LOG_OUTPUT_DEFINE(log_output, char_out, &buf, 1);

struct backend_cb {
	/* count log messages handled by this backend */
	size_t counter;
	/* count log messages handled immediately by this backend */
	size_t sync;
	/* inform put() to check timestamp of message against exp_timestamps */
	bool check_timestamp;
	uint32_t exp_timestamps[16];
	/* inform put() to check severity of message against exp_severity */
	bool check_severity;
	uint16_t exp_severity[4];
	/* inform put() to check domain_id of message */
	bool check_domain_id;
	/* How many messages have been logged.
	 * used in async mode, to make sure all logs have been handled by compare
	 * counter with total_logs
	 */
	size_t total_logs;
};

static void process(const struct log_backend *const backend,
		union log_msg_generic *msg)
{
	uint32_t flags;
	struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx;

	/* If printk message skip it. */
	if (log_msg_get_level(&(msg->log)) == LOG_LEVEL_INTERNAL_RAW_STRING) {
		return;
	}

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		cb->sync++;
	}

	if (cb->check_domain_id) {
		zassert_equal(log_msg_get_domain(&(msg->log)), Z_LOG_LOCAL_DOMAIN_ID,
				"Unexpected domain id");
	}

	if (cb->check_timestamp) {
		uint32_t exp_timestamp = cb->exp_timestamps[cb->counter];

		zassert_equal(log_msg_get_timestamp(&(msg->log)), exp_timestamp,
			      "Unexpected message index");
	}

	if (cb->check_severity) {
		zassert_equal(log_msg_get_level(&(msg->log)),
			      cb->exp_severity[cb->counter],
			      "Unexpected log severity");
	}

	cb->counter++;
	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		if (cb->counter == cb->total_logs) {
			k_sem_give(&log_sem);
		}
	}

	if (k_is_user_context()) {
		zassert_equal(log_msg_get_domain(&(msg->log)), domain,
				"Unexpected domain id");

		zassert_equal(log_msg_get_level(&(msg->log)), level,
			      "Unexpected log severity");
	}

	flags = log_backend_std_get_flags();
	log_output_msg_process(&log_output, &msg->log, flags);
}

static void panic(const struct log_backend *const backend)
{
	ARG_UNUSED(backend);
}

const struct log_backend_api log_backend_test_api = {
	.process = process,
	.panic = panic,
};

LOG_BACKEND_DEFINE(backend1, log_backend_test_api, false);
struct backend_cb backend1_cb;

LOG_BACKEND_DEFINE(backend2, log_backend_test_api, false);
struct backend_cb backend2_cb;

/* The logging system support user customize timestamping in log messages
 * by register a timestamp function, in timestamp_get() below, just return
 * a counter as timestamp for different messages.
 * when install this timestamp function, timestamping frequency is set to
 * 2000000, means 2 timestamp/us
 */
#ifndef CONFIG_USERSPACE
static uint32_t stamp;
static uint32_t timestamp_get(void)
{
	stamp++;
	return log_output_timestamp_to_us(stamp * 2);
}

static void log_setup(bool backend2_enable)
{
	stamp = 0U;

	log_init();
#ifndef CONFIG_LOG_PROCESS_THREAD
	log_thread_set(k_current_get());
#endif

	memset(&backend1_cb, 0, sizeof(backend1_cb));

	log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);

	if (backend2_enable) {
		memset(&backend2_cb, 0, sizeof(backend2_cb));

		log_backend_enable(&backend2, &backend2_cb, LOG_LEVEL_DBG);
	} else {
		log_backend_disable(&backend2);
	}
}

#endif

static bool log_test_process(void)
{
	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		/* waiting for all logs have been handled */
		k_sem_take(&log_sem, K_FOREVER);
		return false;
	} else {
		return log_process();
	}
}

/**
 * @brief Support multi-processor systems
 *
 * @details Logging system identify domain/processor by domain_id which is now
 *          statically configured by Z_LOG_LOCAL_DOMAIN_ID
 *
 * @addtogroup logging
 */

#ifndef CONFIG_USERSPACE

/**
 * @brief Create Tests for Dynamic Loadable Logging Backends
 *
 * @details Test the three APIs, log_backend_activate, log_backend_is_active and
 *          log_backend_deactivate.
 *
 * @addtogroup logging
 */
ZTEST(test_log_core_additional, test_log_backend)
{
	log_init();

	zassert_false(log_backend_is_active(&backend1));
	log_backend_activate(&backend1, NULL);
	zassert_true(log_backend_is_active(&backend1));
	log_backend_deactivate(&backend1);
	zassert_false(log_backend_is_active(&backend1));
}

ZTEST(test_log_core_additional, test_log_domain_id)
{
	log_setup(false);

	backend1_cb.check_domain_id = true;
	backend1_cb.total_logs = 1;

	LOG_INF("info message for domain id test");

	while (log_test_process()) {
	}

	zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
		      "Unexpected amount of messages received by the backend");
}

/**
 * @brief Synchronous processing of logging messages.
 *
 * @details if CONFIG_LOG_MODE_IMMEDIATE is enabled, log message is
 *          handled immediately
 *
 * @addtogroup logging
 */
ZTEST(test_log_core_additional, test_log_sync)
{
	TC_PRINT("Logging synchronously\n");

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		log_setup(false);
		LOG_INF("Log immediately");
		LOG_INF("Log immediately");

		/* log immediately, no log_process needed */
		zassert_equal(2, backend1_cb.sync,
			      "Unexpected amount of messages received by the backend.");
	} else {
		ztest_test_skip();
	}
}

/**
 * @brief Early logging
 * @details Handle log message attempts as well as creating new log contexts
 *         instance, before the backend are active
 *
 * @addtogroup logging
 */
ZTEST(test_log_core_additional, test_log_early_logging)
{
	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		ztest_test_skip();
	} else {
		log_init();

		/* deactivate other backends */
		STRUCT_SECTION_FOREACH(log_backend, backend) {
			if (strcmp(backend->name, "test")) {
				log_backend_deactivate(backend);
			}
		}

		TC_PRINT("Create log message before backend active\n");

		LOG_INF("log info before backend active");
		LOG_WRN("log warn before backend active");
		LOG_ERR("log error before backend active");

		TC_PRINT("Activate backend with context");
		memset(&backend1_cb, 0, sizeof(backend1_cb));
		backend1_cb.total_logs = 3;
		log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);

		while (log_test_process()) {
		}

		zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
			      "Unexpected amount of messages received. %d",
			      backend1_cb.counter);
	}
}

/**
 * @brief Log severity
 *
 * @details This module is registered with LOG_LEVEL_INF, LOG_LEVEL_DBG will be
 *          filtered out at compile time, only 3 message handled
 *
 * @addtogroup logging
 */
ZTEST(test_log_core_additional, test_log_severity)
{
	log_setup(false);

	backend1_cb.check_severity = true;
	backend1_cb.exp_severity[0] = LOG_LEVEL_INF;
	backend1_cb.exp_severity[1] = LOG_LEVEL_WRN;
	backend1_cb.exp_severity[2] = LOG_LEVEL_ERR;

	LOG_INF("info message");
	LOG_WRN("warning message");
	LOG_ERR("error message");
	backend1_cb.total_logs = 3;

	while (log_test_process()) {
	}

	zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
		      "Unexpected amount of messages received by the backend.");
}

/**
 * @brief Customizable timestamping in log messages
 *
 * @details Log core permit user to register customized timestamp function
 *
 * @addtogroup logging
 */
ZTEST(test_log_core_additional, test_log_timestamping)
{
	stamp = 0U;

	log_init();
	/* deactivate all other backend */
	STRUCT_SECTION_FOREACH(log_backend, backend) {
		if ((backend == &backend1) || (backend == &backend2)) {
			log_backend_deactivate(backend);
		}
	}

	TC_PRINT("Register timestamp function\n");
	zassert_equal(-EINVAL, log_set_timestamp_func(NULL, 0),
		      "Expects successful timestamp function setting.");
	zassert_equal(0, log_set_timestamp_func(timestamp_get, TIMESTAMP_FREC),
		      "Expects successful timestamp function setting.");

	memset(&backend1_cb, 0, sizeof(backend1_cb));
	log_backend_enable(&backend1, &backend1_cb, LOG_LEVEL_DBG);

	backend1_cb.check_timestamp = true;

	backend1_cb.exp_timestamps[0] = 1U;
	backend1_cb.exp_timestamps[1] = 2U;
	backend1_cb.exp_timestamps[2] = 3U;

	LOG_INF("test timestamp");
	LOG_INF("test timestamp");
	LOG_WRN("test timestamp");
	backend1_cb.total_logs = 3;

	while (log_test_process()) {
	}

	zassert_equal(backend1_cb.total_logs,
		      backend1_cb.counter,
		      "Unexpected amount of messages received by the backend.");
}

/**
 * @brief Multiple logging backends
 *
 * @details Enable two backends in this module and enable UART backend
 *          by CONFIG_LOG_BACKEND_UART, there are three backends at least.
 *
 * @addtogroup logging
 */

#define UART_BACKEND "log_backend_uart"
ZTEST(test_log_core_additional, test_multiple_backends)
{
	int cnt;

	TC_PRINT("Test multiple backends");
	/* enable both backend1 and backend2 */
	log_setup(true);
	STRUCT_SECTION_COUNT(log_backend, &cnt);
	zassert_true((cnt >= 2),
		     "There is no multi backends");

	if (IS_ENABLED(CONFIG_LOG_BACKEND_UART)) {
		bool have_uart = false;

		STRUCT_SECTION_FOREACH(log_backend, backend) {
			if (strcmp(backend->name, UART_BACKEND) == 0) {
				have_uart = true;
			}
		}
		zassert_true(have_uart, "There is no UART log backend found");
	}
}

/**
 * @brief Process all logging activities using a dedicated thread
 *
 * @addtogroup logging
 */

#ifdef CONFIG_LOG_PROCESS_THREAD
ZTEST(test_log_core_additional, test_log_thread)
{
	uint32_t slabs_free, used, max;

	TC_PRINT("Logging buffer is configured to %d bytes\n",
		 CONFIG_LOG_BUFFER_SIZE);

	TC_PRINT("Stack size of logging thread is configured by ");
	TC_PRINT("CONFIG_LOG_PROCESS_THREAD_STACK_SIZE: %d bytes\n",
		 CONFIG_LOG_PROCESS_THREAD_STACK_SIZE);

	log_setup(false);

	slabs_free = log_msg_mem_get_free();
	used = log_msg_mem_get_used();
	max = log_msg_mem_get_max_used();
	zassert_equal(used, 0);

	LOG_INF("log info to log thread");
	LOG_WRN("log warning to log thread");
	LOG_ERR("log error to log thread");

	zassert_equal(log_msg_mem_get_used(), 3);
	zassert_equal(log_msg_mem_get_free(), slabs_free - 3);
	zassert_equal(log_msg_mem_get_max_used(), max);

	TC_PRINT("after log, free: %d, used: %d, max: %d\n", slabs_free, used, max);
	/* wait 2 seconds for logging thread to handle this log message*/
	k_sleep(K_MSEC(2000));
	zassert_equal(3, backend1_cb.counter,
		      "Unexpected amount of messages received by the backend.");
	zassert_equal(log_msg_mem_get_used(), 0);
}
#else
ZTEST(test_log_core_additional, test_log_thread)
{
	ztest_test_skip();
}
#endif

static void call_log_generic(const char *fmt, ...)
{
	va_list ap;

	va_start(ap, fmt);
	log2_generic(LOG_LEVEL_INF, fmt, ap);
	va_end(ap);
}

ZTEST(test_log_core_additional, test_log_generic)
{
	char *log_msg = "log user space";
	int i = 100;

	log_setup(false);
	backend1_cb.total_logs = 4;

	call_log_generic("log generic");
	call_log_generic("log generic: %s", log_msg);
	call_log_generic("log generic %d\n", i);
	call_log_generic("log generic %d, %d\n", i, 1);
	while (log_test_process()) {
	}
}

ZTEST(test_log_core_additional, test_log_msg_create)
{
	log_setup(false);
	if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
		int mode;

		domain = 3;
		level = 2;

		z_log_msg_runtime_create(domain, __log_current_const_data,
					  level, &msg_data, 0,
					  sizeof(msg_data), NULL);
		/* try z_log_msg_static_create() */
		Z_LOG_MSG2_STACK_CREATE(0, domain, __log_current_const_data,
					level, &msg_data,
					sizeof(msg_data), NULL);

		Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), mode,
			  Z_LOG_LOCAL_DOMAIN_ID, NULL,
			  LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, test_msg_usr);

		while (log_test_process()) {
		}
	}
}

#else

ZTEST_USER(test_log_core_additional, test_log_msg_create_user)
{
	int mode;

	domain = 3;
	level = 2;

	z_log_msg_runtime_create(domain, NULL,
				  level, &msg_data, 0,
				  sizeof(msg_data), test_msg_usr);
	/* try z_log_msg_static_create() */
	Z_LOG_MSG2_STACK_CREATE(0, domain, NULL,
				level, &msg_data,
				sizeof(msg_data), test_msg_usr);

	Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), mode,
			  Z_LOG_LOCAL_DOMAIN_ID, NULL,
		  LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, test_msg_usr);

	while (log_test_process()) {
	}
}

#endif /** CONFIG_USERSPACE **/

/* The log process thread has the K_LOWEST_APPLICATION_THREAD_PRIO, adjust it
 * to a higher priority to increase the chances of being scheduled to handle
 * log message as soon as possible
 */
void promote_log_thread(const struct k_thread *thread, void *user_data)
{
	if (!(strcmp(thread->name, "logging"))) {
		k_thread_priority_set((k_tid_t)thread, -1);
	}
}

static void *test_log_core_additional_setup(void)
{
#ifdef CONFIG_LOG_PROCESS_THREAD
	k_thread_foreach(promote_log_thread, NULL);
#endif
	return NULL;
}

ZTEST_SUITE(test_log_core_additional, NULL, test_log_core_additional_setup, NULL, NULL, NULL);