diff --git a/subsys/testsuite/include/tc_util.h b/subsys/testsuite/include/tc_util.h index 56896dc4d9f1..a1627d24de76 100644 --- a/subsys/testsuite/include/tc_util.h +++ b/subsys/testsuite/include/tc_util.h @@ -17,6 +17,27 @@ #endif #include +#if defined(CONFIG_ZTEST) && defined(CONFIG_ZTEST_PRINT_TO_LOG) +/* Override the PRINT_DATA and TC_END_REPORT macros to use Zephyr's + * logging system. Use ZTEST_PRINTK() (i.e. always print) for + * TC_END_REPORT() because that line is critical for twister to + * determine when tests running within QEMU have completed. + */ + +#include + +#define PRINT_DATA ZTEST_INF + +#define TC_END_REPORT(result) \ + do { \ + PRINT_LINE; \ + TC_PRINT_RUNID; \ + ZTEST_PRINTK("PROJECT EXECUTION %s\n", \ + (result) == TC_PASS ? "SUCCESSFUL" : "FAILED"); \ + TC_END_POST(result); \ + } while (0) +#endif + #if defined CONFIG_ZTEST_TC_UTIL_USER_OVERRIDE #include #endif diff --git a/subsys/testsuite/ztest/Kconfig b/subsys/testsuite/ztest/Kconfig index 6d1998576d34..1c80495aa0b3 100644 --- a/subsys/testsuite/ztest/Kconfig +++ b/subsys/testsuite/ztest/Kconfig @@ -10,6 +10,19 @@ config ZTEST if ZTEST +config ZTEST_PRINT_TO_LOG + bool "Use the Zephyr logging subsystem" + depends on LOG + depends on ZTEST_NEW_API + help + If enabled, the ZTEST logging macros (ZTEST_ERR, ZTEST_WRN, etc) will be + forwarded to the Zephyr logging subsystem at the corresponding levels. + The verbosity level of these logs can be controlled using the normal + Zephyr log Kconfig options. A console logging backend will be attached. + + If disabled, all log messages using the ZTEST logging macros will be + directed to printk(). There is no control over verbosity in this case. + config ZTEST_NEW_API bool "Use the new Ztest API" help diff --git a/subsys/testsuite/ztest/include/ztest.h b/subsys/testsuite/ztest/include/ztest.h index 6aa4306948b2..d0ab5cf833b9 100644 --- a/subsys/testsuite/ztest/include/ztest.h +++ b/subsys/testsuite/ztest/include/ztest.h @@ -54,6 +54,37 @@ typedef struct esf z_arch_esf_t; #endif /* KERNEL */ #include + +/* Test logging destination */ +#ifdef CONFIG_ZTEST_PRINT_TO_LOG +/* Use the Zephyr logging subsystem */ +#include + +#ifndef ZTEST_DONT_DECLARE_LOG +/* Automatically declare the log module in all compilation units including + * this header, unless this macro is set. The macro should be set in the + * source file that initially registers the module to avoid a redefinition. + */ + +LOG_MODULE_DECLARE(ztest_log_mod); +#endif /* ZTEST_DONT_DECLARE_LOG */ + + +#define ZTEST_DBG LOG_DBG +#define ZTEST_INF LOG_INF +#define ZTEST_WRN LOG_WRN +#define ZTEST_ERR LOG_ERR +#define ZTEST_PRINTK LOG_PRINTK +#else +/* Direct everything through printk */ +#define ZTEST_DBG printk +#define ZTEST_INF printk +#define ZTEST_WRN printk +#define ZTEST_ERR printk +#define ZTEST_PRINTK printk +#endif /* ZTEST_PRINT_TO_LOG */ + +/* TODO: Do we want to retain this? Could user tests be relying on it? */ #define PRINT printk #include diff --git a/subsys/testsuite/ztest/include/ztest_assert.h b/subsys/testsuite/ztest/include/ztest_assert.h index 1b078e42a03f..8b41505e3d27 100644 --- a/subsys/testsuite/ztest/include/ztest_assert.h +++ b/subsys/testsuite/ztest/include/ztest_assert.h @@ -30,7 +30,7 @@ void ztest_test_fail(void); static inline bool z_zassert_(bool cond, const char *file, int line) { if (cond == false) { - PRINT("\n Assertion failed at %s:%d\n", + ZTEST_ERR("\n Assertion failed at %s:%d\n", ztest_relative_filename(file), line); ztest_test_fail(); return false; @@ -50,21 +50,29 @@ static inline bool z_zassert(bool cond, int line, const char *func, const char *msg, ...) { + static char formatted_msg[512]; /* TODO: is this the right size? */ + if (cond == false) { va_list vargs; + int ret; va_start(vargs, msg); - PRINT("\n Assertion failed at %s:%d: %s: %s\n", - ztest_relative_filename(file), line, func, default_msg); - vprintk(msg, vargs); - printk("\n"); + ZTEST_ERR("\n Assertion failed at %s:%d: %s: %s\n", + ztest_relative_filename(file), line, func, default_msg); + + ret = vsnprintf(formatted_msg, sizeof(formatted_msg), msg, vargs); + if (ret >= sizeof(formatted_msg)) { + ZTEST_ERR("The assertion message has been truncated!\n"); + } + ZTEST_ERR("%s\n", formatted_msg); va_end(vargs); ztest_test_fail(); return false; } +/* TODO - is this config option still relevant? */ #if CONFIG_ZTEST_ASSERT_VERBOSE == 2 else { - PRINT("\n Assertion succeeded at %s:%d (%s)\n", + ZTEST_DBG("\n Assertion succeeded at %s:%d (%s)\n", ztest_relative_filename(file), line, func); } #endif diff --git a/subsys/testsuite/ztest/src/ztest.c b/subsys/testsuite/ztest/src/ztest.c index 96f7cb81e85f..dc761a2f8cd3 100644 --- a/subsys/testsuite/ztest/src/ztest.c +++ b/subsys/testsuite/ztest/src/ztest.c @@ -75,11 +75,11 @@ static int cleanup_test(struct unit_test *test) #endif if (!ret && mock_status == 1) { - PRINT("Test %s failed: Unused mock parameter values\n", + ZTEST_ERR("Test %s failed: Unused mock parameter values\n", test->name); ret = TC_FAIL; } else if (!ret && mock_status == 2) { - PRINT("Test %s failed: Unused mock return values\n", + ZTEST_ERR("Test %s failed: Unused mock return values\n", test->name); ret = TC_FAIL; } else { @@ -244,15 +244,15 @@ static void handle_signal(int sig) "teardown", }; - PRINT(" %s", strsignal(sig)); + ZTEST_ERR(" %s", strsignal(sig)); switch (phase) { case TEST_PHASE_SETUP: case TEST_PHASE_TEST: case TEST_PHASE_TEARDOWN: - PRINT(" at %s function\n", phase_str[phase]); + ZTEST_ERR(" at %s function\n", phase_str[phase]); longjmp(test_fail, 1); case TEST_PHASE_FRAMEWORK: - PRINT("\n"); + ZTEST_ERR("\n"); longjmp(stack_fail, 1); } } @@ -263,7 +263,7 @@ static void init_testing(void) signal(SIGSEGV, handle_signal); if (setjmp(stack_fail)) { - PRINT("Test suite crashed."); + ZTEST_ERR("Test suite crashed."); exit(1); } } @@ -482,7 +482,7 @@ void ztest_verify_all_registered_test_suites_ran(void) for (ptr = _ztest_suite_node_list_start; ptr < _ztest_suite_node_list_end; ++ptr) { if (ptr->stats.run_count < 1) { - PRINT("ERROR: Test '%s' did not run.\n", ptr->name); + ZTEST_ERR("ERROR: Test '%s' did not run.\n", ptr->name); all_tests_run = false; } } @@ -521,7 +521,8 @@ void main(void) ret = k_mem_domain_add_partition(&k_mem_domain_default, &ztest_mem_partition); if (ret != 0) { - PRINT("ERROR: failed to add ztest_mem_partition to mem domain (%d)\n", + ZTEST_ERR( + "ERROR: failed to add ztest_mem_partition to mem domain (%d)\n", ret); k_oops(); } @@ -530,7 +531,8 @@ void main(void) ret = k_mem_domain_add_partition(&k_mem_domain_default, &z_malloc_partition); if (ret != 0) { - PRINT("ERROR: failed to add z_malloc_partition to mem domain (%d)\n", + ZTEST_ERR( + "ERROR: failed to add z_malloc_partition to mem domain (%d)\n", ret); k_oops(); } @@ -553,12 +555,12 @@ void main(void) } state.boots += 1; if (test_status == 0) { - PRINT("Reset board #%u to test again\n", + ZTEST_ERR("Reset board #%u to test again\n", state.boots); k_msleep(10); sys_reboot(SYS_REBOOT_COLD); } else { - PRINT("Failed after %u attempts\n", state.boots); + ZTEST_ERR("Failed after %u attempts\n", state.boots); state.boots = 0; } } diff --git a/subsys/testsuite/ztest/src/ztest_error_hook.c b/subsys/testsuite/ztest/src/ztest_error_hook.c index 0c3a9733f429..e24f5f22cb67 100644 --- a/subsys/testsuite/ztest/src/ztest_error_hook.c +++ b/subsys/testsuite/ztest/src/ztest_error_hook.c @@ -51,10 +51,10 @@ void k_sys_fatal_error_handler(unsigned int reason, const z_arch_esf_t *pEsf) k_tid_t curr_tid = k_current_get(); bool valid_fault = (curr_tid == valid_fault_tid) || fault_in_isr; - printk("Caught system error -- reason %d %d\n", reason, valid_fault); + ZTEST_ERR("Caught system error -- reason %d %d\n", reason, valid_fault); if (valid_fault) { - printk("Fatal error expected as part of test case.\n"); + ZTEST_ERR("Fatal error expected as part of test case.\n"); /* reset back to normal */ reset_stored_fault_status(); @@ -62,7 +62,7 @@ void k_sys_fatal_error_handler(unsigned int reason, const z_arch_esf_t *pEsf) /* do some action after expected fatal error happened */ ztest_post_fatal_error_hook(reason, pEsf); } else { - printk("Fatal error was unexpected, aborting...\n"); + ZTEST_ERR("Fatal error was unexpected, aborting...\n"); k_fatal_halt(reason); } } @@ -119,10 +119,10 @@ void assert_post_action(const char *file, unsigned int line) ARG_UNUSED(line); #endif - printk("Caught assert failed\n"); + ZTEST_ERR("Caught assert failed\n"); if ((k_current_get() == valid_assert_tid) || assert_in_isr) { - printk("Assert error expected as part of test case.\n"); + ZTEST_ERR("Assert error expected as part of test case.\n"); /* reset back to normal */ reset_stored_assert_status(); @@ -132,7 +132,7 @@ void assert_post_action(const char *file, unsigned int line) */ ztest_post_assert_fail_hook(); } else { - printk("Assert failed was unexpected, aborting...\n"); + ZTEST_ERR("Assert failed was unexpected, aborting...\n"); #ifdef CONFIG_USERSPACE /* User threads aren't allowed to induce kernel panics; generate * an oops instead. diff --git a/subsys/testsuite/ztest/src/ztest_mock.c b/subsys/testsuite/ztest/src/ztest_mock.c index 692540284e1a..6ea2f35702b6 100644 --- a/subsys/testsuite/ztest/src/ztest_mock.c +++ b/subsys/testsuite/ztest/src/ztest_mock.c @@ -4,6 +4,12 @@ * SPDX-License-Identifier: Apache-2.0 */ +#ifdef CONFIG_ZTEST_PRINT_TO_LOG +#include + +LOG_MODULE_DECLARE(ztest_log_mod); +#endif /* CONFIG_ZTEST_PRINT_TO_LOG */ + #include #include #include @@ -32,7 +38,7 @@ static struct parameter *alloc_parameter(void) param = calloc(1, sizeof(struct parameter)); if (!param) { - PRINT("Failed to allocate mock parameter\n"); + ZTEST_ERR("Failed to allocate mock parameter\n"); ztest_test_fail(); } @@ -122,7 +128,7 @@ static struct parameter *alloc_parameter(void) allocation_index = sys_bitfield_find_first_clear( params_allocation, CONFIG_ZTEST_PARAMETER_COUNT); if (allocation_index == -1) { - printk("No more mock parameters available for allocation\n"); + ZTEST_ERR("No more mock parameters available for allocation\n"); ztest_test_fail(); } sys_bitfield_set_bit((mem_addr_t)params_allocation, allocation_index); @@ -193,7 +199,7 @@ void z_ztest_check_expected_value(const char *fn, const char *name, param = find_and_delete_value(¶meter_list, fn, name); if (!param) { - PRINT("Failed to find parameter %s for %s\n", name, fn); + ZTEST_ERR("Failed to find parameter %s for %s\n", name, fn); ztest_test_fail(); } @@ -204,7 +210,7 @@ void z_ztest_check_expected_value(const char *fn, const char *name, /* We need to cast these values since the toolchain doesn't * provide inttypes.h */ - PRINT("%s:%s received wrong value: Got %lu, expected %lu\n", fn, + ZTEST_ERR("%s:%s received wrong value: Got %lu, expected %lu\n", fn, name, (unsigned long)val, (unsigned long)expected); ztest_test_fail(); } @@ -223,7 +229,7 @@ void z_ztest_check_expected_data(const char *fn, const char *name, void *data, param = find_and_delete_value(¶meter_list, fn, name); if (!param) { - PRINT("Failed to find parameter %s for %s\n", name, fn); + ZTEST_ERR("Failed to find parameter %s for %s\n", name, fn); /* No return from this function but for coverity reasons * put a return after to avoid the warning of a null * dereference of param below. @@ -236,15 +242,15 @@ void z_ztest_check_expected_data(const char *fn, const char *name, void *data, free_parameter(param); if (expected == NULL && data != NULL) { - PRINT("%s:%s received null pointer\n", fn, name); + ZTEST_ERR("%s:%s received null pointer\n", fn, name); ztest_test_fail(); } else if (data == NULL && expected != NULL) { - PRINT("%s:%s received data while expected null pointer\n", fn, + ZTEST_ERR("%s:%s received data while expected null pointer\n", fn, name); ztest_test_fail(); } else if (data != NULL) { if (memcmp(data, expected, length) != 0) { - PRINT("%s:%s data provided don't match\n", fn, name); + ZTEST_ERR("%s:%s data provided don't match\n", fn, name); ztest_test_fail(); } } @@ -262,14 +268,14 @@ void z_ztest_copy_return_data(const char *fn, const char *name, void *data, void *return_data; if (data == NULL) { - PRINT("%s:%s received null pointer\n", fn, name); + ZTEST_ERR("%s:%s received null pointer\n", fn, name); ztest_test_fail(); return; } param = find_and_delete_value(¶meter_list, fn, name); if (!param) { - PRINT("Failed to find parameter %s for %s\n", name, fn); + ZTEST_ERR("Failed to find parameter %s for %s\n", name, fn); memset(data, 0, length); ztest_test_fail(); } else { @@ -291,7 +297,7 @@ uintptr_t z_ztest_get_return_value(const char *fn) find_and_delete_value(&return_value_list, fn, ""); if (!param) { - PRINT("Failed to find return value for function %s\n", fn); + ZTEST_ERR("Failed to find return value for function %s\n", fn); ztest_test_fail(); } @@ -317,13 +323,13 @@ int z_cleanup_mock(void) int fail = 0; if (parameter_list.next) { - PRINT("Parameter not used by mock: %s:%s\n", + ZTEST_ERR("Parameter not used by mock: %s:%s\n", parameter_list.next->fn, parameter_list.next->name); fail = 1; } if (return_value_list.next) { - PRINT("Return value no used by mock: %s\n", + ZTEST_ERR("Return value no used by mock: %s\n", return_value_list.next->fn); fail = 2; } diff --git a/subsys/testsuite/ztest/src/ztest_new.c b/subsys/testsuite/ztest/src/ztest_new.c index 6a38eb0aeead..8bb1b7595f92 100644 --- a/subsys/testsuite/ztest/src/ztest_new.c +++ b/subsys/testsuite/ztest/src/ztest_new.c @@ -4,6 +4,15 @@ * SPDX-License-Identifier: Apache-2.0 */ +#ifdef CONFIG_ZTEST_PRINT_TO_LOG +#include + +LOG_MODULE_REGISTER(ztest_log_mod); + +/* Setting this prevents ztest.h from re-declaring the log module objects */ +#define ZTEST_DONT_DECLARE_LOG +#endif /* CONFIG_ZTEST_PRINT_TO_LOG */ + #include #include #include @@ -77,11 +86,11 @@ static int cleanup_test(struct ztest_unit_test *test) #endif if (!ret && mock_status == 1) { - PRINT("Test %s failed: Unused mock parameter values\n", + ZTEST_ERR("Test %s failed: Unused mock parameter values\n", test->name); ret = TC_FAIL; } else if (!ret && mock_status == 2) { - PRINT("Test %s failed: Unused mock return values\n", + ZTEST_ERR("Test %s failed: Unused mock return values\n", test->name); ret = TC_FAIL; } else { @@ -256,17 +265,17 @@ static void handle_signal(int sig) "teardown", }; - PRINT(" %s", strsignal(sig)); + ZTEST_ERR(" %s", strsignal(sig)); switch (phase) { case TEST_PHASE_SETUP: case TEST_PHASE_BEFORE: case TEST_PHASE_TEST: case TEST_PHASE_AFTER: case TEST_PHASE_TEARDOWN: - PRINT(" at %s function\n", phase_str[phase]); + ZTEST_ERR(" at %s function\n", phase_str[phase]); longjmp(test_fail, 1); case TEST_PHASE_FRAMEWORK: - PRINT("\n"); + ZTEST_ERR("\n"); longjmp(stack_fail, 1); } } @@ -277,7 +286,7 @@ static void init_testing(void) signal(SIGSEGV, handle_signal); if (setjmp(stack_fail)) { - PRINT("Test suite crashed."); + ZTEST_ERR("Test suite crashed."); /* TODO: should there be a \n? */ exit(1); } } @@ -560,7 +569,7 @@ void ztest_verify_all_test_suites_ran(void) for (suite = _ztest_suite_node_list_start; suite < _ztest_suite_node_list_end; ++suite) { if (suite->stats.run_count < 1) { - PRINT("ERROR: Test suite '%s' did not run.\n", suite->name); + ZTEST_ERR("Test suite '%s' did not run.\n", suite->name); all_tests_run = false; } } @@ -568,7 +577,7 @@ void ztest_verify_all_test_suites_ran(void) for (test = _ztest_unit_test_list_start; test < _ztest_unit_test_list_end; ++test) { suite = ztest_find_test_suite(test->test_suite_name); if (suite == NULL) { - PRINT("ERROR: Test '%s' assigned to test suite '%s' which doesn't exist\n", + ZTEST_ERR("Test '%s' assigned to test suite '%s' which doesn't exist\n", test->name, test->test_suite_name); all_tests_run = false; } @@ -629,12 +638,12 @@ void main(void) } state.boots += 1; if (test_status == 0) { - PRINT("Reset board #%u to test again\n", + ZTEST_ERR("Reset board #%u to test again\n", state.boots); k_msleep(10); sys_reboot(SYS_REBOOT_COLD); } else { - PRINT("Failed after %u attempts\n", state.boots); + ZTEST_ERR("Failed after %u attempts\n", state.boots); state.boots = 0; } } diff --git a/subsys/testsuite/ztest/src/ztress.c b/subsys/testsuite/ztest/src/ztress.c index 424066489647..9b56415886ae 100644 --- a/subsys/testsuite/ztest/src/ztress.c +++ b/subsys/testsuite/ztest/src/ztress.c @@ -3,6 +3,13 @@ * * SPDX-License-Identifier: Apache-2.0 */ + +#ifdef CONFIG_ZTEST_PRINT_TO_LOG +#include + +LOG_MODULE_DECLARE(ztest_log_mod); +#endif /* CONFIG_ZTEST_PRINT_TO_LOG */ + #include #include #include @@ -102,6 +109,7 @@ static void progress_timeout(struct k_timer *timer) uint64_t rem = 1000 * (k_timer_expires_ticks(&test_timer) - sys_clock_tick_get()) / CONFIG_SYS_CLOCK_TICKS_PER_SEC; + /* TODO: this isn't really a log message but more of a progress bar. leave alone? */ printk("\r%u%% remaining:%u ms", progress, (uint32_t)rem); } @@ -275,7 +283,7 @@ static void ztress_init(struct ztress_context_data *thread_data) k_msleep(10); if (idle_tid == NULL) { - printk("Failed to identify idle thread. CPU load will not be tracked\n"); + ZTEST_WRN("Failed to identify idle thread. CPU load will not be tracked\n"); } k_timer_start(&ctrl_timer, K_MSEC(100), K_MSEC(100)); @@ -385,15 +393,15 @@ void ztress_set_timeout(k_timeout_t t) void ztress_report(void) { - printk("\nZtress execution report:\n"); + ZTEST_INF("\nZtress execution report:\n"); for (uint32_t i = 0; i < context_cnt; i++) { - printk("\t context %u:\n\t\t - executed:%u, preempted:%u\n", + ZTEST_INF("\t context %u:\n\t\t - executed:%u, preempted:%u\n", i, exec_cnt[i], preempt_cnt[i]); - printk("\t\t - ticks initial:%u, optimized:%u\n", + ZTEST_INF("\t\t - ticks initial:%u, optimized:%u\n", (uint32_t)init_backoff[i].ticks, (uint32_t)backoff[i].ticks); } - printk("\tAvarage CPU load:%u%%, measurements:%u\n", + ZTEST_INF("\tAvarage CPU load:%u%%, measurements:%u\n", rt.cpu_load / 10, rt.cpu_load_measurements); } diff --git a/tests/ztest/base/prj_verbose_0.conf b/tests/ztest/base/prj_verbose_0.conf index b4903cd10cb3..01b1431f5790 100644 --- a/tests/ztest/base/prj_verbose_0.conf +++ b/tests/ztest/base/prj_verbose_0.conf @@ -1,3 +1,4 @@ CONFIG_ZTEST=y CONFIG_ZTEST_NEW_API=y CONFIG_ZTEST_ASSERT_VERBOSE=0 +CONFIG_ZTEST_PRINT_TO_LOG=y diff --git a/tests/ztest/base/prj_verbose_1.conf b/tests/ztest/base/prj_verbose_1.conf index ef6cb613538d..44f3e07c7a4e 100644 --- a/tests/ztest/base/prj_verbose_1.conf +++ b/tests/ztest/base/prj_verbose_1.conf @@ -1,3 +1,4 @@ CONFIG_ZTEST=y CONFIG_ZTEST_NEW_API=y CONFIG_ZTEST_ASSERT_VERBOSE=1 +CONFIG_ZTEST_PRINT_TO_LOG=y diff --git a/tests/ztest/base/prj_verbose_2.conf b/tests/ztest/base/prj_verbose_2.conf index c995cf19ee03..e7c84beba5a3 100644 --- a/tests/ztest/base/prj_verbose_2.conf +++ b/tests/ztest/base/prj_verbose_2.conf @@ -1,3 +1,4 @@ CONFIG_ZTEST=y CONFIG_ZTEST_NEW_API=y CONFIG_ZTEST_ASSERT_VERBOSE=2 +CONFIG_ZTEST_PRINT_TO_LOG=y