| /* |
| * Copyright (c) 2018 Nordic Semiconductor |
| * |
| * SPDX-License-Identifier: Apache-2.0 |
| */ |
| |
| /** |
| * @file |
| * @brief Test log core |
| * |
| */ |
| |
| |
| #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> |
| #include "test_module.h" |
| |
| #define LOG_MODULE_NAME test |
| LOG_MODULE_REGISTER(LOG_MODULE_NAME); |
| |
| typedef void (*custom_put_callback_t)(struct log_backend const *const backend, |
| struct log_msg *msg, size_t counter); |
| |
| static bool in_panic; |
| |
| struct backend_cb { |
| size_t counter; |
| bool panic; |
| bool keep_msgs; |
| bool check_id; |
| uint32_t exp_id[100]; |
| bool check_timestamp; |
| uint32_t exp_timestamps[100]; |
| bool check_strdup; |
| bool exp_strdup[100]; |
| custom_put_callback_t callback; |
| uint32_t total_drops; |
| }; |
| |
| static void put(struct log_backend const *const backend, |
| struct log_msg *msg) |
| { |
| log_msg_get(msg); |
| struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx; |
| |
| if (cb->check_id) { |
| uint32_t exp_id = cb->exp_id[cb->counter]; |
| |
| zassert_equal(log_msg_source_id_get(msg), |
| exp_id, |
| "Unexpected source_id"); |
| } |
| |
| if (cb->check_timestamp) { |
| uint32_t exp_timestamp = cb->exp_timestamps[cb->counter]; |
| |
| zassert_equal(log_msg_timestamp_get(msg), |
| exp_timestamp, |
| "Unexpected message index"); |
| } |
| |
| if (cb->check_strdup) { |
| zassert_false(cb->exp_strdup[cb->counter] |
| ^ log_is_strdup((void *)log_msg_arg_get(msg, 0)), |
| NULL); |
| } |
| |
| if (cb->callback) { |
| cb->callback(backend, msg, cb->counter); |
| } |
| |
| cb->counter++; |
| |
| if (!cb->keep_msgs) { |
| log_msg_put(msg); |
| } |
| } |
| |
| static void panic(struct log_backend const *const backend) |
| { |
| struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx; |
| |
| cb->panic = true; |
| } |
| |
| static void dropped(struct log_backend const *const backend, uint32_t cnt) |
| { |
| struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx; |
| |
| cb->total_drops += cnt; |
| } |
| |
| const struct log_backend_api log_backend_test_api = { |
| .put = put, |
| .panic = panic, |
| .dropped = dropped, |
| }; |
| |
| 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; |
| |
| static uint32_t stamp; |
| |
| static uint32_t test_source_id; |
| |
| static uint32_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) |
| { |
| |
| for (int16_t i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); 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 = 0U; |
| zassert_false(in_panic, "Logger in panic state."); |
| |
| log_init(); |
| |
| zassert_equal(0, log_set_timestamp_func(timestamp_get, 0), |
| "Expects successful timestamp function setting."); |
| |
| 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); |
| } |
| |
| test_source_id = log_source_id_get(STRINGIFY(LOG_MODULE_NAME)); |
| } |
| |
| static void test_log_strdup_gc(void) |
| { |
| char test_str[] = "test string"; |
| char *dstr; |
| uint32_t size_u0, size_u1, size_cu0, size_cu1, size_l0, size_l1; |
| |
| log_setup(false); |
| |
| BUILD_ASSERT(CONFIG_LOG_STRDUP_BUF_COUNT == 1, |
| "Test assumes certain configuration"); |
| backend1_cb.check_strdup = true; |
| backend1_cb.exp_strdup[0] = true; |
| backend1_cb.exp_strdup[1] = false; |
| |
| size_l0 = log_get_strdup_longest_string(); |
| size_u0 = log_get_strdup_pool_utilization(); |
| size_cu0 = log_get_strdup_pool_current_utilization(); |
| |
| dstr = log_strdup(test_str); |
| /* test if message freeing is not fooled by using value within strdup |
| * buffer pool but with different format specifier. |
| */ |
| LOG_INF("%s %p", dstr, dstr + 1); |
| LOG_INF("%s", log_strdup(test_str)); |
| |
| while (log_process(false)) { |
| } |
| |
| zassert_equal(2, backend1_cb.counter, |
| "Unexpected amount of messages received by the backend."); |
| |
| /* Processing should free strdup buffer. */ |
| backend1_cb.exp_strdup[2] = true; |
| LOG_INF("%s", log_strdup(test_str)); |
| |
| size_cu1 = log_get_strdup_pool_current_utilization(); |
| |
| while (log_process(false)) { |
| } |
| |
| zassert_equal(3, backend1_cb.counter, |
| "Unexpected amount of messages received by the backend."); |
| size_l1 = log_get_strdup_longest_string(); |
| size_u1 = log_get_strdup_pool_utilization(); |
| zassert_true(size_l1 > size_l0, "longest string size never changed"); |
| zassert_true(size_u1 > size_u0, "strdup pool utilization never changed"); |
| zassert_true(size_cu1 > size_cu0, |
| "strdup pool current utilization never changed"); |
| } |
| |
| #define DETECT_STRDUP_MISSED(str, do_strdup, ...) \ |
| {\ |
| char tmp[] = "tmp";\ |
| uint32_t exp_cnt = backend1_cb.counter + 1 + (do_strdup ? 0 : 1); \ |
| LOG_ERR(str, ##__VA_ARGS__, do_strdup ? log_strdup(tmp) : tmp); \ |
| \ |
| while (log_process(false)) { \ |
| } \ |
| \ |
| zassert_equal(exp_cnt, backend1_cb.counter,\ |
| "Unexpected amount of messages received by the backend (%d).", \ |
| backend1_cb.counter); \ |
| } |
| |
| static void test_log_strdup_detect_miss(void) |
| { |
| if (IS_ENABLED(CONFIG_LOG_DETECT_MISSED_STRDUP)) { |
| return; |
| } |
| |
| log_setup(false); |
| |
| DETECT_STRDUP_MISSED("%s", true); |
| DETECT_STRDUP_MISSED("%s", false); |
| |
| DETECT_STRDUP_MISSED("%-20s", true); |
| DETECT_STRDUP_MISSED("%-20s", false); |
| |
| DETECT_STRDUP_MISSED("%20s", true); |
| DETECT_STRDUP_MISSED("%20s", false); |
| |
| DETECT_STRDUP_MISSED("%20.4s", true); |
| DETECT_STRDUP_MISSED("%20.4s", false); |
| |
| DETECT_STRDUP_MISSED("%% %s %%", true); |
| DETECT_STRDUP_MISSED("%% %s %%", false); |
| |
| DETECT_STRDUP_MISSED("%% %08X %s", true, 4); |
| DETECT_STRDUP_MISSED("%% %08X %s", false, 4); |
| } |
| |
| static void strdup_trim_callback(struct log_backend const *const backend, |
| struct log_msg *msg, size_t counter) |
| { |
| char *str = (char *)log_msg_arg_get(msg, 0); |
| size_t len = strlen(str); |
| |
| zassert_equal(len, CONFIG_LOG_STRDUP_MAX_STRING, |
| "Expected trimmed string"); |
| } |
| |
| static void test_strdup_trimming(void) |
| { |
| char test_str[] = "123456789"; |
| |
| BUILD_ASSERT(CONFIG_LOG_STRDUP_MAX_STRING == 8, |
| "Test assumes certain configuration"); |
| |
| log_setup(false); |
| |
| backend1_cb.callback = strdup_trim_callback; |
| |
| LOG_INF("%s", log_strdup(test_str)); |
| |
| while (log_process(false)) { |
| } |
| |
| zassert_equal(1, backend1_cb.counter, |
| "Unexpected amount of messages received by the backend."); |
| } |
| |
| static void test_single_z_log_get_s_mask(const char *str, uint32_t nargs, |
| uint32_t exp_mask) |
| { |
| uint32_t mask = z_log_get_s_mask(str, nargs); |
| |
| zassert_equal(mask, exp_mask, "Unexpected mask %x (expected %x)", |
| mask, exp_mask); |
| } |
| |
| static void test_z_log_get_s_mask(void) |
| { |
| test_single_z_log_get_s_mask("%d%%%-10s%p%x", 4, 0x2); |
| test_single_z_log_get_s_mask("%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d" |
| "%d%d%d%d%d%d%d%d%d%d%d%d%d%d%d%s", |
| 32, 0x80000000); |
| } |
| |
| /*test case main entry*/ |
| void test_main(void) |
| { |
| ztest_test_suite(test_log_core, |
| ztest_unit_test(test_log_strdup_gc), |
| ztest_unit_test(test_log_strdup_detect_miss), |
| ztest_unit_test(test_strdup_trimming), |
| ztest_unit_test(test_z_log_get_s_mask) |
| ); |
| ztest_run_test_suite(test_log_core); |
| } |