twister : tests report: project execution failed without any testsuites failed

[djiatsaf-st]

Describe the bug
This PR #86383 Convert SPI Loopback test to ZTEST
and introduce in particular the use of zassume_false and zassume_true.

While running the test on STM32 boards, we realized that the project test report was failed yet there is no testsuite failed.
It could be that twister considers assumption failed is the same as assertion failed when report tests status.

In twister.json :

"name":"tests/drivers/spi/spi_loopback/drivers.spi.stm32_spi_dma.loopback",
            "arch":"arm",
            "platform":"nucleo_h743zi/stm32h743xx",
            "path":"tests/drivers/spi/spi_loopback",
            "run_id":"1b3142779eb930bec9ba2678bd9e3394",
            "runnable":true,
            "retries":0,
            "toolchain":"zephyr",
            "status":"failed",
            "log":"*** Booting Zephyr OS build v4.1.0-rc2-103-g2cf6b7ee643f ***\r\nSPI test on buffers TX/RX 0x240040a0/0x24004080, frame size = 8, DMA enabled (without CONFIG_NOCACHE_MEMORY)\r\nRunning TESTSUITE spi_extra_api_features\r\n===================================================================\r\nSTART - test_spi_lock_release\r\n PASS - test_spi_lock_release in 0.001 seconds\r\n===================================================================\r\nTESTSUITE spi_extra_api_features succeeded\r\nRunning TESTSUITE spi_extra_api_features\r\n===================================================================\r\nSTART - test_spi_lock_release\r\n PASS - test_spi_lock_release in 0.001 seconds\r\n===================================================================\r\nTESTSUITE spi_extra_api_features succeeded\r\nRunning TESTSUITE spi_loopback\r\n===================================================================\r\nTesting loopback spec: SLOW\r\nSTART - test_spi_complete_large_transfers\r\n PASS - test_spi_complete_large_transfers in 0.141 seconds\r\n===================================================================\r\nSTART - test_spi_complete_loop\r\n PASS - test_spi_complete_loop in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_complete_multiple\r\n PASS - test_spi_complete_multiple in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_null_tx_buf\r\n PASS - test_spi_null_tx_buf in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_rx_bigger_than_tx\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:274: spi_loopback_test_spi_rx_bigger_than_tx: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true\r\n\r\n SKIP - test_spi_rx_bigger_than_tx in 0.019 seconds\r\n===================================================================\r\nSTART - test_spi_rx_every_4\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:251: spi_loopback_test_spi_rx_every_4: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true\r\n\r\n SKIP - test_spi_rx_every_4 in 0.018 seconds\r\n===================================================================\r\nSTART - test_spi_rx_half_end\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:232: spi_loopback_test_spi_rx_half_end: IS_ENABLED(CONFIG_SPI_STM32_DMA) is true\r\n\r\n SKIP - test_spi_rx_half_end in 0.015 seconds\r\n===================================================================\r\nSTART - test_spi_rx_half_start\r\n PASS - test_spi_rx_half_start in 0.001 seconds\r\n===================================================================\r\nTESTSUITE spi_loopback succeeded\r\nRunning TESTSUITE spi_loopback\r\n===================================================================\r\nTesting loopback spec: FAST\r\nSTART - test_spi_complete_large_transfers\r\n PASS - test_spi_complete_large_transfers in 0.005 seconds\r\n===================================================================\r\nSTART - test_spi_complete_loop\r\n PASS - test_spi_complete_loop in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_complete_multiple\r\n PASS - test_spi_complete_multiple in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_null_tx_buf\r\n PASS - test_spi_null_tx_buf in 0.001 seconds\r\n===================================================================\r\nSTART - test_spi_rx_bigger_than_tx\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:274: spi_loopback_test_spi_rx_bigger_than_tx: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true\r\n\r\n SKIP - test_spi_rx_bigger_than_tx in 0.019 seconds\r\n===================================================================\r\nSTART - test_spi_rx_every_4\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:251: spi_loopback_test_spi_rx_every_4: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true\r\n\r\n SKIP - test_spi_rx_every_4 in 0.018 seconds\r\n===================================================================\r\nSTART - test_spi_rx_half_end\r\n\r\n    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:232: spi_loopback_test_spi_rx_half_end: IS_ENABLED(CONFIG_SPI_STM32_DMA) is true\r\n\r\n SKIP - test_spi_rx_half_end in 0.015 seconds\r\n===================================================================\r\nSTART - test_spi_rx_half_start\r\n PASS - test_spi_rx_half_start in 0.001 seconds\r\n===================================================================\r\nTESTSUITE spi_loopback succeeded\r\n\r\n------ TESTSUITE SUMMARY START ------\r\n\r\nSUITE PASS - 100.00% [spi_extra_api_features]: pass = 1, fail = 0, skip = 0, total = 1 duration = 0.001 seconds\r\n - PASS - [spi_extra_api_features.test_spi_lock_release] duration = 0.001 seconds\r\n\r\nSUITE PASS - 100.00% [spi_loopback]: pass = 5, fail = 0, skip = 3, total = 8 duration = 0.197 seconds\r\n - PASS - [spi_loopback.test_spi_complete_large_transfers] duration = 0.141 seconds\r\n - PASS - [spi_loopback.test_spi_complete_loop] duration = 0.001 seconds\r\n - PASS - [spi_loopback.test_spi_complete_multiple] duration = 0.001 seconds\r\n - PASS - [spi_loopback.test_spi_null_tx_buf] duration = 0.001 seconds\r\n - SKIP - [spi_loopback.test_spi_rx_bigger_than_tx] duration = 0.019 seconds\r\n - SKIP - [spi_loopback.test_spi_rx_every_4] duration = 0.018 seconds\r\n - SKIP - [spi_loopback.test_spi_rx_half_end] duration = 0.015 seconds\r\n - PASS - [spi_loopback.test_spi_rx_half_start] duration = 0.001 seconds\r\n\r\n------ TESTSUITE SUMMARY END ------\r\n\r\n===================================================================\r\nRunID: 1b3142779eb930bec9ba2678bd9e3394\r\nPROJECT EXECUTION FAILED\r\n",
            "reason":"Failed harness:'Testsuite failed'",
            "execution_time":"2.66",
            "build_time":"91.59",
 

