sanitycheck log mixing between tests

[ABOSTM]

Describe the bug
When running sanitycheck on all tests of directory tests\arch\arm, there is some mixing in logs.
This mixing causes, from time to time, in test PASSED, but reported Failed.
All run doesn't give always the same result (not always test failed , not always the same mixing)
But the failed test is always tests/arch/arm/arm_irq_vector_table (even if I think it is just a combination of circumstances). And it is not always failed on the same board.
Note: tests is launched on a bunch of STM32 board:
nucleo_f207zg, nucleo_f429zi, nucleo_f746zg, nucleo_l152re, nucleo_l4r5zi, nucleo_wb55rg, stm32f3_disco
Thoses tests run everyday on bench and failure occurs at least on 1 board about every day or every 2 days.

To Reproduce
Command to reproduce (require all boards to be connected):
sanitycheck --ninja --warnings-as-errors --runtime-artifact-cleanup -p nucleo_f207zg -p nucleo_f429zi -p nucleo_f746zg -p nucleo_l152re -p nucleo_l4r5zi -p nucleo_wb55rg -p stm32f3_disco -T tests/arch/arm/ --hardware-map ../map.yaml --device-testing --outdir /local/mcu/zephyrproject/logs/200528/log_job_master_d8560f698b_1503 [log_job_master_d8560f698b_1503.zip](https://github.com/zephyrproject-rtos/zephyr/files/4697102/log_job_master_d8560f698b_1503.zip) [log_job_master_d8560f698b_1503.zip](https://github.com/zephyrproject-rtos/zephyr/files/4697103/log_job_master_d8560f698b_1503.zip)

Log mixing
Hereafter some example of mixing (see zip file):
log_job_master_d8560f698b_1503\nucleo_f746zg\tests\arch\arm\arm_interrupt\arch.interrupt.arm\handler.log
--> "Running test suite arm_thread_swap"

log_job_master_d8560f698b_1503\nucleo_l4r5zi\tests\arch\arm\arm_irq_vector_table\arch.interrupt.arm.irq_vector_table\handler.log
--> "Running test suite arm_thread_swap"

log_job_master_d8560f698b_1503\nucleo_f746zg\tests\arch\arm\arm_ramfunc\arch.arm.ramfunc\handler.log
--> "Running test suite arm_thread_swap"

log_job_master_d8560f698b_1503\nucleo_f746zg\tests\arch\arm\arm_interrupt\arch.interrupt.arm\handler.log
--> "Running test suite arm_thread_swap"

c:\tmps\log_zephyr\log_job_master_d8560f698b_1503\nucleo_f429zi\tests\arch\arm\arm_interrupt\arch.interrupt.no_optimizations\handler.log
--> "Running test suite arm_thread_swap"

c:\tmps\log_zephyr\log_job_master_d8560f698b_1503\nucleo_l4r5zi\tests\arch\arm\arm_interrupt\arch.interrupt.no_optimizations\handler.log
--> "Running test suite vector_table"

(And more, I do not mention all of mixing)

The stranger mixing corresponding to failed case:
log_job_master_d8560f698b_1503\nucleo_f429zi\tests\arch\arm\arm_irq_vector_table\arch.interrupt.arm.irq_vector_table\handler.log
It starts with a test "arm_iunterrupt" and finishes with another test "vector_table"
--> "Running test suite arm_interrupt"
--> "Test suite vector_table succeeded"

So it looks like a sanitycheck issue, parsing/splitting console logs.

I attache a zip file containing all logs in there respective directories.

[ABOSTM]

log_job_master_d8560f698b_1503.zip

[ABOSTM]

I found similar mixing when running:

• sanitycheck -N --device-testing --hardware-map ../map.yaml -c -p nucleo_f746zg -T samples/drivers/watchdog/ -T samples/drivers/can/
• sanitycheck -N --device-testing --hardware-map ../map.yaml -c-p nucleo_f303re -T tests/kernel/mem_slab

[carlescufi]

@nashif could you take a look?
CC @PerMac

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[PerMac]

I observed the same (similar?) issue when running on-target tests in our setup. Sometimes a test case is reported as failed in the platform.xml report but the failure message indicates something went wrong since the logs are from different test. E.g.:

<testcase classname="sample.kernel" name="sample.kernel.philosopher.stacks" time="5.862062">
<failure message="failed" type="failure">
time_nmi =================================================================== Test suite arm_runtime_nmi_fn succeeded =================================================================== PROJECT EXECUTION SUCCESSFUL
</failure>
</testcase>

[PerMac]

This looks like a higher priority than low (probably medium). Currently, this is the issue that prevents us from having green builds. During most of the runs, it happens that there is one false positive due to this error. It also seems that a test which failed due to this is not repeated with --retry-failed. @nashif I can try making a patch that will fix retrying of such cases for now, but it won't be the solution for log/results mixing.

[PerMac]

FYI: Most of the time I see this output leaking into other tests and causing them to fail:

arm_runtime_nmi
===================================================================
Test suite arm_runtime_nmi_fn succeeded
===================================================================
PROJECT EXECUTION SUCCESSFUL

[nashif]

fixed by #32784