zephyr icon indicating copy to clipboard operation
zephyr copied to clipboard

Published 20 hours ago • verified publisher icon zephyrproject-rtos

ztest: add test summary support.

Open smrtos opened this issue 3 years ago • 16 comments
trafficstars

This is a second try of https://github.com/zephyrproject-rtos/zephyr/pull/48105. If this PR is merged, https://github.com/zephyrproject-rtos/zephyr/pull/48484 can be closed.

Several issues are addressed:

  • https://github.com/zephyrproject-rtos/zephyr/issues/48480 Root cause: When declaring a unit test with ZTEST* macros, a stats object is defined and associated with the unit test. Previously, this stats object is named only after the test function. So if the same function is used in different suites, the same stats object will be defined multiple times, thus the duplicate symbol error. This can be avoided by including the suite name in the stats object name because suite name is guaranteed to be unique. And also, this can make sure test function in different suites can have separate stats. Fixed with: https://github.com/smrtos/zephyr/blob/d36d46cdf61408761e297309aaaafd760fe3dbb3/subsys/testsuite/ztest/include/zephyr/ztest_test_new.h#L266 Verified with: https://github.com/smrtos/zephyr/tree/ztest_add_summary/tests/ztest/summary

  • https://github.com/zephyrproject-rtos/zephyr/pull/48105#pullrequestreview-1055942751 Root cause: should be caused by the messy log flushing when log panic is triggered. Fixed with: https://github.com/smrtos/zephyr/blob/d36d46cdf61408761e297309aaaafd760fe3dbb3/subsys/testsuite/ztest/src/ztest_new.c#L862 Verified with: twister -p qemu_x86_64 -s tests/subsys/logging/log_api/logging.log_api_deferred_printk_cpp -vv twister -p qemu_riscv32_smp -s tests/subsys/logging/log_api/logging.log_api_deferred_printk_cpp -vv twister -p qemu_cortex_a53_smp -s tests/subsys/logging/log_api/logging.log_api_deferred_printk_cpp -vv

  • https://github.com/zephyrproject-rtos/zephyr/issues/48469 Root cause: the tests/kernel/sched/schedule_api is still using old ztest. Previous PR didn't treat them fair enough... Fixed with: lines like: https://github.com/smrtos/zephyr/blob/d36d46cdf61408761e297309aaaafd760fe3dbb3/subsys/testsuite/include/zephyr/tc_util.h#L133-L142 Verified with: west build -b qemu_cortex_a53 tests/kernel/sched/schedule_api --pristine && west build -t run twister -p qemu_x86_64 -s tests/kernel/sched/schedule_api/kernel.scheduler -vv twister -p qemu_riscv32_smp -s tests/kernel/sched/schedule_api/kernel.scheduler -vv twister -p qemu_cortex_a53_smp -s tests/kernel/sched/schedule_api/kernel.scheduler -vv These runs will not have summary output because it is using old ztest.

  • Also fixed an old bug: https://github.com/zephyrproject-rtos/zephyr/issues/48547

The summary looks like this now:

DEBUG   - QEMU (2937061): ------ TESTSUITE SUMMARY START ------
DEBUG   - QEMU (2937061): SUITE PASS - 100.00% [suite1]: pass = 1, fail = 0, skip = 0, total = 1 duration = 0.001 seconds
DEBUG   - QEMU (2937061): - PASS - [suite1.test_foo] duration = 0.001 seconds
DEBUG   - QEMU (2937061):
DEBUG   - QEMU (2937061): SUITE SKIP -   0.00% [suite2]: pass = 0, fail = 0, skip = 1, total = 1 duration = 0.001 seconds
DEBUG   - QEMU (2937061): - SKIP - [suite2.test_foo] duration = 0.001 seconds
DEBUG   - QEMU (2937061):
DEBUG   - QEMU (2937061): ------ TESTSUITE SUMMARY END ------

And:

