frdm_k64f:running testcase tests/subsys/debug/coredump/ and tests/subsys/debug/coredump_backends/ failed

[Zhaoningx]

To Reproduce
When running coredumptestcases, it showed me 'successful', but it is always showed some error log in handler.log.

Steps to reproduce the behavior:
twister -p frdm_k64f --device-testing --device-serial /dev/ttyACM0 -T tests/subsys/debug/coredump/ -j 1
twister -p frdm_k64f --device-testing --device-serial /dev/ttyACM0 -T tests/subsys/debug/coredump_backends/ -j 1
see error
handler.log
X*** Booting Zephyr OS build zephyr-v2.5.0 ***
Coredump: frdm_k64f
E: ***** USAGE FAULT *****
E: Attempt to execute undefined instruction
E: r0/a1: 0x00000014 r1/a2: 0x00000000 r2/a3: 0x00000080
E: r3/a4: 0x00000000 r12/ip: 0x0000000a r14/lr: 0x00000727
E: xpsr: 0x41000000
E: Faulting instruction address (r15/pc): 0x0000072a
E: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
E: Current thread: 0x200001b0 (unknown)
E: #CD:BEGIN#
E: #CD:5a4501000300050000000000
E: #CD:4101002400
E: #CD:140000000000000080000000000000000a000000270700002a07000000000041
E: #CD:48070020
E: #CD:4d0100b001002030020020
E: #CD:cc020020cc020020000000000180000000000000000000000000000000000000
E: #CD:00000000000000000000000000000000e0010020e00100203d2600003d260000
E: #CD:800700203001002080070020001100203d260000010000005007002000000000
E: #CD:00000000000000008003002000040000000000000000000000000000f5ffffff
E: #CD:4d01008003002080070020
E: #CD:0068046001200e49c8710198000ac8720198887205984872fff7b6fe8346bbf1
E: #CD:000f01d05846d1e7a6eb080644443d4400bf002edad10020c8e700000e010000
E: #CD:0000024070b504460d460cb9042070bd40200349c87108468571fff795fef6e7
E: #CD:000002402de9ff4d0c4617461d46dde90cb8ddf838a01db9042004b0bde8f08d
E: #CD:04233a4621460098fff71eff06460eb13046f2e722e014487844006804600220
E: #CD:1249c871084680f80bb00f4979441439286809688860fff767fe06465eb1b8f1
E: #CD:000f01d0c8f80040baf1000f02d00020caf8000004e03f1f2d1d241d002fdad1
E: #CD:00bf3046c9e70000740000000000024000000000000008000000100000002000
E: #CD:0000400000008000000000010000000104000240000000000000000000001000
E: #CD:0200000000100000000000000000000000000000c0ec1b3629221c3660ccff00
E: #CD:0000000000000000c00d00202000000008822000700700000000000000000000
E: #CD:0000000000000000000000000000000000000000000000000000000000000000
E: #CD:0000000000000000000000000000000000000000000000000000000080f0fa02
E: #CD:0000000000000000401700205803002058030020000000000000000000000000
E: #CD:4005002040050020580300204c0500204c050020000000000000000000000000
E: #CD:0000000000000000000000000000000040170020401700200000000005010000
E: #CD:50030020b8040020000000000200000051000000b40000204edc1a10ff869303
E: #CD:5003002000000000000000000000000000000000000000000000000000000000
E: #CD:0000000000000000000000000000000000000000000000000000000000000000
E: #CD:0000000080f0fa0200000000b8040020b8040020000000008838002018040020
E: #CD:180400200000000000000000000000001006002010060020180400201c060020
E: #CD:1c06002000000000180400200000000000000000500300200000000018040020
E: #CD:0000000000000000000000000000000000000000000000000000000000000000
E: #CD:0000000000000000000000000000000000000000000000000000000000000000
E: #CD:0000000000000000000000000000000000000000000000001337000066000000
E: #CD:38020020cb0f0000ad0f0000053f0000133700000a00000038020020cb0f0000
E: #CD:ad0f00006007002013000000950700002e000000950700003507000000000000
E: #CD:350700000000000000000000000000000000000000000000fc3e000000000000
E: #CD:80000373000000000000000000000000000000003d2600003d26000080070020
E: #CD:3001002080070020001100203d2600000100000063070000063f000014000000
E: #CD:a402002017300000140000000000000080000000000000000a00000027070000
E: #CD:2a07000000000041b00100205d260000000000002d3000000000000041130000
E: #CD:END#

