subsys: logging: log_core_additional: test_log_domain_id Twister reports fails even the test passed

[arikgreen]

Describe the bug

The fail was observed on platforms:

• intel_adsp/ace15_mtpm
• intel_adsp/cavs25
• up_squared/apollo_lake

The twister reporting fail in twister.json file for this test:

{
    "name":"logging.thread",
    "arch":"xtensa",
    "platform":"intel_adsp/cavs25",
    "path":"tests/subsys/logging/log_core_additional",
    "run_id":"18da6c8e0a8773ff3bd612de2bb0ac71",
    "runnable":true,
    "retries":0,
    "toolchain":"zephyr",
    "status":"passed",
    "execution_time":"10.25",
    "build_time":"40.24",
    "testcases":[
        {
            "identifier":"test_log_core_additional.log_msg_create",
            "execution_time":"0.20",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_generic",
            "execution_time":"0.20",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_thread_trigger",
            "execution_time":"0.00",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_thread",
            "execution_time":"2.00",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.multiple_backends",
            "execution_time":"0.00",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_timestamping",
            "execution_time":"0.20",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_severity",
            "execution_time":"0.20",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_early_logging",
            "execution_time":"0.20",
            "status":"passed"
        },
        {
            "identifier":"test_log_core_additional.log_sync",
            "execution_time":"0.00",
            "status":"skipped",
            "reason":"ztest skip"
        },
        {
            "identifier":"test_log_core_additional.log_domain_id",
            "execution_time":"0.00",
            "status":"failed"
        },
        {
            "identifier":"test_log_core_additional.log_backend",
            "execution_time":"0.00",
            "status":"passed"
        }
    ]
},

but this test passed and the twister.log confirmed it:

