zephyr/tests/subsys/logging/log_api/src/main.c

/*
 * Copyright (c) 2021 Nordic Semiconductor
 *
 * SPDX-License-Identifier: Apache-2.0
 */

#include "mock_backend.h"
#include "mock_frontend.h"
#include "test_module.h"
#include <zephyr/ztest.h>
#include <zephyr/logging/log.h>
#include <zephyr/logging/log_ctrl.h>
#include <zephyr/sys/cbprintf.h>

#ifndef CONFIG_LOG_BUFFER_SIZE
#define CONFIG_LOG_BUFFER_SIZE 4
#endif

#ifndef NO_BACKENDS
#define NO_BACKENDS 0
#endif

LOG_MODULE_REGISTER(test, CONFIG_SAMPLE_MODULE_LOG_LEVEL);

#ifdef CONFIG_LOG_USE_TAGGED_ARGUMENTS
/* The extra sizeof(int) is the end of arguments tag. */
#define LOG_SIMPLE_MSG_LEN \
	ROUND_UP(sizeof(struct log_msg) + \
		 sizeof(struct cbprintf_package_hdr_ext) + \
		 sizeof(int) + (IS_ENABLED(CONFIG_LOG_MSG_APPEND_RO_STRING_LOC) ? 1 : 0), \
		 CBPRINTF_PACKAGE_ALIGNMENT)
#else
#define LOG_SIMPLE_MSG_LEN \
	ROUND_UP(sizeof(struct log_msg) + \
		 sizeof(struct cbprintf_package_hdr_ext) + \
		 (IS_ENABLED(CONFIG_LOG_MSG_APPEND_RO_STRING_LOC) ? 1 : 0), \
		 CBPRINTF_PACKAGE_ALIGNMENT)
#endif

#ifdef CONFIG_LOG_TIMESTAMP_64BIT
#define TIMESTAMP_INIT_VAL 0x100000000
#else
#define TIMESTAMP_INIT_VAL 0
#endif

#if NO_BACKENDS
static struct log_backend backend1;
static struct log_backend backend2;
#else
MOCK_LOG_BACKEND_DEFINE(backend1, false);
MOCK_LOG_BACKEND_DEFINE(backend2, false);
#endif

static log_timestamp_t stamp;
static bool in_panic;
static int16_t test_source_id;
static int16_t test2_source_id;

static log_timestamp_t timestamp_get(void)
{
	return NO_BACKENDS ? (log_timestamp_t)UINT32_MAX : stamp++;
}

/**
 * @brief Flush logs.
 *
 * If processing thread is enabled keep sleeping until there are no pending messages
 * else process logs here.
 */
static void flush_log(void)
{
	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		while (log_data_pending()) {
			k_msleep(10);
		}
		k_msleep(100);
	} else {
		while (LOG_PROCESS()) {
		}
	}
}

static bool frontend_only(void)
{
	return NO_BACKENDS || IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY);
}

static void log_setup(bool backend2_enable)
{
	stamp = TIMESTAMP_INIT_VAL;
	zassert_false(in_panic, "Logger in panic state.");

	log_core_init();
	if (!IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		log_init();
	}

	zassert_equal(0, log_set_timestamp_func(timestamp_get, 0),
		      "Expects successful timestamp function setting.");

	mock_log_frontend_reset();

	test_source_id = log_source_id_get(STRINGIFY(test));
	test2_source_id = log_source_id_get(STRINGIFY(test2));

	if (frontend_only()) {
		return;
	}

	mock_log_backend_reset(&backend1);
	mock_log_backend_reset(&backend2);

	log_backend_enable(&backend1, backend1.cb->ctx, LOG_LEVEL_DBG);

	if (backend2_enable) {
		log_backend_enable(&backend2, backend2.cb->ctx, LOG_LEVEL_DBG);
	} else {
		log_backend_disable(&backend2);
	}

}

/**
 * @brief Process and validate that backends got expected content.
 *
 * @param backend2_enable If true backend2 is also validated.
 * @param panic True means that logging is in panic mode, flushing is skipped.
 */
static void process_and_validate(bool backend2_enable, bool panic)
{
	if (!panic) {
		flush_log();
	}

	mock_log_frontend_validate(panic);

	if (NO_BACKENDS) {
		int cnt;

		STRUCT_SECTION_COUNT(log_backend, &cnt);
		zassert_equal(cnt, 0);
		return;
	}

	if (IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY)) {
		return;
	}

	mock_log_backend_validate(&backend1, panic);

	if (backend2_enable) {
		mock_log_backend_validate(&backend2, panic);
	}
}