Environment (please complete the following information):

OS: Fedora33
Toolchain: zephyr-sdk-0.12.2
Commit ID: fe7c2ef

[laodzu]

This is not a bug, but expected bahaviour. The test case just tests that Zephyr catches an illegal Null pointer assignment and prints a core dump. So although the core dump looks like an error, this test checks that it is indeed generated.

Testcase is here
Testcase YAML

So I think this bug report can be closed.

[dcpleung]

As @laodzu said, this is expected behavior as the test is to make sure a coredump can be generated. So closing...

[LeiW000]

@Zhaoningx , my understanding is that twister takes this as a failure of the test case? If that is the case, maybe there is something wrong with the test case.

[Zhaoningx]

Hi @LeiW000 , yes, so we need to spend some time to debug this I think, by the way, this issue has also met on reel board platform, so I'll talk with Kelvin later, maybe he has good idea for this.

[LeiW000]

I don't think we should close the issue now. The dump info is expected behavior. But twister takes it as a failure. It is still a bug.

[laodzu]

I think there is now some confusion in this ticket. Twister does not take this is a failure. As the original report already states, Twister shows "successful".

Here is the log from my system running the test:

2021-02-22 10:43:58,438 - twister - DEBUG - run status: frdm_k64f/tests/subsys/debug/coredum/coredump.logging_backend passed
2021-02-22 10:43:58,442 - twister - DEBUG - running footprint_reports
2021-02-22 10:43:58,676 - twister - INFO - 1 of 1 test configurations passed (100.00%), 0 failed, 0 skipped with 0 warnings in 33.31 seconds

So again, the test passes - as expected. This is all expected behaviour so the bug can indeed be closed.

[laodzu]

@Zhaoningx Was your initial report not correct that twister shows "successful" running the test? As explained, the test correctly test the ability of Zephyr to do a crash dump. For this an illegal access is done on purpose and the crash is observed correctly by twister - just as you state right in your report. This is also what I confirmed by running the test on my own frdm_k64f board.

So can anyone explain to me, why this bug has been re-opened?

[Zhaoningx]

Hi @laodzu , yep, I totally agree with you, but there are still some issues about this bug, so I re-open this, see log below:

It shows that the testcase is successful to test, but marked as failure by twister.

[laodzu]

@Zhaoningx Ah, slowly I understand what you are talking about. So there is a discrepancy between what twister reports in its console output and between what it writes into the XML report files.
To illustrate, I rerun both test cases and this is the console output:

dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$ scripts/twister -p frdm_k64f --device-testing --device-serial /dev/ttyACM0 -T tests/subsys/debug/coredump -T tests/subsys/debug/coredump_backends/ -j 1
INFO - Zephyr version: zephyr-v2.5.0-270-g37dca2044414
INFO - JOBS: 1
INFO - Using 'zephyr' toolchain.
INFO - Building initial testcase list...
INFO - 3 test scenarios (3 configurations) selected, 1 configurations discarded due to filters.

Device testing on:

Platform	ID	Serial device
frdm_k64f		/dev/ttyACM0

INFO - Adding tasks to the queue...
INFO - Added initial list of jobs to queue
INFO - Total complete: 2/ 2 100% skipped: 1, failed: 0
INFO - 2 of 2 test configurations passed (100.00%), 0 failed, 1 skipped with 0 warnings in 29.66 seconds
INFO - In total 4 test cases were executed, 3 skipped on 1 out of total 325 platforms (0.31%)
INFO - 2 test configurations executed on platforms, 0 test configurations were only built.

Hardware distribution summary:

Board	ID	Counter
frdm_k64f		2
INFO - Saving reports...
INFO - Writing xunit report /opt/src/git/zephyrproject/zephyr/twister-out/twister.xml...
INFO - Writing xunit report /opt/src/git/zephyrproject/zephyr/twister-out/twister_report.xml...
INFO - Run completed
dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$

And this is the XML report it produced:

dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$ xq . twister-out/twister_report.xml 
{
  "testsuites": {
    "testsuite": {
      "@name": "frdm_k64f",
      "@time": "9.760272",
      "@tests": "5",
      "@failures": "1",
      "@errors": "0",
      "@skipped": "3",
      "properties": {
        "property": {
          "@name": "version",
          "@value": "zephyr-v2.5.0-270-g37dca2044414"
        }
      },
      "testcase": [
        {
          "@classname": "coredump.logging_backend",
          "@name": "coredump.logging_backend",
          "@time": "4.539616",
          "failure": {
            "@type": "failure",
            "@message": "failed",
            "#text": "============================================\nSTART - test_query_stored_dump\nSKIP - test_query_stored_dump\n===================================================================\nSTART - test_verify_stored_dump\nSKIP - test_verify_stored_dump\n===================================================================\nTest suite coredump_backends succeeded\n===================================================================\nPROJECT EXECUTION SUCCESSFUL"
          }
        },
        {
          "@classname": "coredump.backends",
          "@name": "coredump.backends.logging",
          "@time": "5.220656"
        },
        {
          "@classname": "coredump.backends",
          "@name": "coredump.backends.flash.coredump",
          "@time": "0.000000",
          "skipped": {
            "@type": "skipped",
            "@message": "Not in testcase platform allow list"
          }
        },
        {
          "@classname": "coredump.backends",
          "@name": "coredump.backends.flash.query_stored_dump",
          "@time": "0.000000",
          "skipped": {
            "@type": "skipped",
            "@message": "Not in testcase platform allow list"
          }
        },
        {
          "@classname": "coredump.backends",
          "@name": "coredump.backends.flash.verify_stored_dump",
          "@time": "0.000000",
          "skipped": {
            "@type": "skipped",
            "@message": "Not in testcase platform allow list"
          }
        }
      ]
    }
  }
}
dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$

So the problems seems to be in tests/subsys/debug/coredump/ - the
tests in tests/subsys/debug/coredump_backends seem to work out
correctly. I'll investigate further.

[laodzu]

Running the two tests individually works as expected - both tests pass and the XML files are correct. The bug only appears when running both tests in a single twister invocation.
Very strange.

[dcpleung]

@nashif Have you seen the same issue with twister?

[nashif]

works for me on frdm_k64f.

[laodzu]

@nashif Thanks for also testing. Can you clarify if running both tests at once yield correct XML output even though the console output signaled success?

[nashif]

@nashif Thanks for also testing. Can you clarify if running both tests at once yield correct XML output even though the console output signaled success?

confirm there is an issue with xml output, looking.

[laodzu]

@nashif @andyross Thanks for fixing one race. Unfortunately the bug in this issue is not fixed on my system. I still have the same failure mode. Running the tests individually again work, running them from one twister invocation fails. I tried this 5 times and it failed 5 times, so if it is another race, I can hit it in a pretty deterministic fashion:

dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$ git describe
zephyr-v2.5.0-900-gd2a2b7cb56
dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$ scripts/twister -p frdm_k64f --device-testing --device-serial /dev/ttyACM0 -T tests/subsys/debug/coredump -T tests/subsys/debug/coredump_backends/ -j 1
Renaming output directory to /opt/src/git/zephyrproject/zephyr/twister-out.2
INFO - Zephyr version: zephyr-v2.5.0-900-gd2a2b7cb5665
INFO - JOBS: 1
INFO - Using 'zephyr' toolchain.
INFO - Building initial testcase list...
INFO - 3 test scenarios (3 configurations) selected, 1 configurations discarded due to filters.

Device testing on:

Platform	ID	Serial device
frdm_k64f		/dev/ttyACM0