DEBUG   - QEMU (2936214): ------ TESTSUITE SUMMARY START ------
DEBUG   - QEMU (2936214): SUITE PASS - 100.00% [test_log_api]: pass = 8, fail = 0, skip = 1, total = 9 duration = 14.851 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_arg_evaluation] duration = 2.422 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_arguments] duration = 1.210 seconds
DEBUG   - QEMU (2936214): - SKIP - [test_log_api.test_log_backend_runtime_filtering] duration = 1.209 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_from_declared_module] duration = 2.420 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_overflow] duration = 3.630 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_override_level] duration = 1.320 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_panic] duration = 1.212 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_printk] duration = 0.109 seconds
DEBUG   - QEMU (2936214): - PASS - [test_log_api.test_log_various_messages] duration = 1.319 seconds
DEBUG   - QEMU (2936214):
DEBUG   - QEMU (2936214): SUITE SKIP -   0.00% [test_log_api_1cpu]: pass = 0, fail = 0, skip = 1, total = 1 duration = 1.211 seconds
DEBUG   - QEMU (2936214): - SKIP - [test_log_api_1cpu.test_log_msg_dropped_notification] duration = 1.211 seconds
DEBUG   - QEMU (2936214):
DEBUG   - QEMU (2936214): ------ TESTSUITE SUMMARY END ------

Signed-off-by: Ming Shao [email protected]

smrtos avatar Jul 30 '22 14:07 smrtos

The main changes are done. Now testing with as many boards as I can find. The existing tests are quite diverse. Hope everything is fine...

smrtos avatar Aug 02 '22 08:08 smrtos

The CI saw below error: https://github.com/zephyrproject-rtos/zephyr/runs/7627365444?check_suite_focus=true https://github.com/zephyrproject-rtos/zephyr/pull/48499/checks?check_run_id=7627894565

INFO    - 608/608 qemu_arc_hs               tests/lib/mem_alloc/libraries.libc.newlib.mem_alloc FAILED Timeout (qemu 59.982s)

But I rebased and tried with:

twister -p qemu_arc_hs -s tests/lib/mem_alloc/libraries.libc.newlib.mem_alloc -vv

All passed:

DEBUG   - QEMU (409867): *** Booting Zephyr OS build zephyr-v3.1.0-2464-g928656470a57  ***
DEBUG   - QEMU (409867): Running TESTSUITE test_c_lib_dynamic_memalloc
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_malloc_align
DEBUG   - QEMU (409867): Compiler type info for arc qemu_arc
DEBUG   - QEMU (409867): TYPE            SIZE  ALIGN
DEBUG   - QEMU (409867): int                4      4
DEBUG   - QEMU (409867): long               4      4
DEBUG   - QEMU (409867): long long          8      4
DEBUG   - QEMU (409867): double             8      4
DEBUG   - QEMU (409867): size_t             4      4
DEBUG   - QEMU (409867): void *             4      4
DEBUG   - QEMU (409867): void (*)(void)     4      4
DEBUG   - QEMU (409867): time_t             8      4
DEBUG   - QEMU (409867): PASS - test_malloc_align in 0.167 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_malloc
DEBUG   - QEMU (409867): PASS - test_malloc in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_free
DEBUG   - QEMU (409867): PASS - test_free in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_calloc
DEBUG   - QEMU (409867): SKIP - test_calloc in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_realloc
DEBUG   - QEMU (409867): PASS - test_realloc in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_reallocarray
DEBUG   - QEMU (409867): SKIP - test_reallocarray in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_memalloc_all
DEBUG   - QEMU (409867): PASS - test_memalloc_all in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): START - test_memalloc_max
DEBUG   - QEMU (409867): PASS - test_memalloc_max in 0.001 seconds
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): TESTSUITE test_c_lib_dynamic_memalloc succeeded
DEBUG   - QEMU (409867): ===================================================================
DEBUG   - QEMU (409867): RunID: be74c1058a36f2326e4b62bb09a9f19a
DEBUG   - QEMU (409867): PROJECT EXECUTION SUCCESSFUL
DEBUG   - QEMU (409867) complete (passed) after 2.20586895942688 seconds