static bool dbg_enabled(void)
{
	return IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG) || (CONFIG_LOG_OVERRIDE_LEVEL == 4);
}

ZTEST(test_log_api, test_log_various_messages)
{
	char str[128];
	char dstr[] = "abcd";
	int8_t i = -5;
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	unsigned long long ull = 0x1122334455667799;
	long long ll = -12313213214454545;

#define TEST_MSG_0 "%lld %llu %hhd"
#define TEST_MSG_0_PREFIX "%s: %lld %llu %hhd"
#define TEST_MSG_1 "%f %d %f"

	if (dbg_enabled()) {
		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 TEST_MSG_0_PREFIX, __func__, ll, ull, i);
		} else {
			snprintk(str, sizeof(str), TEST_MSG_0, ll, ull, i);
		}

		mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
		mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
					exp_timestamp++, str);
	}

	LOG_DBG(TEST_MSG_0, ll, ull, i);

#ifdef CONFIG_FPU
	float f = -1.2356f;
	double d = -1.2356;

	snprintk(str, sizeof(str), TEST_MSG_1, (double)f, 100,  d);
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, str);
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
				exp_timestamp++, str);

	LOG_INF(TEST_MSG_1, (double)f, 100, d);
#endif /* CONFIG_FPU */

	snprintk(str, sizeof(str), "wrn %s", dstr);
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, str);
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
				exp_timestamp++, str);

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_ERR, "err");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
				exp_timestamp++, "err");

	LOG_WRN("wrn %s", dstr);
	dstr[0] = '\0';

	LOG_ERR("err");

	process_and_validate(false, false);

#undef TEST_MSG_0
#undef TEST_MSG_0_PREFIX
#undef TEST_MSG_1
}

/*
 * Test is using 2 backends and runtime filtering is enabled. After first call
 * filtering for backend2 is reduced to warning. It is expected that next INFO
 * level log message will be passed only to backend1.
 */
ZTEST(test_log_api, test_log_backend_runtime_filtering)
{
	uint16_t s_id = LOG_CURRENT_MODULE_ID();
	uint8_t d_id = Z_LOG_LOCAL_DOMAIN_ID;
	log_timestamp_t exp_ts = TIMESTAMP_INIT_VAL;

	if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
		ztest_test_skip();
	}

	log_setup(true);

	if (dbg_enabled()) {
		char str[128];

		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 "%s: test", __func__);
		} else {
			snprintk(str, sizeof(str), "test");
		}

		mock_log_frontend_record(s_id, LOG_LEVEL_DBG, str);
		if (!frontend_only()) {
			mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_DBG, exp_ts, str);
			mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_DBG, exp_ts, str);
		}
		exp_ts++;
	}

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
	if (!frontend_only()) {
		mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_INF, exp_ts, "test");
		mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_INF, exp_ts, "test");
	}
	exp_ts++;

	LOG_DBG("test");
	LOG_INF("test");

	process_and_validate(true, false);

	uint32_t exp_level1 = dbg_enabled() ? LOG_LEVEL_DBG : LOG_LEVEL_INF;
	uint32_t exp_level2 = LOG_LEVEL_WRN;

	uint32_t b_level;
	uint32_t f_level;

	/* Validate levels before changing for backend2 and frontend */
	if (!frontend_only()) {
		b_level = log_filter_get(&backend1, d_id, s_id, true);
		zassert_equal(b_level, exp_level1);

		b_level = log_filter_get(&backend2, d_id, s_id, true);
		zassert_equal(b_level, exp_level1);
	}

	if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
		f_level = log_frontend_filter_get(s_id, true);
		zassert_equal(f_level, exp_level1);

		log_frontend_filter_set(s_id, LOG_LEVEL_WRN);

		f_level = log_frontend_filter_get(s_id, true);
		zassert_equal(f_level, exp_level2);
	}

	if (!frontend_only()) {
		log_filter_set(&backend2, d_id, s_id, LOG_LEVEL_WRN);

		b_level = log_filter_get(&backend1, d_id, s_id, true);
		zassert_equal(b_level, exp_level1);

		b_level = log_filter_get(&backend2, d_id, s_id, true);
		zassert_equal(b_level, exp_level2);
	}

	uint8_t data[] = {1, 2, 4, 5, 6, 8};

	if (!frontend_only()) {
		/* INF logs expected only on backend1 */
		mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_INF, exp_ts++, "test");

		mock_log_backend_generic_record(&backend1, s_id, d_id, LOG_LEVEL_INF,
						exp_ts++, "hexdump", data, sizeof(data));
	}

	/* WRN message expected on backends and frontend */
	mock_log_frontend_record(s_id, LOG_LEVEL_WRN, "test2");
	if (!frontend_only()) {
		mock_log_backend_record(&backend1, s_id, d_id, LOG_LEVEL_WRN, exp_ts, "test2");
		mock_log_backend_record(&backend2, s_id, d_id, LOG_LEVEL_WRN, exp_ts++, "test2");
	}

	mock_log_frontend_generic_record(s_id, d_id, LOG_LEVEL_WRN, "hexdump", data, sizeof(data));
	if (!frontend_only()) {
		mock_log_backend_generic_record(&backend1, s_id, d_id, LOG_LEVEL_WRN,
						exp_ts, "hexdump", data, sizeof(data));
		mock_log_backend_generic_record(&backend2, s_id, d_id, LOG_LEVEL_WRN,
						exp_ts++, "hexdump", data, sizeof(data));
	}

	LOG_INF("test");
	LOG_HEXDUMP_INF(data, sizeof(data), "hexdump");
	LOG_WRN("test2");
	LOG_HEXDUMP_WRN(data, sizeof(data), "hexdump");

	process_and_validate(true, false);
}