2025-03-25 03:25:25,380 - twister - DEBUG - DEVICE: *** Booting Zephyr OS build 4.1.99 (delayed boot 500ms) ***
2025-03-25 03:25:25,479 - twister - DEBUG - DEVICE: Running TESTSUITE test_log_core_additional
2025-03-25 03:25:25,480 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:25,579 - twister - DEBUG - DEVICE: START - test_log_backend
2025-03-25 03:25:25,580 - twister - DEBUG - DEVICE: PASS - test_log_backend in 0.001 seconds
2025-03-25 03:25:25,581 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:25,615 - twister - DEBUG - Finished running cmake tests/subsys/logging/log_timestamp for intel_adsp/cavs25 in 9.97 seconds
2025-03-25 03:25:25,617 - twister - DEBUG - build test: intel_adsp/cavs25/zephyr/logging.output.default_timestamp
2025-03-25 03:25:25,617 - twister - DEBUG - Building tests/subsys/logging/log_timestamp for intel_adsp/cavs25
2025-03-25 03:25:25,618 - twister - DEBUG - Running /usr/bin/cmake --build twister-out/intel_adsp_cavs25/zephyr/tests/subsys/logging/log_timestamp/logging.output.default_timestamp
2025-03-25 03:25:25,679 - twister - DEBUG - DEVICE: START - test_log_domain_id
2025-03-25 03:25:25,805 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0[00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-25 03:25:25,903 - twister - DEBUG - DEVICE: .201 seconds
2025-03-25 03:25:25,904 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:25,905 - twister - DEBUG - DEVICE: START - test_log_early_logging
2025-03-25 03:25:25,905 - twister - DEBUG - DEVICE: Create log message before backend active
2025-03-25 03:25:25,987 - twister - DEBUG - -- west flash: using runner intel_adsp
-- runners.intel_adsp: Starting Intel ADSP runner

2025-03-25 03:25:26,077 - twister - DEBUG - DEVICE: Activate backend with context PASS - test_log_early_logging in 0.201 seconds
2025-03-25 03:25:26,178 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:26,278 - twister - DEBUG - DEVICE: START - test_log_generic
2025-03-25 03:25:26,380 - twister - DEBUG - DEVICE: PASS - test_log_generic in 0.201 seconds
2025-03-25 03:25:26,481 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:26,580 - twister - DEBUG - DEVICE: START - test_log_msg_create
2025-03-25 03:25:26,683 - twister - DEBUG - DEVICE: PASS - test_log_msg_create in 0.201 seconds
2025-03-25 03:25:26,784 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:26,884 - twister - DEBUG - DEVICE: START - test_log_severity
2025-03-25 03:25:26,986 - twister - DEBUG - DEVICE: PASS - test_log_severity in 0.201 seconds
2025-03-25 03:25:27,087 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:27,186 - twister - DEBUG - DEVICE: START - test_log_sync
2025-03-25 03:25:27,187 - twister - DEBUG - DEVICE: Logging synchronously
2025-03-25 03:25:27,188 - twister - DEBUG - DEVICE: SKIP - test_log_sync in 0.001 seconds
2025-03-25 03:25:27,189 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:27,287 - twister - DEBUG - DEVICE: START - test_log_thread
2025-03-25 03:25:27,288 - twister - DEBUG - DEVICE: Logging buffer is configured to 1024 bytes
2025-03-25 03:25:27,290 - twister - DEBUG - DEVICE: Stack size of logging thread is configured by CONFIG_LOG_PROCESS_THREAD_STACK_SIZE: 1024 bytes
2025-03-25 03:25:27,857 - twister - DEBUG - Finished building tests/subsys/logging/log_core_additional for intel_adsp/cavs25 in 27.18 seconds
2025-03-25 03:25:27,857 - twister - DEBUG - Determine test cases for test instance: intel_adsp/cavs25/zephyr/logging.sync
2025-03-25 03:25:27,857 - twister - DEBUG - Determine test cases for test suite: logging.sync
2025-03-25 03:25:27,943 - twister - DEBUG - Test instance intel_adsp/cavs25/zephyr/logging.sync already has 17 testcase(s) known: [<TestCase test_log_core_additional.log_backend with None>, <TestCase test_log_core_additional.log_hexdump_from_user with None>, <TestCase test_log_core_additional.log_msg_create_user with None>, <TestCase test_log_core_additional.log_filter_set with None>, <TestCase test_log_core_additional.log_generic_user with None>, <TestCase test_log_core_additional.log_severity with None>, <TestCase test_log_core_additional.log_generic with None>, <TestCase test_log_core_additional.log_timestamping with None>, <TestCase test_log_core_additional.log_sync with None>, <TestCase test_log_core_additional.log_early_logging with None>, <TestCase test_log_core_additional.log_thread with None>, <TestCase test_log_core_additional.log_panic with None>, <TestCase test_log_core_additional.multiple_backends with None>, <TestCase test_log_core_additional.log_msg_create with None>, <TestCase test_log_core_additional.log_domain_id with None>, <TestCase test_log_core_additional.log_thread_trigger with None>, <TestCase test_log_core_additional.log_from_user with None>]
2025-03-25 03:25:27,943 - twister - DEBUG - Detected 11 Ztest case(s): [test_log_core_additional.log_msg_create, test_log_core_additional.log_generic, test_log_core_additional.log_thread_trigger, test_log_core_additional.log_thread, test_log_core_additional.multiple_backends, test_log_core_additional.log_timestamping, test_log_core_additional.log_severity, test_log_core_additional.log_early_logging, test_log_core_additional.log_sync, test_log_core_additional.log_domain_id, test_log_core_additional.log_backend] in twister-out/intel_adsp_cavs25/zephyr/tests/subsys/logging/log_core_additional/logging.sync/zephyr/zephyr.elf
2025-03-25 03:25:27,947 - twister - DEBUG - run test: intel_adsp/cavs25/zephyr/logging.sync
2025-03-25 03:25:27,948 - twister - DEBUG - Reset instance status from 'passed' to None before run.
2025-03-25 03:25:29,194 - twister - DEBUG - DEVICE: PASS - test_log_thread in 2.001 seconds
2025-03-25 03:25:29,293 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:29,294 - twister - DEBUG - DEVICE: START - test_log_thread_trigger
2025-03-25 03:25:29,295 - twister - DEBUG - DEVICE: PASS - test_log_thread_trigger in 0.002 seconds
2025-03-25 03:25:29,296 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:29,406 - twister - DEBUG - DEVICE: START - test_log_timestamping
2025-03-25 03:25:29,506 - twister - DEBUG - DEVICE: Register timestamp function
2025-03-25 03:25:29,606 - twister - DEBUG - DEVICE: PASS - test_log_timestamping in 0.201 seconds
2025-03-25 03:25:29,607 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:29,716 - twister - DEBUG - DEVICE: START - test_multiple_backends
2025-03-25 03:25:29,817 - twister - DEBUG - DEVICE: Test multiple backends PASS - test_multiple_backends in 0.001 seconds
2025-03-25 03:25:29,818 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:29,819 - twister - DEBUG - DEVICE: TESTSUITE test_log_core_additional succeeded
2025-03-25 03:25:29,820 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY START ------
2025-03-25 03:25:29,821 - twister - DEBUG - DEVICE: SUITE PASS - 100.00% [test_log_core_additional]: pass = 10, fail = 0, skip = 1, total = 11 duration = 3.212 seconds
2025-03-25 03:25:29,822 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_backend] duration = 0.001 seconds
2025-03-25 03:25:29,823 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_domain_id] duration = 0.201 seconds
2025-03-25 03:25:29,824 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_early_logging] duration = 0.201 seconds
2025-03-25 03:25:29,825 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_generic] duration = 0.201 seconds
2025-03-25 03:25:29,826 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_msg_create] duration = 0.201 seconds
2025-03-25 03:25:29,827 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_severity] duration = 0.201 seconds
2025-03-25 03:25:29,828 - twister - DEBUG - DEVICE: - SKIP - [test_log_core_additional.test_log_sync] duration = 0.001 seconds
2025-03-25 03:25:29,829 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_thread] duration = 2.001 seconds
2025-03-25 03:25:29,830 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_thread_trigger] duration = 0.002 seconds
2025-03-25 03:25:29,831 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_timestamping] duration = 0.201 seconds
2025-03-25 03:25:29,832 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_multiple_backends] duration = 0.001 seconds
2025-03-25 03:25:29,833 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY END ------
2025-03-25 03:25:29,833 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:25:29,834 - twister - DEBUG - DEVICE: RunID: 18da6c8e0a8773ff3bd612de2bb0ac71
2025-03-25 03:25:29,834 - twister - DEBUG - DEVICE: PROJECT EXECUTION SUCCESSFUL

