WIP: Add zephyr logging to ztest

This is a demo PR for the TSC based on a conversation on the #testing
channel in the Discord.

  * Define a set of ztest logging macros (ZTEST_ERR, ZTEST_WRN, etc)
    that get used globally.
  * Add a Kconfig for choosing between Zephyr logging framework and
    built-in printk() logging (only supported in new ztest API)
  * Transistion ztest log outputs to these new macros at the appropriate
    levels.

 ### TODO
  * There's a lot of test output happening in tc_util.h, which isn't
    part of ztest and has its own printk macro wrapper. Need to find
    a nice way to override that.
  * Various other TODOs and thoughts added in comments.
  * Strip newlines from log messages since logging subsystem adds its
    own.

Zephyr logging has been enabled in the `tests/ztest/base/` tests, which
you can run with `/workdir/zephyr/scripts/twister -T
/workdir/zephyr/tests/ztest/base -vvv` for dev purposes.

Author: tristan-google

subsys/testsuite/include/tc_util.h

@@ -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

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

subsys/testsuite/ztest/include/ztest.h

@@ -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
+/* 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 <zephyr.h>

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

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;
 		}
 	}

subsys/testsuite/ztest/src/ztest_error_hook.c

@@ -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);
 	}
 }
@@ -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.

subsys/testsuite/ztest/src/ztest_mock.c

@@ -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>
@@ -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(&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();
 	}
 
@@ -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(&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.
@@ -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(&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 {
@@ -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;
 	}