static size_t get_max_hexdump(void)
{
	return CONFIG_LOG_BUFFER_SIZE - sizeof(struct log_msg_hdr);
}

#if defined(CONFIG_ARCH_POSIX)
#define STR_SIZE(s) (strlen(s) + 2 * sizeof(char))
#else
#define STR_SIZE(s) 0
#endif

static size_t get_long_hexdump(void)
{
	size_t extra_msg_sz = 0;
	size_t extra_hexdump_sz = 0;

	if (IS_ENABLED(CONFIG_LOG_USE_TAGGED_ARGUMENTS)) {
		/* First message with 2 arguments => 2 tags */
		extra_msg_sz = 2 * sizeof(int);

		/*
		 * Hexdump with an implicit "%s" and the "hexdump" string
		 * as argument => 1 tag.
		 */
		extra_hexdump_sz = sizeof(int);
	}
	if (IS_ENABLED(CONFIG_TEST_LOG_MSG_APPEND_RO_STRING_LOC)) {
		extra_msg_sz += sizeof(uint8_t); /* Location of format string. */
	}

	return CONFIG_LOG_BUFFER_SIZE -
		/* First message */
		ROUND_UP(LOG_SIMPLE_MSG_LEN + 2 * sizeof(int) + extra_msg_sz,
			 CBPRINTF_PACKAGE_ALIGNMENT) -
		/* Hexdump message excluding data */
		ROUND_UP(LOG_SIMPLE_MSG_LEN + STR_SIZE("hexdump") + extra_hexdump_sz,
			 CBPRINTF_PACKAGE_ALIGNMENT);
}

/*
 * When LOG_MODE_OVERFLOW is enabled, logger should discard oldest messages when
 * there is no room. However, if after discarding all messages there is still no
 * room then current log is discarded.
 */
static uint8_t log_buf[CONFIG_LOG_BUFFER_SIZE];

ZTEST(test_log_api, test_log_overflow)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		ztest_test_skip();
	}

	if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
		ztest_test_skip();
	}

	for (int i = 0; i < CONFIG_LOG_BUFFER_SIZE; i++) {
		log_buf[i] = i;
	}

	uint32_t hexdump_len = get_long_hexdump();

	/* expect first message to be dropped */
	exp_timestamp++;
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test 100 100");
	mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
					 LOG_LEVEL_INF, "hexdump", log_buf, hexdump_len);
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test2");
	mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
					exp_timestamp++, "hexdump",
					log_buf, hexdump_len);
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
				exp_timestamp++, "test2");
	mock_log_backend_drop_record(&backend1, 1);

	LOG_INF("test %d %d", 100, 100);
	LOG_HEXDUMP_INF(log_buf, hexdump_len, "hexdump");
	LOG_INF("test2");

	process_and_validate(false, false);

	log_setup(false);

	exp_timestamp = TIMESTAMP_INIT_VAL;
	hexdump_len = get_max_hexdump();
	mock_log_backend_reset(&backend1);
	mock_log_frontend_reset();

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "test");
	mock_log_frontend_generic_record(LOG_CURRENT_MODULE_ID(), Z_LOG_LOCAL_DOMAIN_ID,
					 LOG_LEVEL_INF, "test", log_buf, hexdump_len + 1);
	/* Log2 allocation is not destructive if request exceeds the
	 * capacity.
	 */
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
				exp_timestamp, "test");
	mock_log_backend_drop_record(&backend1, 1);

	LOG_INF("test");
	LOG_HEXDUMP_INF(log_buf, hexdump_len + 1, "test");

	process_and_validate(false, false);

}

