michaelh/zephyr
1
0
Fork 0
Code Releases Activity

tests: logging: Add log_api test suite

Browse source 
Add test suite which validates logging behavior in various
configurations.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruscinski 2021-04-26 14:24:35 +02:00 • committed by Carles Cufí
commit ef856385e7
11 changed files with 1370 additions and 0 deletions
Download patch file Download diff file Expand all files Collapse all files

7
tests/subsys/logging/log_api/CMakeLists.txt Normal file
View file

@ -0,0 +1,7 @@
# SPDX-License-Identifier: Apache-2.0
cmake_minimum_required(VERSION 3.13.1)
find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
project(log_core)
target_sources(app PRIVATE src/main.c src/maincxx.cxx src/mock_backend.c src/test_module.c)

8
tests/subsys/logging/log_api/Kconfig Normal file
View file

@ -0,0 +1,8 @@
# Copyright (c) 2021 Nordic Semiconductor ASA
# SPDX-License-Identifier: Apache-2.0
module = SAMPLE_MODULE
module-str = Test logging API
source "subsys/logging/Kconfig.template.log_config"
source "Kconfig.zephyr"

17
tests/subsys/logging/log_api/prj.conf Normal file
View file

@ -0,0 +1,17 @@
CONFIG_MAIN_THREAD_PRIORITY=5
CONFIG_ZTEST=y
CONFIG_TEST_USERSPACE=y
CONFIG_TEST_LOGGING_DEFAULTS=n
CONFIG_LOG=y
CONFIG_LOG_PRINTK=n
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_BUFFER_SIZE=768
CONFIG_LOG_STRDUP_BUF_COUNT=1
CONFIG_LOG_STRDUP_MAX_STRING=8
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=n
CONFIG_ASSERT=y
CONFIG_LOG_STRDUP_POOL_PROFILING=y

20
tests/subsys/logging/log_api/src/main.c Normal file
View file