In the twister.log we see corrupted line for this test. In the same line we see mixed two lines:

2025-03-25 03:25:25,805 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0[00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-25 03:25:25,903 - twister - DEBUG - DEVICE: .201 seconds

The correct output should seems that:

2025-03-25 03:25:25,805 - twister - DEBUG - DEVICE: [00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-25 03:25:25,903 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0.201 seconds

To Reproduce

have one of above platform connected
go to your zephyr directory and setup env
call ./scripts/twister -T tests/subsys/logging/log_core_additional -p intel_adsp/cavs25 --device-testing --device-serial-pty="$ZEPHYR_BASE/soc/intel/intel_adsp/tools/cavstool_client.py,-s,remotehostname,-l" -v --inline-logs
See console output with test suite passed and all test cases passed but in the twister.json file the test log_domain_id is failed.

Expected behavior

Impact

twister.json file - reporting feature in twister

Environment (please complete the following information):

• OS: Linux 24
• Zephyr version: v4.1.0-1193-gbc5a60c812ba

Additional information
These are logs from up_squared/apollo_lake

2025-03-25 04:06:14,853 - twister - DEBUG - DEVICE: *** Booting Zephyr OS build 4.1.99 (delayed boot 500ms) ***
2025-03-25 04:06:14,867 - twister - DEBUG - DEVICE: Running TESTSUITE test_log_core_additional
2025-03-25 04:06:14,874 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 04:06:14,876 - twister - DEBUG - DEVICE: START - test_log_backend
2025-03-25 04:06:14,881 - twister - DEBUG - DEVICE: PASS - test_log_backend in 0.001 seconds
2025-03-25 04:06:14,887 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 04:06:14,890 - twister - DEBUG - DEVICE: START - test_log_domain_id
2025-03-25 04:06:15,098 - twister - DEBUG - DEVICE: PA[S0S0 :-0 0t:e0s0t._5l5o3g,_0d0o0m]a i�n[_0imd< iinnf >0 .l2o0g1_ tseescto:n disn
2025-03-25 04:06:15,105 - twister - DEBUG - DEVICE: f=o= =m=e=s=s=a=g=e= =f=o=r= =d=o=m=a=i=n= =i=d= =t=e=s=t=�=[=0=m=
2025-03-25 04:06:15,105 - twister - DEBUG - DEVICE: =
2025-03-25 04:06:15,108 - twister - DEBUG - DEVICE: =================================

and the wrong lines in the twister.log file

2025-03-25 04:06:15,098 - twister - DEBUG - DEVICE: PA[S0S0 :-0 0t:e0s0t._5l5o3g,_0d0o0m]a i�n[_0imd< iinnf >0 .l2o0g1_ tseescto:n disn
2025-03-25 04:06:15,105 - twister - DEBUG - DEVICE: f=o= =m=e=s=s=a=g=e= =f=o=r= =d=o=m=a=i=n= =i=d= =t=e=s=t=�=[=0=m=
2025-03-25 04:06:15,105 - twister - DEBUG - DEVICE: =

The same result as for cavs25 in twister.json file - the test test_log_core_additional.log_domain_id is set as failed

{
	"name":"logging.thread",
	"arch":"x86",
	"platform":"up_squared/apollo_lake",
	"path":"tests/subsys/logging/log_core_additional",
	"run_id":"0f235514c5ab137903552f9dcd02f96c",
	"runnable":true,
	"toolchain":"zephyr",
	"status":"passed",
	"execution_time":"38.85",
	"build_time":"51.18",
	"testcases":[
		{
			"identifier":"test_log_core_additional.log_msg_create",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_generic",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_thread_trigger",
			"execution_time":"0.00",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_thread",
			"execution_time":"2.01",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.multiple_backends",
			"execution_time":"0.00",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_timestamping",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_severity",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_early_logging",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_sync",
			"execution_time":"0.00",
			"status":"skipped",
			"reason":"ztest skip"
		},
		{
			"identifier":"test_log_core_additional.log_domain_id",
			"execution_time":"0.00",
			"status":"failed"
		},
		{
			"identifier":"test_log_core_additional.log_backend",
			"execution_time":"0.00",
			"status":"passed"
		}
	]
}

and the same issue on ace15

2025-03-25 03:13:35,542 - twister - DEBUG - DEVICE: INFO:cavs-client:Receive: start_log
2025-03-25 03:13:35,543 - twister - DEBUG - DEVICE: INFO:cavs-client:Start to monitor log output...
2025-03-25 03:13:35,928 - twister - DEBUG - DEVICE: --
2025-03-25 03:13:36,028 - twister - DEBUG - DEVICE: ***** delaying boot 500ms (per build configuration) *****
2025-03-25 03:13:36,206 - twister - DEBUG - DEVICE: *** Booting Zephyr OS build 4.1.99 (delayed boot 500ms) ***
2025-03-25 03:13:36,306 - twister - DEBUG - DEVICE: Running TESTSUITE test_log_core_additional
2025-03-25 03:13:36,306 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:36,306 - twister - DEBUG - DEVICE: START - test_log_backend
2025-03-25 03:13:36,307 - twister - DEBUG - DEVICE: PASS - test_log_backend in 0.001 seconds
2025-03-25 03:13:36,307 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:36,406 - twister - DEBUG - DEVICE: START - test_log_domain_id
2025-03-25 03:13:36,608 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0.2[00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-25 03:13:36,707 - twister - DEBUG - DEVICE: 01 seconds
2025-03-25 03:13:36,708 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:36,708 - twister - DEBUG - DEVICE: START - test_log_early_logging
2025-03-25 03:13:36,708 - twister - DEBUG - DEVICE: Create log message before backend active
2025-03-25 03:13:36,917 - twister - DEBUG - DEVICE: Activate backend with context PASS - test_log_early_logging in 0.201 seconds
2025-03-25 03:13:37,017 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:37,017 - twister - DEBUG - DEVICE: START - test_log_generic
2025-03-25 03:13:37,195 - twister - DEBUG - DEVICE: PASS - test_log_generic in 0.201 seconds
2025-03-25 03:13:37,294 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:37,394 - twister - DEBUG - DEVICE: START - test_log_msg_create
2025-03-25 03:13:37,503 - twister - DEBUG - DEVICE: PASS - test_log_msg_create in 0.201 seconds
2025-03-25 03:13:37,602 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:37,603 - twister - DEBUG - DEVICE: START - test_log_severity
2025-03-25 03:13:37,791 - twister - DEBUG - Waiting for a DUT to run intel_adsp/ace15_mtpm/zephyr/logging.output.ts64.date.fulllibc
2025-03-25 03:13:37,812 - twister - DEBUG - DEVICE: PASS - test_log_severity in 0.201 seconds
2025-03-25 03:13:37,912 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:37,912 - twister - DEBUG - DEVICE: START - test_log_sync
2025-03-25 03:13:37,913 - twister - DEBUG - DEVICE: Logging synchronously
2025-03-25 03:13:37,913 - twister - DEBUG - DEVICE: SKIP - test_log_sync in 0.001 seconds
2025-03-25 03:13:37,913 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:38,012 - twister - DEBUG - DEVICE: START - test_log_thread
2025-03-25 03:13:38,012 - twister - DEBUG - DEVICE: Logging buffer is configured to 1024 bytes
2025-03-25 03:13:38,013 - twister - DEBUG - DEVICE: Stack size of logging thread is configured by CONFIG_LOG_PROCESS_THREAD_STACK_SIZE: 1024 bytes
2025-03-25 03:13:40,002 - twister - DEBUG - DEVICE: PASS - test_log_thread in 2.001 seconds
2025-03-25 03:13:40,102 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:40,102 - twister - DEBUG - DEVICE: START - test_log_thread_trigger
2025-03-25 03:13:40,102 - twister - DEBUG - DEVICE: PASS - test_log_thread_trigger in 0.002 seconds
2025-03-25 03:13:40,103 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:40,218 - twister - DEBUG - DEVICE: START - test_log_timestamping
2025-03-25 03:13:40,317 - twister - DEBUG - DEVICE: Register timestamp function
2025-03-25 03:13:40,418 - twister - DEBUG - DEVICE: PASS - test_log_timestamping in 0.201 seconds
2025-03-25 03:13:40,419 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:40,519 - twister - DEBUG - DEVICE: START - test_multiple_backends
2025-03-25 03:13:40,519 - twister - DEBUG - DEVICE: Test multiple backends PASS - test_multiple_backends in 0.001 seconds
2025-03-25 03:13:40,520 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:40,520 - twister - DEBUG - DEVICE: TESTSUITE test_log_core_additional succeeded
2025-03-25 03:13:40,520 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY START ------
2025-03-25 03:13:40,521 - twister - DEBUG - DEVICE: SUITE PASS - 100.00% [test_log_core_additional]: pass = 10, fail = 0, skip = 1, total = 11 duration = 3.212 seconds
2025-03-25 03:13:40,522 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_backend] duration = 0.001 seconds
2025-03-25 03:13:40,522 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_domain_id] duration = 0.201 seconds
2025-03-25 03:13:40,523 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_early_logging] duration = 0.201 seconds
2025-03-25 03:13:40,523 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_generic] duration = 0.201 seconds
2025-03-25 03:13:40,523 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_msg_create] duration = 0.201 seconds
2025-03-25 03:13:40,524 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_severity] duration = 0.201 seconds
2025-03-25 03:13:40,524 - twister - DEBUG - DEVICE: - SKIP - [test_log_core_additional.test_log_sync] duration = 0.001 seconds
2025-03-25 03:13:40,525 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_thread] duration = 2.001 seconds
2025-03-25 03:13:40,525 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_thread_trigger] duration = 0.002 seconds
2025-03-25 03:13:40,526 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_log_timestamping] duration = 0.201 seconds
2025-03-25 03:13:40,526 - twister - DEBUG - DEVICE: - PASS - [test_log_core_additional.test_multiple_backends] duration = 0.001 seconds
2025-03-25 03:13:40,527 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY END ------
2025-03-25 03:13:40,527 - twister - DEBUG - DEVICE: ===================================================================
2025-03-25 03:13:40,527 - twister - DEBUG - DEVICE: RunID: 9bb685407df1da6bee4c89f37990408b
2025-03-25 03:13:40,528 - twister - DEBUG - DEVICE: PROJECT EXECUTION SUCCESSFUL