smrtos avatar Aug 02 '22 09:08 smrtos

For the CI error with qemu_arc_hs:

I rebased and tested with below commands:

twister -p qemu_arc_hs -T tests

Still all passed. Cannot reproduce the CI error. I am using zephyr SDK 0.14.2.

INFO    - Using Ninja..
INFO    - Zephyr version: zephyr-v3.1.0-2895-g7ac5f2fe6bda
...

INFO    - 1327 test scenarios (1234 configurations) selected, 810 configurations discarded due to filters.
INFO    - Adding tasks to the queue...
INFO    - Added initial list of jobs to queue
INFO    - Total complete: 1234/1234  100%  skipped:  914, failed:    0
INFO    - 320 of 1234 test configurations passed (100.00%), 0 failed, 914 skipped with 0 warnings in 1241.45 seconds
INFO    - In total 11058 test cases were executed, 8819 skipped on 1 out of total 478 platforms (0.21%)
INFO    - 292 test configurations executed on platforms, 28 test configurations were only built.

For the CI error with mps2_an385, I don't have such a board to test.

smrtos avatar Aug 02 '22 10:08 smrtos

For the CI error with mps2_an385, I don't have such a board to test.

this is qemu

nashif avatar Aug 02 '22 12:08 nashif

I just re-pushed. It's strange that the mps2_an385 failure disappeared. Only the qemu_arc_hs failure remains: https://github.com/zephyrproject-rtos/zephyr/runs/7644514469?check_suite_focus=true

smrtos avatar Aug 03 '22 07:08 smrtos

I just re-pushed. No significant change.

It's strange that the mps2_an385 CI failure disappeared.

Only the qemu_arc_hs failure remains: https://github.com/zephyrproject-rtos/zephyr/runs/7647515326?check_suite_focus=true Which still all pass on my local.

twister -vv -p qemu_arc_hs -T tests/

INFO    - 320 of 1234 test configurations passed (100.00%), 0 failed, 914 skipped with 0 warnings in 1214.80 seconds
INFO    - In total 11058 test cases were executed, 8819 skipped on 1 out of total 478 platforms (0.21%)
INFO    - 292 test configurations executed on platforms, 28 test configurations were only built.

smrtos avatar Aug 03 '22 08:08 smrtos

Seems the CI healed itself... And I cannot find the CI log for qemu_arc_hs...

smrtos avatar Aug 04 '22 14:08 smrtos

Seems the CI healed itself... And I cannot find the CI log for qemu_arc_hs...

no it did not :) I just triggered a re-run. Some qemu platforms fails occasionally due to timing issues with the host...

nashif avatar Aug 04 '22 20:08 nashif

Testing on reel_board and found some CMake warning like below and some build failures. Investigating.

Build:

twister -p reel_board -T tests/drivers/build_all/led
twister -p reel_board -T tests/drivers/build_all/gpio

Warning:

CMake Warning:
  Manually-specified variables were not used by the project:

    TC_RUNID

This should be fine.

The build error I saw with led and gpio was fixed by: 700745195525f311fd939fad4fe8cd2bdda17dc3

smrtos avatar Aug 05 '22 00:08 smrtos

Saw 6 failures on reel_board with tests folder, 4 of which also happened on main branch.

The 4 are related to bugs below: https://github.com/zephyrproject-rtos/zephyr/issues/48725 https://github.com/zephyrproject-rtos/zephyr/issues/48726

The other 2 only happened with this PR. But it's likely that they share the same reason with https://github.com/zephyrproject-rtos/zephyr/issues/48725 since the symptom is similar.

Case 1:

twister -vv --hardware-map ~/daily_qa/cavs25.map --device-testing -s tests/arch/arm/arm_thread_swap/arch.arm.swap.common.no_optimizations