To Reproduce

Steps to reproduce the behavior:

1. Go to your zephyr directory
2. Have board compatible with test
3. ./scripts/twister --device-testing --device-serial /dev/ttyACM0 -p nucleo_h743zi -T tests/drivers/spi/spi_loopback --fixture spi_loopback
4. See handler.log and twister.json files

Expected behavior

In the twister.json file, for an "assumption failed" in log, we should have "status":"skipped" or "status":"passed"

Logs and console output
We can see in console :

===================================================================
START - test_spi_null_tx_buf
 PASS - test_spi_null_tx_buf in 0.001 seconds
===================================================================
START - test_spi_rx_bigger_than_tx

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:274: spi_loopback_test_spi_rx_bigger_than_tx: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true

 SKIP - test_spi_rx_bigger_than_tx in 0.019 seconds
===================================================================
START - test_spi_rx_every_4

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:251: spi_loopback_test_spi_rx_every_4: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true

 SKIP - test_spi_rx_every_4 in 0.018 seconds
===================================================================
START - test_spi_rx_half_end

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:232: spi_loopback_test_spi_rx_half_end: IS_ENABLED(CONFIG_SPI_STM32_DMA) is true

 SKIP - test_spi_rx_half_end in 0.015 seconds
===================================================================
START - test_spi_rx_half_start
 PASS - test_spi_rx_half_start in 0.001 seconds
===================================================================
TESTSUITE spi_loopback succeeded
Running TESTSUITE spi_loopback
===================================================================
Testing loopback spec: FAST
START - test_spi_complete_large_transfers
 PASS - test_spi_complete_large_transfers in 0.005 seconds
===================================================================
START - test_spi_complete_loop
 PASS - test_spi_complete_loop in 0.001 seconds
===================================================================
START - test_spi_complete_multiple
 PASS - test_spi_complete_multiple in 0.001 seconds
===================================================================
START - test_spi_null_tx_buf
 PASS - test_spi_null_tx_buf in 0.001 seconds
===================================================================
START - test_spi_rx_bigger_than_tx

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:274: spi_loopback_test_spi_rx_bigger_than_tx: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true

 SKIP - test_spi_rx_bigger_than_tx in 0.019 seconds
===================================================================
START - test_spi_rx_every_4

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:251: spi_loopback_test_spi_rx_every_4: IS_ENABLED(CONFIG_SPI_STM32_DMA) || IS_ENABLED(CONFIG_DSPI_MCUX_EDMA) is true

 SKIP - test_spi_rx_every_4 in 0.018 seconds
===================================================================
START - test_spi_rx_half_end

    Assumption failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:232: spi_loopback_test_spi_rx_half_end: IS_ENABLED(CONFIG_SPI_STM32_DMA) is true

 SKIP - test_spi_rx_half_end in 0.015 seconds
===================================================================
START - test_spi_rx_half_start
 PASS - test_spi_rx_half_start in 0.001 seconds
===================================================================
TESTSUITE spi_loopback succeeded

------ TESTSUITE SUMMARY START ------

SUITE PASS - 100.00% [spi_extra_api_features]: pass = 1, fail = 0, skip = 0, total = 1 duration = 0.001 seconds
 - PASS - [spi_extra_api_features.test_spi_lock_release] duration = 0.001 seconds