/*
 * Test checks if arguments are correctly processed by the logger.
 *
 * Log messages with supported number of messages are called. Test backend and
 * frontend validate number of arguments and values.
 */
#define MOCK_LOG_FRONT_BACKEND_RECORD(str) do { \
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(), \
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF, \
				exp_timestamp++, str); \
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, str); \
} while (0)

ZTEST(test_log_api, test_log_arguments)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	MOCK_LOG_FRONT_BACKEND_RECORD("test");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5");

	LOG_INF("test");
	LOG_INF("test %d %d %d", 1, 2, 3);
	LOG_INF("test %d %d %d %d", 1, 2, 3, 4);
	LOG_INF("test %d %d %d %d %d", 1, 2, 3, 4, 5);

	process_and_validate(false, false);

	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9");

	LOG_INF("test %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6);
	LOG_INF("test %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7);
	LOG_INF("test %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8);
	LOG_INF("test %d %d %d %d %d %d %d %d %d", 1, 2, 3, 4, 5, 6, 7, 8, 9);

	process_and_validate(false, false);

	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11");

	LOG_INF("test %d %d %d %d %d %d %d %d %d %d",
		1, 2, 3, 4, 5, 6, 7, 8, 9, 10);
	LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d",
		1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11);

	process_and_validate(false, false);

	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12");
	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13");

	LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d",
		1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12);

	LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d",
		1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13);

	process_and_validate(false, false);

	MOCK_LOG_FRONT_BACKEND_RECORD("test 1 2 3 4 5 6 7 8 9 10 11 12 13 14");
	LOG_INF("test %d %d %d %d %d %d %d %d %d %d %d %d %d %d",
		1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14);

	process_and_validate(false, false);
}

/* Function comes from the file which is part of test module. It is
 * expected that logs coming from it will have same source_id as current
 * module (this file).
 */
ZTEST(test_log_api, test_log_from_declared_module)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	/* See test module for log message content. */
	if (dbg_enabled()) {
		char str[128];

		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 "%s: " TEST_DBG_MSG, "test_func");
		} else {
			snprintk(str, sizeof(str), TEST_DBG_MSG);
		}

		mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
		mock_log_backend_record(&backend1, test_source_id,
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
					exp_timestamp++, str);
	}

	mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
	mock_log_backend_record(&backend1, test_source_id,
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
				exp_timestamp++, TEST_ERR_MSG);

	test_func();

	if (dbg_enabled()) {
		char str[128];

		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 "%s: " TEST_INLINE_DBG_MSG, "test_inline_func");
		} else {
			snprintk(str, sizeof(str), TEST_INLINE_DBG_MSG);
		}

		mock_log_frontend_record(test_source_id, LOG_LEVEL_DBG, str);
		mock_log_backend_record(&backend1, test_source_id,
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
					exp_timestamp++, str);
	}

	mock_log_frontend_record(test_source_id, LOG_LEVEL_ERR, TEST_INLINE_ERR_MSG);
	mock_log_backend_record(&backend1, test_source_id,
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
				exp_timestamp, TEST_INLINE_ERR_MSG);

	test_inline_func();

	process_and_validate(false, false);

}

/** Calculate how many messages will fit in the buffer. Also calculate if
 * remaining free space is size of message or not. This impacts how many messages
 * are dropped. If free space is equal to message size then when buffer is full,
 * adding new message will lead to one message drop, otherwise 2 message will
 * be dropped.
 */
static size_t get_short_msg_capacity(void)
{
	return CONFIG_LOG_BUFFER_SIZE / LOG_SIMPLE_MSG_LEN;
}