INFO - Adding tasks to the queue...
INFO - Added initial list of jobs to queue
INFO - Total complete: 2/ 2 100% skipped: 1, failed: 0
INFO - 2 of 2 test configurations passed (100.00%), 0 failed, 1 skipped with 0 warnings in 83.23 seconds
INFO - In total 4 test cases were executed, 3 skipped on 1 out of total 331 platforms (0.30%)
INFO - 2 test configurations executed on platforms, 0 test configurations were only built.

Hardware distribution summary:

Board	ID	Counter
frdm_k64f		2
INFO - Saving reports...
INFO - Writing xunit report /opt/src/git/zephyrproject/zephyr/twister-out/twister.xml...
INFO - Writing xunit report /opt/src/git/zephyrproject/zephyr/twister-out/twister_report.xml...
INFO - Run completed

Results:

dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$ xq . twister-out/twister_report.xml
{
"testsuites": {
"testsuite": {
"@name": "frdm_k64f",
"@time": "15.023175",
"@tests": "5",
"@failures": "1",
"@errors": "0",
"@Skipped": "3",
"properties": {
"property": {
"@name": "version",
"@value": "zephyr-v2.5.0-900-gd2a2b7cb5665"
}
},
"testcase": [
{
"@classname": "coredump.logging_backend",
"@name": "coredump.logging_backend",
"@time": "5.981344",
"failure": {
"@type": "failure",
"@message": "failed",
"#text": "=================================================================\nSTART - test_verify_stored_dump\nSKIP - test_verify_stored_dump\n===================================================================\nTest suite coredump_backends succeeded\n===================================================================\nPROJECT EXECUTION SUCCESSFUL"
}
},
{
"@classname": "coredump.backends",
"@name": "coredump.backends.logging",
"@time": "9.041832"
},
{
"@classname": "coredump.backends",
"@name": "coredump.backends.flash.coredump",
"@time": "0.000000",
"skipped": {
"@type": "skipped",
"@message": "Not in testcase platform allow list"
}
},
{
"@classname": "coredump.backends",
"@name": "coredump.backends.flash.query_stored_dump",
"@time": "0.000000",
"skipped": {
"@type": "skipped",
"@message": "Not in testcase platform allow list"
}
},
{
"@classname": "coredump.backends",
"@name": "coredump.backends.flash.verify_stored_dump",
"@time": "0.000000",
"skipped": {
"@type": "skipped",
"@message": "Not in testcase platform allow list"
}
}
]
}
}
}
dzu@krikkit:/opt/src/git/zephyrproject/zephyr (master)$

[laodzu]

@Zhaoningx Can you please verify if the bug is really fixed for you? As I wrote, I still see the problem but I cannot reopen the bug.

[Zhaoningx]

Hi @laodzu , after double check, It is not really fixed, I saw the report of yesterday, the failures of coredump is still met. See log as below:

so I reopen this.

[chen-png]

when we ran "tests/subsys/debug/coredump" and " tests/subsys/debug/coredump_backends" together, because the testcase “coredump.backends.logging” in "tests/subsys/debug/coredump_backends" is a console harness testcase, when it gets expected string from serial, it will stop, the other string will be captured by next testcase "tests/subsys/debug/coredump".
so the result will be like this:
result of coredump.backends.logging:

E: #CD:b9a9c80d3c6faa14894ac45e9eda4ad6ec1dc7bc86278a93645ec9d46f343b0f
E: #CD:954aa7f8a4abc572717fc0a0fb7b80449b44f79bb322a32df46607128487e2cd
E: #CD:48722359bef9b274d9051c41ef03e2da37deab1ce1b18a2990b103ef292e1a29
E: #CD:991783f2c5667992fcdb87d5e144a9ea03000000000000000000000010000000
E: #CD:0907000061490000260700000000004109070000614900000000000061490000
E: #CD:END#

result of coredump.logging_backend,

Test suite coredump_backends succeeded
PROJECT EXECUTION SUCCESSFUL

in actually, this is not the correct result of this testcase, it's the second part of last testcase "coredump.backends.logging" , because it captured the "PROJECT EXECUTION SUCCESSFUL", so it was judged as passed, however, the detail testcase is still failed.

I tried to change the harness to test of "coredump.backends.logging", it worked well.