ztest: tracing backend works incorrectly when new ZTEST enabled.

[Zhaoningx]

Describe the bug

I created a dummy tracing backend to get and verify the data to verify the tracing functionality. The code as below:

#if defined(CONFIG_TRACING_BACKEND_UART)
static void tracing_backends_output(
		const struct tracing_backend *backend,
		uint8_t *data, uint32_t length)
{
	printk("-=-=-=-=-=-=-=-=-=-=-=-\n");
	printk("data = %s\n", data);
	printk("-=-=-=-=-=-=-=-=-=-=-=-\n");
	/* Check the output data. */
#ifdef CONFIG_TRACING_ASYNC
	/* Define static 'i' is for guaranteeing all strings of 0 ~ end
	 * of the array string_tracked are tested.
	 */
	static int i;

	while (string_tracked[i] != NULL) {
		if (strstr(data, string_tracked[i]) != NULL) {
			tracing_api_found = true;
		} else {
			tracing_api_not_found = true;
		}
		i++;
	}
#endif
	if (strstr(data, "tracing_format_data_testing") != NULL) {
		data_format_found = true;
	}
	if (strstr(data, "tracing_format_raw_data_testing") != NULL) {
		raw_data_format_found = true;
	}
	if (strstr(data, "tracing_format_string_testing") != NULL) {
		sync_string_format_found = true;
	}
}

const struct tracing_backend_api tracing_uart_backend_api = {
	.init = NULL,
	.output  = tracing_backends_output
};

TRACING_BACKEND_DEFINE(tracing_backend_uart, tracing_uart_backend_api);
#endif

And when I migrated the test cases to the new ZTEST API, I find that when the test suite ZTEST_SUITE is running, the dummy tracing backend will don't get any output anymore. So test cases will fail to check flags. More details please refer to the directory tests/subsys/tracing/tracing_api/

Impact
testcases failed

Environment (please complete the following information):
OS: linux
Toolchain Zephyr SDK 14.2

[nashif]

@Zhaoningx you need to provide more details and how this can be reproduced, for example, you could provice a link to a branch with the modified test and the backend so one can examine it.

[Zhaoningx]

Hi @nashif, I used the old ZTEST suite, and insert a printk function to backend API, the log as below:

DEBUG   - QEMU (7374): SeaBIOS (version zephyr-v1.0.0-0-g31d4e0e-dirty-20200714_234759-fv-az50-zephyr)
DEBUG   - QEMU (7374): Booting from ROM..
DEBUG   - QEMU (7374): *** Booting Zephyr OS build zephyr-v3.1.0-4097-g80f848e4a4fe  ***
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): Running TESTSUITE test_tracing
DEBUG   - QEMU (7374): ===================================================================
DEBUG   - QEMU (7374): START - test_tracing_sys_api
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): PASS - test_tracing_sys_api in 0.122 seconds
DEBUG   - QEMU (7374): ===================================================================
DEBUG   - QEMU (7374): START - test_tracing_data_format
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374): PASS - test_tracing_data_format in 0.230 seconds
DEBUG   - QEMU (7374): ===================================================================
DEBUG   - QEMU (7374): START - test_tracing_cmd_manual
DEBUG   - QEMU (7374): PASS - test_tracing_cmd_manual in 0.001 seconds
DEBUG   - QEMU (7374): ===================================================================
DEBUG   - QEMU (7374): TESTSUITE test_tracing succeeded
DEBUG   - QEMU (7374): ===================================================================
DEBUG   - QEMU (7374): RunID: 582b8dd78d6763d395ad50bec0632e8b
DEBUG   - QEMU (7374): PROJECT EXECUTION SUCCESSFUL
DEBUG   - QEMU (7382): SeaBIOS (version zephyr-v1.0.0-0-g31d4e0e-dirty-20200714_234759-fv-az50-zephyr)
DEBUG   - QEMU (7382): Booting from ROM..
DEBUG   - QEMU (7382): *** Booting Zephyr OS build zephyr-v3.1.0-4097-g80f848e4a4fe  ***
DEBUG   - QEMU (7382): Running TESTSUITE test_tracing
DEBUG   - QEMU (7382): ===================================================================
DEBUG   - QEMU (7382): START - test_tracing_sys_api
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7382): PASS - test_tracing_sys_api in 0.119 seconds
DEBUG   - QEMU (7382): ===================================================================
DEBUG   - QEMU (7382): START - test_tracing_data_format
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7382): PASS - test_tracing_data_format in 0.215 seconds
DEBUG   - QEMU (7382): ===================================================================
DEBUG   - QEMU (7382): START - test_tracing_cmd_manual
DEBUG   - QEMU (7382): PASS - test_tracing_cmd_manual in 0.001 seconds
DEBUG   - QEMU (7382): ===================================================================
DEBUG   - QEMU (7382): TESTSUITE test_tracing succeeded
DEBUG   - QEMU (7382): ===================================================================
DEBUG   - QEMU (7382): RunID: a6cbfa22e32703d9ae4a088c104622ad
DEBUG   - QEMU (7382): PROJECT EXECUTION SUCCESSFUL
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7382): -=-=-=-=backend is running-=-=-=-=
DEBUG   - QEMU (7374) complete (passed) after 2.094356060028076 seconds
DEBUG   - QEMU (7382) complete (passed) after 2.095092296600342 seconds
DEBUG   - No timeout, return code from QEMU (None): 0
DEBUG   - return code from QEMU (None): 0
DEBUG   - run status: qemu_x86/tests/subsys/tracing/tracing_api/tracing.transport.uart.sync.test passed
INFO    - 1/2 qemu_x86                  tests/subsys/tracing/tracing_api/tracing.transport.uart.sync.test PASSED (qemu 2.094s)
DEBUG   - No timeout, return code from QEMU (None): 0
DEBUG   - return code from QEMU (None): 0
DEBUG   - run status: qemu_x86/tests/subsys/tracing/tracing_api/tracing.transport.uart.async.test passed
INFO    - 2/2 qemu_x86                  tests/subsys/tracing/tracing_api/tracing.transport.uart.async.test PASSED (qemu 2.095s)

And migrate to new ZTEST API, the log as below:

*** Booting Zephyr OS build zephyr-v3.1.0-4097-g80f848e4a4fe  ***
-=-=-=-=backend is running-=-=-=-=
-=-=-=-=backend is running-=-=-=-=
Running TESTSUITE tracing
===================================================================
START - test_tracing_cmd_manual
 PASS - test_tracing_cmd_manual in 0.002 seconds
===================================================================
START - test_tracing_data_format

    Assertion failed at WEST_TOPDIR/zephyr/tests/subsys/tracing/tracing_api/src/main.c:229: tracing_test_tracing_data_format: (data_format_found == true is false)
Failed to check output from backend
 FAIL - test_tracing_data_format in 0.110 seconds
===================================================================
START - test_tracing_sys_api

    Assertion failed at WEST_TOPDIR/zephyr/tests/subsys/tracing/tracing_api/src/main.c:203: tracing_test_tracing_sys_api: (sync_string_format_found == true is false)
Failed to check output from backend
 FAIL - test_tracing_sys_api in 0.110 seconds
===================================================================
TESTSUITE tracing failed.

As you can see, when I migrated testcases to new ZTEST API, when the testsuite is running, the backend log printk("-=-=-=-=backend is running-=-=-=-=") is stopped. I don't know what's wrong with this, so issue a bug here.

[hwang37]

@Zhaoningx could you please continue working with @mengxianglinx @enjiamai on it?

[nashif]

this is an issue you found while converting a test to the new API, it does not exist in the current code, is this really a bug? This could be a bug in the way you are trying to convert?

[nashif]

Do not see how this is tracing related.

[mengxianglinx]

When convert test to new API, test cases run in different order than before, that exposes bug in tracing_backends_output().
Every test case should be standalone.
It is not tracing related.