SUITE PASS - 100.00% [spi_loopback]: pass = 5, fail = 0, skip = 3, total = 8 duration = 0.197 seconds
 - PASS - [spi_loopback.test_spi_complete_large_transfers] duration = 0.141 seconds
 - PASS - [spi_loopback.test_spi_complete_loop] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_complete_multiple] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_null_tx_buf] duration = 0.001 seconds
 - SKIP - [spi_loopback.test_spi_rx_bigger_than_tx] duration = 0.019 seconds
 - SKIP - [spi_loopback.test_spi_rx_every_4] duration = 0.018 seconds
 - SKIP - [spi_loopback.test_spi_rx_half_end] duration = 0.015 seconds
 - PASS - [spi_loopback.test_spi_rx_half_start] duration = 0.001 seconds

------ TESTSUITE SUMMARY END ------

===================================================================
RunID: 1b3142779eb930bec9ba2678bd9e3394
PROJECT EXECUTION **FAILED**

Impact
The test is reported as failed without it actually being the case

Environment (please complete the following information):

• OS: Ubuntu 22.04 LTS
• Toolchain Zephyr SDK 0.17.0

[nashif]

Are you missing a ZTEST_EXPECT_SKIP here?

see https://docs.zephyrproject.org/latest/develop/test/ztest.html#test-result-expectations`

[decsny]

Are you missing a ZTEST_EXPECT_SKIP here?

see https://docs.zephyrproject.org/latest/develop/test/ztest.html#test-result-expectations`

What if, skip is not always expected, it's just used as a way to skip in some cases, I am not clear from this documentation the proper way on how to handle that

[nashif]

Are you missing a ZTEST_EXPECT_SKIP here?
see docs.zephyrproject.org/latest/develop/test/ztest.html#test-result-expectations`

What if, skip is not always expected, it's just used as a way to skip in some cases, I am not clear from this documentation the proper way on how to handle that

@yperess can you please take a look and give your input?

[yperess]

We don't have a feature for that, but it should be very easy to support, the quick way is to do this...

#if !defined(CONFIG_SPI_STM32_DMA) && !defined(CONFIG_DSPI_MCUX_EDMA)
ZTEST_EXPECT_SKIP(spi_loopback, test_spi_rx_bigger_than_tx);
ZTEST_EXPECT_SKIP(spi_loopback, test_spi_rx_every_4);
#endif

#ifdef CONFIG_SPI_STM
ZTEST_EXPECT_SKIP(spi_loopback, test_spi_rx_half_end)
#endif

The better way to do it is implement ZTEST_EXPECT_SKIP_IF({boolean statement}, {suite}, {test}) so you can do things like

ZTEST_EXPECT_SKIP_IF(
    !defined(CONFIG_SPI_STM32_DMA) && !defined(CONFIG_DSPI_MCUX_EDMA),
    spi_loopback,
    test_spi_rx_bigger_than_tx
);

[decsny]

I mean , it seems redundant to say , expect a skip if these configs and then also skip if these configs, maybe for this test, we just put #if around the test cases since these are statically defined macros

But more general question is why does a skip lead to a twister project execution fail here, or is it the assumption that makes it fail? Because I thought I have seen tests with skips before that dont cause a fail, and I think don't have this ZTEST_EXPECT_SKIP so a bit confused what is the difference here, maybe they didn't use assumption?

[nashif]

But more general question is why does a skip lead to a twister project execution fail here, or is it the assumption that makes it fail? Because I thought I have seen tests with skips before that dont cause a fail, and I think don't have this ZTEST_EXPECT_SKIP so a bit confused what is the difference here, maybe they didn't use assumption?

This is not a twister issue, this is all in ZTEST. Ztest at the end of the test concludes the test has failed and twister just evaluates that and determines based on the output from ztest that something went wrong, see:

RunID: 1b3142779eb930bec9ba2678bd9e3394
PROJECT EXECUTION **FAILED**

We need ztest to mark this as passed when using the assume logic somehow.

[decsny]

But more general question is why does a skip lead to a twister project execution fail here, or is it the assumption that makes it fail? Because I thought I have seen tests with skips before that dont cause a fail, and I think don't have this ZTEST_EXPECT_SKIP so a bit confused what is the difference here, maybe they didn't use assumption?

This is not a twister issue, this is all in ZTEST. Ztest at the end of the test concludes the test has failed and twister just evaluates that and determines based on the output from ztest that something went wrong, see:

RunID: 1b3142779eb930bec9ba2678bd9e3394
PROJECT EXECUTION **FAILED**

We need ztest to mark this as passed when using the assume logic somehow.

Okay sure, but, it's just that sometimes I have seen that when doing a build using twister, there are some hooks in the scripting and build system for twister to set some flags /change some behaviors that would not normally happen when using like west build or manual build, and even further some hooks on top of that when twister is run by a ci workflow, so I didn't know if there is some magic flag it is setting for for ZTest somewhere to cause this. And from my understanding, the ZTest is also supported/generated with python scripting so this wouldn't be surprising to me.

[nashif]

And from my understanding, the ZTest is also supported/generated with python scripting so this wouldn't be surprising to me.

no, ztest has 0 python in it :)

[nashif]

how was this resolved in #86383?