Skip to content

WIP: Add logging levels to ztest #1

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

WIP: Add logging levels to ztest #1

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 21 additions & 0 deletions subsys/testsuite/include/tc_util.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,27 @@
#endif
#include <sys/printk.h>

#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 <ztest.h>

#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 <tc_util_user_override.h>
#endif
Expand Down
13 changes: 13 additions & 0 deletions subsys/testsuite/ztest/Kconfig
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
31 changes: 31 additions & 0 deletions subsys/testsuite/ztest/include/ztest.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,37 @@ typedef struct esf z_arch_esf_t;
#endif /* KERNEL */

#include <sys/printk.h>

/* Test logging destination */
#ifdef CONFIG_ZTEST_PRINT_TO_LOG
/* Use the Zephyr logging subsystem */
#include <logging/log.h>

#ifndef ZTEST_DONT_DECLARE_LOG
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the convention is to prefix with Z_ for internal defines

/* 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
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you remove the \n from the logs and do:

ZTEST_DBG(msg, ...) printk(msg "\n", ##__VA_ARGS__)

Copy link
Owner Author

@tristan-google tristan-google Feb 9, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was hoping to avoid this, as there are a lot of tests printing their own log messages, but if that's the best way forward I'll do that...

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You know, before we keep pushing on this we should know what the overhead of CONFIG_LOG=y is. There's an option to route logging to printk via CONFIG_LOG_PRINTK=y. It's possible that this is 100% acceptable and the overhead of requiring logging in ztest is fine.

#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 <zephyr.h>
Expand Down
20 changes: 14 additions & 6 deletions subsys/testsuite/ztest/include/ztest_assert.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down
24 changes: 13 additions & 11 deletions subsys/testsuite/ztest/src/ztest.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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);
}
}
Expand Down Expand Up @@ -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);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel like these prefixes like ERROR: don't make sense anymore, can we remove them and add them in the printk case or remove them entirely

all_tests_run = false;
}
}
Expand Down Expand Up @@ -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();
}
Expand All @@ -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();
}
Expand All @@ -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;
}
}
Expand Down
12 changes: 6 additions & 6 deletions subsys/testsuite/ztest/src/ztest_error_hook.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,18 +51,18 @@ 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();

/* 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);
}
}
Expand Down Expand Up @@ -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();
Expand All @@ -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.
Expand Down
32 changes: 19 additions & 13 deletions subsys/testsuite/ztest/src/ztest_mock.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,12 @@
* SPDX-License-Identifier: Apache-2.0
*/

#ifdef CONFIG_ZTEST_PRINT_TO_LOG
#include <logging/log.h>

LOG_MODULE_DECLARE(ztest_log_mod);
#endif /* CONFIG_ZTEST_PRINT_TO_LOG */

#include <ztest.h>
#include <zephyr/types.h>
#include <string.h>
Expand Down Expand Up @@ -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();
}

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -193,7 +199,7 @@ void z_ztest_check_expected_value(const char *fn, const char *name,

param = find_and_delete_value(&parameter_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();
}

Expand All @@ -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();
}
Expand All @@ -223,7 +229,7 @@ void z_ztest_check_expected_data(const char *fn, const char *name, void *data,

param = find_and_delete_value(&parameter_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.
Expand All @@ -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();
}
}
Expand All @@ -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(&parameter_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 {
Expand All @@ -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();
}

Expand All @@ -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;
}
Expand Down
Loading