corrupted lines:

2025-03-25 03:13:36,608 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0.2[00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-25 03:13:36,707 - twister - DEBUG - DEVICE: 01 seconds

Part of twister.json from this run

{
	"name":"logging.thread",
	"arch":"xtensa",
	"platform":"intel_adsp/ace15_mtpm",
	"path":"tests/subsys/logging/log_core_additional",
	"run_id":"9bb685407df1da6bee4c89f37990408b",
	"runnable":true,
	"toolchain":"zephyr",
	"status":"passed",
	"execution_time":"15.19",
	"build_time":"33.06",
	"testcases":[
		{
			"identifier":"test_log_core_additional.log_msg_create",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_generic",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_thread_trigger",
			"execution_time":"0.00",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_thread",
			"execution_time":"2.00",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.multiple_backends",
			"execution_time":"0.00",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_timestamping",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_severity",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_early_logging",
			"execution_time":"0.20",
			"status":"passed"
		},
		{
			"identifier":"test_log_core_additional.log_sync",
			"execution_time":"0.00",
			"status":"skipped",
			"reason":"ztest skip"
		},
		{
			"identifier":"test_log_core_additional.log_domain_id",
			"execution_time":"0.00",
			"status":"failed"
		},
		{
			"identifier":"test_log_core_additional.log_backend",
			"execution_time":"0.00",
			"status":"passed"
		}
	]
}

[nashif]

call ./scripts/twister -T tests/subsys/logging/log_core_additional -p intel_adsp/cavs25 --device-testing --device-serial /dev/ttyACM0 -v --inline-logs

that does not make sense. cavs25 does not have ttyACM0

[arikgreen]

call ./scripts/twister -T tests/subsys/logging/log_core_additional -p intel_adsp/cavs25 --device-testing --device-serial /dev/ttyACM0 -v --inline-logs

that does not make sense. cavs25 does not have ttyACM0

sorry, I forgot change this parameter. I changed in description.

[arikgreen]

@nashif I appended to the description the logs from up2 and ace15_mtpm

[golowanow]

I think there is at least 2 problems here to investigate and resolve

1. log_domain_id test LOG_INF output messed with Ztest result and to me it looks actually as a failure for this test case of logging subsystem.

zephyr/tests/subsys/logging/log_core_additional/src/log_test.c

Lines 219 to 222 in ca0f5f6

	LOG_INF("info message for domain id test");
	while (log_test_process()) {
	}

START - test_log_domain_id
 PASS - test_log_domain_id in 0[00:00:00.701,000] <inf> log_test: info message for domain id test
.201 seconds

2. Twister Ztest harness in this situation has no match on the test case result (pattern not match on the corrupted line), but the suite summary entry should also update test case status as passed. For some reason it wasn't done, or changed to failed.
   It would be helpful to repeat this situation with additional trace logs running twister with -vvv

[arikgreen]

in this case, always are mixed the log message from line 219 and the summary for this test case

zephyr/tests/subsys/logging/log_core_additional/src/log_test.c

Lines 212 to 226 in ca0f5f6

	ZTEST(test_log_core_additional, test_log_domain_id)
	{
	log_setup(false);
	backend1_cb.check_domain_id = true;
	backend1_cb.total_logs = 1;
	LOG_INF("info message for domain id test");
	while (log_test_process()) {
	}
	zassert_equal(backend1_cb.total_logs, backend1_cb.counter,
	"Unexpected amount of messages received by the backend");
	}

There is the simple workaround for it:
add 250ms sleep between LOG_INF() and zassert_equal()
After that LOG_INF return right message before the test case return summary message:

2025-03-28 14:09:15,613 - twister - DEBUG - DEVICE: ===================================================================
2025-03-28 14:09:15,712 - twister - DEBUG - DEVICE: START - test_log_domain_id
2025-03-28 14:09:15,712 - twister - DEBUG - TC_START: Ztest case 'log_domain_id' matched to 'logging.thread.test_log_core_additional.log_domain_id
2025-03-28 14:09:15,835 - twister - DEBUG - DEVICE: [00:00:00.701,000] <inf> log_test: info message for domain id test
2025-03-28 14:09:15,936 - twister - DEBUG - DEVICE: PASS - test_log_domain_id in 0.251 seconds
2025-03-28 14:09:15,936 - twister - DEBUG - TC_END: Ztest case 'log_domain_id' matched to 'logging.thread.test_log_core_additional.log_domain_id
2025-03-28 14:09:15,936 - twister - DEBUG - TC_END: END case 'logging.thread.test_log_core_additional.log_domain_id':{'count': 1}
2025-03-28 14:09:15,937 - twister - DEBUG - DEVICE: ===================================================================

@golowanow

Twister Ztest harness in this situation has no match on the test case result (pattern not match on the corrupted line), but the suite summary entry should also update test case status as passed. For some reason it wasn't done, or changed to failed.
It would be helpful to repeat this situation with additional trace logs running twister with -vvv

In the harness Test a status of test case is changed to Failed because regex pattern test_case_end_pattern not match line in a log.

zephyr/scripts/pylib/twister/twisterlib/harness.py

Lines 909 to 926 in ca0f5f6

	# some testcases are skipped based on predicates and do not show up
	# during test execution, however they are listed in the summary. Parse
	# the summary for status and use that status instead.
	elif result_match := self.test_case_end_pattern.match(line):
	matched_status = result_match.group(1)
	tc_name = result_match.group(3)
	tc = self.get_testcase(tc_name, 'TC_END')
	self.end_case(tc.name)
	tc.status = TwisterStatus[matched_status]
	if tc.status == TwisterStatus.SKIP:
	tc.reason = "ztest skip"
	tc.duration = float(result_match.group(4))
	if tc.status == TwisterStatus.FAIL:
	tc.output = self.testcase_output
	self.testcase_output = ""
	self._match = False
	self.ztest = True
	elif test_suite_summary_match := self.test_suite_summary_pattern.match(line):

[golowanow]

@arikgreen

In the harness Test a status of test case is changed to Failed because regex pattern test_case_end_pattern not match line in a log.

yeah, (see my comment 2.) and that's exactly why my ask is to reproduce the issue running twister with -vvv to trace how match happens in this particular case.