static void log_n_messages(uint32_t n_msg, uint32_t exp_dropped)
{
	printk("ex dropped:%d\n", exp_dropped);
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	stamp = TIMESTAMP_INIT_VAL;

	for (uint32_t i = 0; i < n_msg; i++) {
		mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "dummy");
		if (i >= exp_dropped) {
			mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
				exp_timestamp, "dummy");
		}
		exp_timestamp++;
		LOG_INF("dummy");
	}

	mock_log_backend_drop_record(&backend1, exp_dropped);

	process_and_validate(false, false);
	mock_log_backend_reset(&backend1);
}

/*
 * Test checks if backend receives notification about dropped messages. It
 * first blocks threads to ensure full control of log processing time and
 * then logs certain log messages, expecting dropped notification.
 *
 * With multiple cpus you may not get consistent message dropping
 * as other core may process logs. Executing on 1 cpu only.
 */
ZTEST(test_log_api_1cpu, test_log_msg_dropped_notification)
{
	log_setup(false);

	if (IS_ENABLED(CONFIG_SMP)) {
		/* With smp you may not get consistent message dropping as other
		 * core may process logs.
		 */
		ztest_test_skip();
	}

	if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
		ztest_test_skip();
	}

	if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
		ztest_test_skip();
	}

	uint32_t capacity = get_short_msg_capacity();

	log_n_messages(capacity, 0);

	/* Expect messages dropped when logger more than buffer capacity. */
	log_n_messages(capacity + 1, 1);
	log_n_messages(capacity + 2, 2);
}

/* Test checks if panic is correctly executed. On panic logger should flush all
 * messages and process logs in place (not in deferred way).
 */
ZTEST(test_log_api, test_log_panic)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
				exp_timestamp++, "test");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
				exp_timestamp++, "test");
	LOG_WRN("test");
	LOG_WRN("test");

	/* logs should be flushed in panic */
	log_panic();

	process_and_validate(false, true);

	/* messages processed where called */
	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "test");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
				exp_timestamp++, "test");
	LOG_WRN("test");

	process_and_validate(false, true);
}

ZTEST(test_log_api, test_log_printk)
{
	if (!IS_ENABLED(CONFIG_LOG_PRINTK)) {
		ztest_test_skip();
	}

	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	mock_log_backend_record(&backend1, 0,
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
				exp_timestamp++, "test 100");
	printk("test %d", 100);

	log_panic();

	mock_log_backend_record(&backend1, 0,
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INTERNAL_RAW_STRING,
				exp_timestamp++, "test 101");
	printk("test %d", 101);

	process_and_validate(false, true);
}

ZTEST(test_log_api, test_log_printk_vs_raw)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	mock_log_frontend_record(0, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
	mock_log_backend_record(&backend1, 0,
				0, LOG_LEVEL_INTERNAL_RAW_STRING,
				exp_timestamp++, "test 100\n");
	LOG_PRINTK("test %d\n", 100);


	mock_log_frontend_record(1, LOG_LEVEL_INTERNAL_RAW_STRING, "test 100\n");
	mock_log_backend_record(&backend1, 1,
				0, LOG_LEVEL_INTERNAL_RAW_STRING,
				exp_timestamp++, "test 100\n");
	LOG_RAW("test %d\n", 100);


	process_and_validate(false, false);
}

ZTEST(test_log_api, test_log_arg_evaluation)
{
	char str[128];
#define TEST_MSG_0 "%u %u"
#define TEST_MSG_0_PREFIX "%s: %u %u"
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
	uint32_t cnt0 = 0;
	uint32_t cnt1 = 0;
	uint32_t exp0 = 1;
	uint32_t exp1 = 1;

	log_setup(false);

	if (dbg_enabled()) {
		/* Debug message arguments are only evaluated when this level
		 * is enabled.
		 */
		exp0++;
		exp1++;
	}

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_INF, "0 0");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_INF,
				exp_timestamp++, "0 0");
	if (dbg_enabled()) {
		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 TEST_MSG_0_PREFIX, __func__, 1, 1);
		} else {
			snprintk(str, sizeof(str), TEST_MSG_0, 1, 1);
		}
		mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_DBG, str);
		mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
					exp_timestamp++, str);
	}
	/* Arguments used for logging shall be evaluated only once. They should
	 * be evaluated also when given log level is disabled.
	 */
	LOG_INF("%u %u", cnt0++, cnt1++);
	LOG_DBG("%u %u", cnt0++, cnt1++);

	zassert_equal(cnt0, exp0, "Got:%u, Expected:%u", cnt0, exp0);
	zassert_equal(cnt1, exp1, "Got:%u, Expected:%u", cnt1, exp1);

	process_and_validate(false, false);