Error 1:

DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v3.1.0-3126-g909c6fb2733a  ***
DEBUG   - DEVICE: Running TESTSUITE arm_thread_swap
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - t: ***** MPU FAULT *****
DEBUG   - DEVICE: E:   Stacking error (context area might be not valid)
DEBUG   - DEVICE: E:   Data Access Violation
DEBUG   - DEVICE: E:   MMFAR Address: 0x2000203c
DEBUG   - DEVICE: E: r0/a1:  0x00000000  r1/a2:  0x000202c7  r2/a3:  0x00000000
DEBUG   - DEVICE: E: r3/a4:  0x000202c7 r12/ip:  0x00000000 r14/lr:  0x000202c7
DEBUG   - DEVICE: E:  xpsr:  0x00020200
DEBUG   - DEVICE: E: Faulting instruction address (r15/pc): 0x00000000
DEBUG   - DEVICE: E: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
DEBUG   - DEVICE: E: Current thread: 0x20000268 (main)
DEBUG   - DEVICE: E: Halting system

Case 2:

twister -vv --hardware-map ~/daily_qa/cavs25.map --device-testing -s tests/arch/arm/arm_interrupt/arch.interrupt.no_optimizations

Error2:

DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v3.1.0-3126-g909c6fb2733a  ***
DEBUG   - DEVICE: Running TESTSUITE arm_interrupt
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - t: ***** MPU FAULT *****
DEBUG   - DEVICE: E:   Stacking error (context area might be not valid)
DEBUG   - DEVICE: E:   Data Access Violation
DEBUG   - DEVICE: E:   MMFAR Address: 0x2000243c
DEBUG   - DEVICE: E: r0/a1:  0x00000000  r1/a2:  0x00000000  r2/a3:  0x00000000
DEBUG   - DEVICE: E: r3/a4:  0x00000000 r12/ip:  0x00000000 r14/lr:  0x00000000
DEBUG   - DEVICE: E:  xpsr:  0x00000000
DEBUG   - DEVICE: E: Faulting instruction address (r15/pc): 0x00000000
DEBUG   - DEVICE: E: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
DEBUG   - DEVICE: E: Current thread: 0x200001b0 (main)
DEBUG   - DEVICE: Caught system error -- reason 2
DEBUG   - DEVICE: Was not expecting a crash
DEBUG   - -- west flash: using runner pyocd

smrtos avatar Aug 05 '22 06:08 smrtos

Verification so far:

twister -vv -p qemu_arc_hs -T tests/ -- 100% pass twister -vv -p qemu_cortex_a53_smp -T tests -- 100% after manual retry twister -vv -p qemu_riscv32_smp -T tests -- 100% after manual retry twister -vv -p qemu_x86_64 -T tests -- 99.96%, only tests/boot/uefi/ failed. Because no uefi-run and OVMF environment on my local. twister -vv --hardware-map ~/daily_qa/cavs25.map --device-testing -T tests -- pass with bugs on main branch.

smrtos avatar Aug 05 '22 10:08 smrtos

Reviewing right now, I'm almost done but please DNM as I have some questions. Sorry for not getting to this earlier.

aaronemassey avatar Aug 05 '22 17:08 aaronemassey

@aaronemassey @nashif @jeremybettis Could you help review again? I refined a bit. Thanks.

smrtos avatar Aug 05 '22 22:08 smrtos

@aaronemassey @nashif @jeremybettis Could you help review again? I refined a bit. Thanks.

Might get to it on the weekend, but if not will take a look Monday!

aaronemassey avatar Aug 05 '22 23:08 aaronemassey

@smrtos please rebase

nashif avatar Aug 10 '22 00:08 nashif

Rebased. @nashif @aaronemassey @yperess

The only conflict is ztest_new added the skip handling. So I don't need to do it any more.

image

smrtos avatar Aug 10 '22 06:08 smrtos