@ -0,0 +1,20 @@
/*
* Copyright (c) 2019 Oticon A/S
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <ztest.h>
#include <sys/util.h>
#include <string.h>
#include "test.inc"
void test_cxx(void);
void test_cc(void);
void test_main(void)
{
test_cc();
test_cxx();
}

11
tests/subsys/logging/log_api/src/maincxx.cxx Normal file
View file

@ -0,0 +1,11 @@
/*
* Copyright (c) 2019 Oticon A/S
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <ztest.h>
#include <sys/util.h>
#include <string.h>
#include "test.inc"

386
tests/subsys/logging/log_api/src/mock_backend.c Normal file
View file

@ -0,0 +1,386 @@
/*
* Copyright (c) 2021 Nordic Semiconductor
*
* SPDX-License-Identifier: Apache-2.0
*/
#include "mock_backend.h"
#include <ztest.h>
#include <logging/log_core.h>
void mock_log_backend_reset(const struct log_backend *backend)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->msg_rec_idx = 0;
mock->msg_proc_idx = 0;
mock->do_check = true;
mock->exp_drop_cnt = 0;
mock->drop_cnt = 0;
mock->panic = false;
}
void mock_log_backend_check_enable(const struct log_backend *backend)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->do_check = true;
}
void mock_log_backend_check_disable(const struct log_backend *backend)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->do_check = false;
}
void mock_log_backend_dummy_record(const struct log_backend *backend, int cnt)
{
struct mock_log_backend *mock = backend->cb->ctx;
for (int i = 0; i < cnt; i++) {
mock->exp_msgs[mock->msg_rec_idx + i].check = false;
}
mock->msg_rec_idx += cnt;
}
void mock_log_backend_drop_record(const struct log_backend *backend, int cnt)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->exp_drop_cnt = cnt;
}
void mock_log_backend_generic_record(const struct log_backend *backend,
uint16_t source_id,
uint16_t domain_id,
uint8_t level,
log_timestamp_t timestamp,
const char *str,
uint8_t *data,
uint32_t data_len)
{
struct mock_log_backend *mock = backend->cb->ctx;
struct mock_log_backend_msg *exp = &mock->exp_msgs[mock->msg_rec_idx];
exp->check = true;
exp->timestamp = timestamp;
exp->source_id = source_id;
exp->domain_id = domain_id;
exp->level = level;
int len = strlen(str);
__ASSERT_NO_MSG(len < sizeof(exp->str));
memcpy(exp->str, str, len);
exp->str[len] = 0;
if (data_len <= sizeof(exp->data)) {
memcpy(exp->data, data, data_len);
}
exp->data_len = data_len;
mock->msg_rec_idx++;
}
void mock_log_backend_validate(const struct log_backend *backend, bool panic)
{
struct mock_log_backend *mock = backend->cb->ctx;
zassert_equal(mock->exp_drop_cnt, mock->drop_cnt,
"Got: %u, Expected: %u", mock->drop_cnt, mock->exp_drop_cnt);
zassert_equal(mock->msg_rec_idx, mock->msg_proc_idx, NULL);
zassert_equal(mock->panic, panic, NULL);
}
static void fmt_cmp(struct log_msg *msg, char *exp_str)
{
char str[128];
const char *fmt = msg->str;
uint32_t nargs = log_msg_nargs_get(msg);
log_arg_t *args = alloca(sizeof(log_arg_t)*nargs);
for (int i = 0; i < nargs; i++) {
args[i] = log_msg_arg_get(msg, i);
}
switch (log_msg_nargs_get(msg)) {
case 0:
snprintk(str, sizeof(str), fmt, NULL);
break;
case 1:
snprintk(str, sizeof(str), fmt, args[0]);
break;
case 2:
snprintk(str, sizeof(str), fmt, args[0], args[1]);
break;
case 3:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2]);
break;
case 4:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3]);
break;
case 5:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4]);
break;
case 6:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5]);
break;
case 7:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6]);
break;
case 8:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7]);
break;
case 9:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8]);
break;
case 10:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9]);
break;
case 11:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9], args[10]);
break;
case 12:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9], args[10], args[11]);
break;
case 13:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9], args[10], args[11], args[12]);
break;
case 14:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9], args[10], args[11], args[12],
args[13]);
break;
case 15:
snprintk(str, sizeof(str), fmt, args[0], args[1], args[2],
args[3], args[4], args[5], args[6], args[7],
args[8], args[9], args[10], args[11], args[12],
args[13], args[14]);
break;
default:
/* Unsupported number of arguments. */
__ASSERT_NO_MSG(true);
break;
}
zassert_equal(0, strcmp(str, exp_str), NULL);
}
static void hexdump_cmp(struct log_msg *msg, uint8_t *exp_data,
uint32_t exp_len, bool skip_data_check)
{
uint32_t len = msg->hdr.params.hexdump.length;
size_t offset = 0;
size_t l;
zassert_equal(len, exp_len, "Got: %u, expected: %u", len, exp_len);
if (skip_data_check) {
return;
}
do {
uint8_t d;
l = 1;
log_msg_hexdump_data_get(msg, &d, &l, offset);
if (l) {
zassert_equal(d, exp_data[offset],
"Got:%02x, Expected:%02x", d, exp_data[offset]);
}
offset += l;
} while (l > 0);
zassert_equal(offset, exp_len, NULL);
}
static void put(const struct log_backend *const backend,
struct log_msg *msg)
{
struct mock_log_backend *mock = backend->cb->ctx;
struct mock_log_backend_msg *exp = &mock->exp_msgs[mock->msg_proc_idx];
mock->msg_proc_idx++;
if (!exp->check) {
return;
}
zassert_equal(msg->hdr.timestamp, exp->timestamp,
"Got: %u, expected: %u", msg->hdr.timestamp, exp->timestamp);
zassert_equal(msg->hdr.ids.level, exp->level, NULL);
zassert_equal(msg->hdr.ids.source_id, exp->source_id, NULL);
zassert_equal(msg->hdr.ids.domain_id, exp->domain_id, NULL);
if (msg->hdr.params.generic.type == LOG_MSG_TYPE_STD) {
zassert_equal(exp->data_len, 0, NULL);
fmt_cmp(msg, exp->str);
} else {
zassert_equal(0, strcmp(msg->str, exp->str), NULL);
hexdump_cmp(msg, exp->data, exp->data_len,
exp->data_len > sizeof(exp->data));
}
}
struct test_str {
char *str;
int cnt;
};
static int out(int c, void *ctx)
{
struct test_str *s = ctx;
s->str[s->cnt++] = (char)c;
return c;
}
static void process(const struct log_backend *const backend,
union log_msg2_generic *msg)
{
struct mock_log_backend *mock = backend->cb->ctx;
struct mock_log_backend_msg *exp = &mock->exp_msgs[mock->msg_proc_idx];
mock->msg_proc_idx++;
if (!exp->check) {
return;
}
zassert_equal(msg->log.hdr.timestamp, exp->timestamp,
"Got: %u, expected: %u",
msg->log.hdr.timestamp, exp->timestamp);
zassert_equal(msg->log.hdr.desc.level, exp->level, NULL);
zassert_equal(msg->log.hdr.desc.domain, exp->domain_id, NULL);
uint32_t source_id = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ?
log_dynamic_source_id((struct log_source_dynamic_data *)msg->log.hdr.source) :
log_const_source_id((const struct log_source_const_data *)msg->log.hdr.source);
zassert_equal(source_id, exp->source_id, NULL);
size_t len;
uint8_t *data;
data = log_msg2_get_data(&msg->log, &len);
zassert_equal(exp->data_len, len, NULL);
if (exp->data_len <= sizeof(exp->data)) {
zassert_equal(memcmp(data, exp->data, len), 0, NULL);
}
char str[128];
struct test_str s = { .str = str };
data = log_msg2_get_package(&msg->log, &len);
len = cbpprintf(out, &s, data);
str[len] = '\0';
zassert_equal(strcmp(str, exp->str), 0, "Got \"%s\", Expected:\"%s\"",
str, exp->str);
}
static void mock_init(struct log_backend const *const backend)
{
}
static void panic(struct log_backend const *const backend)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->panic = true;
}
static void dropped(const struct log_backend *const backend, uint32_t cnt)
{
struct mock_log_backend *mock = backend->cb->ctx;
mock->drop_cnt += cnt;
}
static void sync_string(const struct log_backend *const backend,
struct log_msg_ids src_level, uint32_t timestamp,
const char *fmt, va_list ap)
{
struct mock_log_backend *mock = backend->cb->ctx;
struct mock_log_backend_msg *exp = &mock->exp_msgs[mock->msg_proc_idx];
mock->msg_proc_idx++;
if (!exp->check) {
return;
}
zassert_equal(timestamp, exp->timestamp,
"Got: %u, expected: %u", timestamp, exp->timestamp);
zassert_equal(src_level.level, exp->level, NULL);
zassert_equal(src_level.source_id, exp->source_id, NULL);
zassert_equal(src_level.domain_id, exp->domain_id, NULL);
zassert_equal(exp->data_len, 0, NULL);
char str[128];
vsnprintk(str, sizeof(str), fmt, ap);
zassert_equal(0, strcmp(str, exp->str), NULL);
}
static void sync_hexdump(const struct log_backend *const backend,
struct log_msg_ids src_level, uint32_t timestamp,
const char *metadata, const uint8_t *data, uint32_t length)
{
struct mock_log_backend *mock = backend->cb->ctx;
struct mock_log_backend_msg *exp = &mock->exp_msgs[mock->msg_proc_idx];
mock->msg_proc_idx++;
if (!exp->check) {
return;
}
zassert_equal(timestamp, exp->timestamp,
"Got: %u, expected: %u", timestamp, exp->timestamp);
zassert_equal(src_level.level, exp->level, NULL);
zassert_equal(src_level.source_id, exp->source_id, NULL);
zassert_equal(src_level.domain_id, exp->domain_id, NULL);
zassert_equal(0, strcmp(metadata, exp->str), NULL);
zassert_equal(length, exp->data_len, NULL);
if (length > sizeof(exp->data)) {
zassert_equal(memcmp(data, exp->data, length), 0, NULL);
}
}
const struct log_backend_api mock_log_backend_api = {
.process = IS_ENABLED(CONFIG_LOG2) ? process : NULL,
.put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL,
.put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ?
sync_string : NULL,
.put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ?
sync_hexdump : NULL,
.panic = panic,
.init = mock_init,
.dropped = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : dropped,
};