#undef TEST_MSG_0
#undef TEST_MSG_0_PREFIX
}

static void log_wrn_once_run(int i)
{
	LOG_WRN_ONCE("once %d", i);
}

ZTEST(test_log_api, test_log_wrn_once)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	mock_log_frontend_record(LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN, "once 0");
	mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
				Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_WRN,
				exp_timestamp++, "once 0");

	log_wrn_once_run(0);
	log_wrn_once_run(1);
	log_wrn_once_run(2);

	process_and_validate(false, false);
}

ZTEST(test_log_api, test_log_override_level)
{
	log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;

	log_setup(false);

	if (CONFIG_LOG_OVERRIDE_LEVEL == 4) {
		char str[128];

		/* If prefix is enabled, add function name prefix */
		if (IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_DBG)) {
			snprintk(str, sizeof(str),
				 "%s: " TEST_DBG_MSG, "test_func");
		} else {
			snprintk(str, sizeof(str), TEST_DBG_MSG);
		}

		mock_log_frontend_record(test2_source_id, LOG_LEVEL_DBG, str);
		mock_log_backend_record(&backend1, test2_source_id,
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_DBG,
					exp_timestamp++, str);

		mock_log_frontend_record(test2_source_id, LOG_LEVEL_ERR, TEST_ERR_MSG);
		mock_log_backend_record(&backend1, test2_source_id,
					Z_LOG_LOCAL_DOMAIN_ID, LOG_LEVEL_ERR,
					exp_timestamp++, TEST_ERR_MSG);
	} else if (CONFIG_LOG_OVERRIDE_LEVEL != 0) {
		zassert_true(false, "Unexpected configuration.");
	}

	test_func2();

	process_and_validate(false, false);
}

/* Disable backends because same suite may be executed again but compiled by C++ */
static void log_api_suite_teardown(void *data)
{
	ARG_UNUSED(data);

	if (NO_BACKENDS) {
		return;
	}

	log_backend_disable(&backend1);
	log_backend_disable(&backend2);
}

static void *log_api_suite_setup(void)
{
	PRINT("Configuration:\n");
	PRINT("\t Mode: %s\n",
	      IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY) ? "Frontend only" :
	      (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? "Immediate" : "Deferred"));
	PRINT("\t Frontend: %s\n",
	      IS_ENABLED(CONFIG_LOG_FRONTEND) ? "Yes" : "No");
	PRINT("\t Runtime filtering: %s\n",
	      IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? "yes" : "no");
	PRINT("\t Overwrite: %s\n",
	      IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ? "yes" : "no");
	if (NO_BACKENDS) {
		PRINT("\t No backends\n");
	}
#if __cplusplus
	PRINT("\t C++: yes\n");
#endif
	flush_log();

	return NULL;
}

static void log_api_suite_before(void *data)
{
	ARG_UNUSED(data);

	if (NO_BACKENDS) {
		return;
	}

	/* Flush logs and enable test backends. */
	flush_log();

	if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
		mock_log_frontend_check_enable();
	}
	mock_log_backend_check_enable(&backend1);
	mock_log_backend_check_enable(&backend2);
}

static void log_api_suite_before_1cpu(void *data)
{
	ztest_simple_1cpu_before(data);
	log_api_suite_before(data);
}

static void log_api_suite_after(void *data)
{
	ARG_UNUSED(data);
	if (NO_BACKENDS) {
		return;
	}

	/* Disable testing backends after the test. Otherwise test may fail due
	 * to unexpected log message.
	 */
	if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
		mock_log_frontend_check_disable();
	}
	mock_log_backend_check_disable(&backend1);
	mock_log_backend_check_disable(&backend2);
}

static void log_api_suite_after_1cpu(void *data)
{
	log_api_suite_after(data);
	ztest_simple_1cpu_after(data);
}

ZTEST_SUITE(test_log_api, NULL, log_api_suite_setup,
	    log_api_suite_before, log_api_suite_after, log_api_suite_teardown);

/* Suite dedicated for tests that need to run on 1 cpu only. */
ZTEST_SUITE(test_log_api_1cpu, NULL, log_api_suite_setup,
	    log_api_suite_before_1cpu, log_api_suite_after_1cpu, log_api_suite_teardown);