78
tests/subsys/logging/log_api/src/mock_backend.h Normal file
View file

@ -0,0 +1,78 @@
/*
* Copyright (c) 2021 Nordic Semiconductor
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef SRC_MOCK_BACKEND_H__
#define SRC_MOCK_BACKEND_H__
#include <logging/log_backend.h>
#ifdef __cplusplus
extern "C" {
#endif
extern const struct log_backend_api mock_log_backend_api;
struct mock_log_backend_msg {
log_timestamp_t timestamp;
uint16_t source_id;
uint16_t domain_id;
uint8_t level;
bool check;
char str[128];
uint8_t data[32];
uint32_t data_len;
};
struct mock_log_backend {
bool do_check;
bool panic;
struct mock_log_backend_msg exp_msgs[64];
int msg_rec_idx;
int msg_proc_idx;
int exp_drop_cnt;
int drop_cnt;
};
void mock_log_backend_reset(const struct log_backend *backend);
void mock_log_backend_check_enable(const struct log_backend *backend);
void mock_log_backend_check_disable(const struct log_backend *backend);
void mock_log_backend_dummy_record(const struct log_backend *backend, int cnt);
void mock_log_backend_drop_record(const struct log_backend *backend, int cnt);
void mock_log_backend_generic_record(const struct log_backend *backend,
uint16_t source_id,
uint16_t domain_id,
uint8_t level,
log_timestamp_t timestamp,
const char *str,
uint8_t *data,
uint32_t data_len);
static inline void mock_log_backend_record(const struct log_backend *backend,
uint16_t source_id,
uint16_t domain_id,
uint8_t level,
log_timestamp_t timestamp,
const char *str)
{
mock_log_backend_generic_record(backend, source_id, domain_id, level,
timestamp, str, NULL, 0);
}
void mock_log_backend_validate(const struct log_backend *backend, bool panic);
#define MOCK_LOG_BACKEND_DEFINE(name, autostart) \
static struct mock_log_backend name##_mock; \
LOG_BACKEND_DEFINE(name, mock_log_backend_api, autostart, &name##_mock)
#ifdef __cplusplus
}
#endif
#endif /* SRC_MOCK_BACKEND_H__ */

634
tests/subsys/logging/log_api/src/test.inc Normal file
View file

@ -0,0 +1,634 @@
/*
* Copyright (c) 2021 Nordic Semiconductor
*
* SPDX-License-Identifier: Apache-2.0
*/
#include "mock_backend.h"
#include "test_module.h"
#include <ztest.h>
#include <logging/log.h>
#include <logging/log_ctrl.h>
#ifndef CONFIG_LOG_BUFFER_SIZE
#define CONFIG_LOG_BUFFER_SIZE 0
#endif
#define MODULE_NAME test
#define CXX_MODULE_NAME test_cxx
#if __cplusplus
LOG_MODULE_REGISTER(CXX_MODULE_NAME, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
#else
LOG_MODULE_REGISTER(MODULE_NAME, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
#endif
#define LOG2_SIMPLE_MSG_LEN \
ROUND_UP(sizeof(struct log_msg2_hdr) + 2 * sizeof(void *), sizeof(long long))
#ifdef CONFIG_LOG_TIMESTAMP_64BIT
#define TIMESTAMP_INIT_VAL 0x100000000
#else
#define TIMESTAMP_INIT_VAL 0
#endif
MOCK_LOG_BACKEND_DEFINE(backend1, true);
MOCK_LOG_BACKEND_DEFINE(backend2, false);
static log_timestamp_t stamp;
static bool in_panic;
static int16_t test_source_id;
static int16_t test_cxx_source_id;
static log_timestamp_t timestamp_get(void)
{
return stamp++;
}
/**
* @brief Function for finding source ID based on source name.
*
* @param name Source name
*
* @return Source ID.
*/
static int16_t log_source_id_get(const char *name)
{
int16_t count = (int16_t)log_src_cnt_get(CONFIG_LOG_DOMAIN_ID);
for (int16_t i = 0; i < count; i++) {
if (strcmp(log_source_name_get(CONFIG_LOG_DOMAIN_ID, i), name)
== 0) {
return i;
}
}
return -1;
}
static void log_setup(bool backend2_enable)
{
stamp = TIMESTAMP_INIT_VAL;
zassert_false(in_panic, "Logger in panic state.");
log_core_init();
log_init();
zassert_equal(0, log_set_timestamp_func(timestamp_get, 0),
"Expects successful timestamp function setting.");
mock_log_backend_reset(&backend1);
mock_log_backend_reset(&backend2);
if (backend2_enable) {
log_backend_enable(&backend2, backend2.cb->ctx, LOG_LEVEL_DBG);
} else {
log_backend_disable(&backend2);
}
test_source_id = log_source_id_get(STRINGIFY(MODULE_NAME));
test_cxx_source_id = log_source_id_get(STRINGIFY(CXX_MODULE_NAME));
}
static void test_log_various_messages(void)
{
char str[128];
char dstr[] = "abcd";
int8_t i = -5;
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
log_setup(false);
#ifdef CONFIG_LOG2
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 (IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG)) {
/* 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_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp++, str);
}
LOG_DBG(TEST_MSG_0, ll, ull, i);
#ifdef CONFIG_FPU
float f = -1.2356;
double d = -1.2356;
snprintk(str, sizeof(str), TEST_MSG_1, f, 100, d);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, str);
LOG_INF(TEST_MSG_1, f, 100, d);
#endif /* CONFIG_FPU */
#else /* CONFIG_LOG2 */
#define TEST_MSG_0 "%hhd"
#define TEST_MSG_0_PREFIX "%s: %hhd"
#define TEST_MSG_1 "%p"
if (IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG)) {
/* 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__, i);
} else {
snprintk(str, sizeof(str), TEST_MSG_0, i);
}
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp++, str);
}
LOG_DBG(TEST_MSG_0, i);
snprintk(str, sizeof(str), TEST_MSG_1, &i);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, str);
LOG_INF(TEST_MSG_1, &i);
#endif
snprintk(str, sizeof(str), "wrn %s", dstr);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp++, str);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_ERR,
exp_timestamp++, "err");
LOG_WRN("wrn %s", log_strdup(dstr));
dstr[0] = '\0';
LOG_ERR("err");
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
}
/*
* 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.
*/
static void test_log_backend_runtime_filtering(void)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
ztest_test_skip();
}
log_setup(true);
if (IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG)) {
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_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp, str);
mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp, str);
exp_timestamp++;
}
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp, "test");
mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp, "test");
exp_timestamp++;
LOG_DBG("test");
LOG_INF("test");
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
mock_log_backend_validate(&backend2, false);
log_filter_set(&backend2,
CONFIG_LOG_DOMAIN_ID,
LOG_CURRENT_MODULE_ID(),
LOG_LEVEL_WRN);
uint8_t data[] = {1, 2, 4, 5, 6, 8};
/* INF logs expected only on backend1 */
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, "test");
mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID,
LOG_LEVEL_INF,
exp_timestamp++, "hexdump",
data, sizeof(data));
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp, "test2");
mock_log_backend_record(&backend2, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp++, "test2");
mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID,
LOG_LEVEL_WRN,
exp_timestamp, "hexdump",
data, sizeof(data));
mock_log_backend_generic_record(&backend2, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID,
LOG_LEVEL_WRN,
exp_timestamp++, "hexdump",
data, sizeof(data));
LOG_INF("test");
LOG_HEXDUMP_INF(data, sizeof(data), "hexdump");
LOG_WRN("test2");
LOG_HEXDUMP_WRN(data, sizeof(data), "hexdump");
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
mock_log_backend_validate(&backend2, false);
}
static size_t get_max_hexdump(void)
{
if (IS_ENABLED(CONFIG_LOG2)) {
return CONFIG_LOG_BUFFER_SIZE - sizeof(struct log_msg2_hdr);
}
uint32_t msgs_in_buf = CONFIG_LOG_BUFFER_SIZE/sizeof(union log_msg_chunk);
return LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK +
HEXDUMP_BYTES_CONT_MSG * (msgs_in_buf - 1);
}
#if defined(__sparc__) || 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)
{
if (IS_ENABLED(CONFIG_LOG2)) {
return CONFIG_LOG_BUFFER_SIZE -
/* First message */
ROUND_UP(LOG2_SIMPLE_MSG_LEN + 2 * sizeof(int) + STR_SIZE("test %d"),
sizeof(long long)) -
/* Hexdump message excluding data */
ROUND_UP(LOG2_SIMPLE_MSG_LEN + STR_SIZE("hexdump"),
sizeof(long long)) - 2 * sizeof(int);
}
uint32_t msgs_in_buf = (uint32_t)CONFIG_LOG_BUFFER_SIZE / sizeof(union log_msg_chunk);
return LOG_MSG_HEXDUMP_BYTES_HEAD_CHUNK +
HEXDUMP_BYTES_CONT_MSG * (msgs_in_buf - 1) -
HEXDUMP_BYTES_CONT_MSG;
}
/*
* 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 data[CONFIG_LOG_BUFFER_SIZE];
static void test_log_overflow(void)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
ztest_test_skip();
}
if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
ztest_test_skip();
}
for (int i = 0; i < CONFIG_LOG_BUFFER_SIZE; i++) {
data[i] = i;
}
log_setup(false);
uint32_t hexdump_len = get_long_hexdump();
/* expect first message to be dropped */
exp_timestamp++;
mock_log_backend_generic_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, "hexdump",
data, hexdump_len);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_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(data, hexdump_len, "hexdump");
LOG_INF("test2");
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
log_setup(false);
exp_timestamp = TIMESTAMP_INIT_VAL;
hexdump_len = get_max_hexdump();
mock_log_backend_reset(&backend1);
if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
/* Log2 allocation is not destructive if request exceeds the
* capacity.
*/
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp, "test");
mock_log_backend_drop_record(&backend1, 1);
} else {
/* Expect big message to be dropped because it does not fit in.
* First message is also dropped in the process of finding free space.
*/
mock_log_backend_drop_record(&backend1, 2);
}
LOG_INF("test");
LOG_HEXDUMP_INF(data, hexdump_len+1, "test");
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
}
/*
* Test checks if arguments are correctly processed by the logger.
*
* Log messages with supported number of messages are called. Test backend
* validates number of arguments and values.
*/
static void test_log_arguments(void)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
log_setup(false);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, "test");
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++,
"test 1 2 3");
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++,
"test 1 2 3 4 5 6 7");
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++,
"test 1 2 3 4 5 6 7 8 9 10 11");
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++,
"test 1 2 3 4 5 6 7 8 9 10 11 12 13 14");
LOG_INF("test");
LOG_INF("test %d %d %d", 1, 2, 3);
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 %d %d %d",
1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11);
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);
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, 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).
*/
static void test_log_from_declared_module(void)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
log_setup(false);
/* See test module for log message content. */
if (IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG)) {
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_backend_record(&backend1, test_source_id,
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp++, str);
}
mock_log_backend_record(&backend1, test_source_id,
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_ERR,
exp_timestamp++, TEST_ERR_MSG);
test_func();
if (IS_ENABLED(CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG)) {
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_backend_record(&backend1, test_source_id,
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_DBG,
exp_timestamp++, str);
}
mock_log_backend_record(&backend1, test_source_id,
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_ERR,
exp_timestamp, TEST_INLINE_ERR_MSG);
test_inline_func();
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, false);
}
static size_t get_short_msg_capacity(void)
{
if (IS_ENABLED(CONFIG_LOG2)) {
return (CONFIG_LOG_BUFFER_SIZE / LOG2_SIMPLE_MSG_LEN) - 1;
}
return CONFIG_LOG_BUFFER_SIZE / sizeof(struct log_msg);
}
static void log_n_messages(uint32_t n_msg, uint32_t exp_dropped)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
stamp = TIMESTAMP_INIT_VAL;
for (uint32_t i = 0; i < n_msg; i++) {
if (i >= exp_dropped) {
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_INF,
exp_timestamp++, "dummy");
}
LOG_INF("dummy");
}
mock_log_backend_drop_record(&backend1, exp_dropped);
while (LOG_PROCESS()) {
}
mock_log_backend_validate(&backend1, 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.
*/
static void test_log_msg_dropped_notification(void)
{
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
ztest_test_skip();
}
if (!IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) {
ztest_test_skip();
}
uint32_t capacity = get_short_msg_capacity();
return;
log_setup(false);
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).
*/
static void test_log_panic(void)
{
log_timestamp_t exp_timestamp = TIMESTAMP_INIT_VAL;
log_setup(false);
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp++, "test");
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp++, "test");
LOG_WRN("test");
LOG_WRN("test");
/* logs should be flushed in panic */
log_panic();
mock_log_backend_validate(&backend1, true);
/* messages processed where called */
mock_log_backend_record(&backend1, LOG_CURRENT_MODULE_ID(),
CONFIG_LOG_DOMAIN_ID, LOG_LEVEL_WRN,
exp_timestamp++, "test");
LOG_WRN("test");
mock_log_backend_validate(&backend1, true);
}
/* Disable backends because same suite may be excuted again but compiled by C++ */
static void log_api_suite_teardown(void)
{
log_backend_disable(&backend1);
log_backend_disable(&backend2);
}
/*test case main entry*/
#if __cplusplus
extern "C" void test_cxx(void);
void test_cxx(void)
#else
void test_cc(void)
#endif
{
PRINT("Configuration:\n");
PRINT("\t Mode: %s\n",
IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? "Immediate" : "Deferred");
PRINT("\t Version: %s\n",
IS_ENABLED(CONFIG_LOG2) ? "v2" : "v1");
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 __cplusplus
PRINT("\t C++: yes\n");
#endif
ztest_test_suite(test_log_api,
ztest_unit_test(test_log_various_messages),
ztest_unit_test(test_log_backend_runtime_filtering),
ztest_unit_test(test_log_overflow),
ztest_unit_test(test_log_arguments),
ztest_unit_test(test_log_from_declared_module),
ztest_unit_test(test_log_msg_dropped_notification),
ztest_unit_test(test_log_panic)
);
ztest_run_test_suite(test_log_api);
log_api_suite_teardown();
}

21
tests/subsys/logging/log_api/src/test_module.c Normal file
View file

@ -0,0 +1,21 @@
/*
* Copyright (c) 2018 Nordic Semiconductor
*
* SPDX-License-Identifier: Apache-2.0
*/
/**
* @file
* @brief Test module for log core test
*
*/
#include <logging/log.h>
LOG_MODULE_DECLARE(test, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
void test_func(void)
{
LOG_DBG("debug");
LOG_ERR("test");
}

36
tests/subsys/logging/log_api/src/test_module.h Normal file
View file

@ -0,0 +1,36 @@
/*
* Copyright (c) 2018 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef TEST_MODULE_H
#define TEST_MODULE_H
#include <logging/log.h>
#ifdef __cplusplus
extern "C" {
#endif
void test_func(void);
#ifdef __cplusplus
}
#endif
#define TEST_INLINE_DBG_MSG "inline debug"
#define TEST_INLINE_ERR_MSG "inline"
#define TEST_DBG_MSG "debug"
#define TEST_ERR_MSG "test"
static inline void test_inline_func(void)
{
LOG_MODULE_DECLARE(test, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
LOG_DBG(TEST_INLINE_DBG_MSG);
LOG_ERR(TEST_INLINE_ERR_MSG);
}
#endif /* TEST_MODULE_H */

152
tests/subsys/logging/log_api/testcase.yaml Normal file
View file

@ -0,0 +1,152 @@
tests:
logging.log_api_deferred_overflow_rt_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=y
- CONFIG_LOG_RUNTIME_FILTERING=y
logging.log_api_deferred_overflow:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=y
logging.log_api_deferred_no_overflow:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=n
logging.log_api_deferred_static_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_DEFERRED=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
logging.log_api_deferred_func_prefix:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_DEFERRED=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
- CONFIG_LOG_FUNC_NAME_PREFIX_DBG=y
logging.log_api_immediate:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_IMMEDIATE=y
logging.log_api_immediate_rt_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_IMMEDIATE=y
- CONFIG_LOG_RUNTIME_FILTERING=y
logging.log_api_immediate_static_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG_MODE_IMMEDIATE=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
logging.log2_api_deferred_overflow_rt_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=y
- CONFIG_LOG_RUNTIME_FILTERING=y
logging.log2_api_deferred_overflow:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=y
logging.log2_api_deferred_no_overflow:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_LOG_MODE_OVERFLOW=n
logging.log2_api_deferred_static_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
logging.log2_api_deferred_func_prefix:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
- CONFIG_LOG_FUNC_NAME_PREFIX_DBG=y
logging.log2_api_deferred_64b_timestamp:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_DEFERRED=y
- CONFIG_LOG_TIMESTAMP_64BIT=y
logging.log2_api_immediate:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_IMMEDIATE=y
logging.log2_api_immediate_rt_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_IMMEDIATE=y
- CONFIG_LOG_RUNTIME_FILTERING=y
logging.log2_api_immediate_static_filter:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_IMMEDIATE=y
- CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y
logging.log2_api_immediate_64b_timestamp:
integration_platforms:
- native_posix
tags: log_api logging
extra_configs:
- CONFIG_LOG2_MODE_IMMEDIATE=y
- CONFIG_LOG_TIMESTAMP_64BIT=y
common:
platform_allow: >
qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m0 qemu_cortex_m3
qemu_cortex_r5 qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86
qemu_x86_64 qemu_xtensa