Mbed-os: unstable Flash - clock and cache test for EV_COG_AD3029LZ nightly

[studavekar]

Description

This failure is seen multiple times in CI system, created a issue to track it. May be worn out flash?

Target
EV_COG_AD3029LZ

Toolchain:
GCC_ARM| ARM|IAR

mbed-os sha:

master

Steps to reproduce

Use command run : mbed test -m EV_COG_AD3029LZ -t GCC_ARM -n tests-mbed_hal-flash -v

Failure

[1538739399.56][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - program page;1;0}}, queued...
[1538739399.66][CONN][RXD] >>> Running case #5: 'Flash - clock and cache test'...
[1538739399.75][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - clock and cache test}}, queued...
[1538739401.03][CONN][RXD] :241::FAIL: Values Not Within Delta 2542 Expected 508585 Was 1153863
[1538739401.03][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - clock and cache test;0;1}}, queued...

logs snippet

[1538739391.93][GLRM][TXD] {{__sync;18ba3351-4452-43bf-be64-b5d203efea70}}
[1538739396.93][CONN][INF] resending new preamble 'e47e12d2-b5a3-4833-b623-1f273afb9072' after 5.00 sec
[1538739396.93][GLRM][TXD] {{__sync;e47e12d2-b5a3-4833-b623-1f273afb9072}}
[1538739397.03][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1538739397.12][CONN][INF] found SYNC in stream: {{__sync;e47e12d2-b5a3-4833-b623-1f273afb9072}} it is #1 sent, queued...
[1538739397.12][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1538739397.13][HTST][INF] sync KV found, uuid=e47e12d2-b5a3-4833-b623-1f273afb9072, timestamp=1538739397.124815
[1538739397.13][CONN][INF] found KV pair in stream: {{__timeout;20}}, queued...
[1538739397.13][HTST][INF] DUT greentea-client version: 1.3.0
[1538739397.13][HTST][INF] setting timeout to: 20 sec
[1538739397.22][CONN][RXD] >>> Running 5 test cases...
[1538739397.23][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
[1538739397.23][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
[1538739397.23][HTST][INF] host test setup() call...
[1538739397.23][HTST][INF] CALLBACKs updated
[1538739397.23][CONN][INF] found KV pair in stream: {{__testcase_count;5}}, queued...
[1538739397.23][HTST][INF] host test detected: default_auto
[1538739397.61][CONN][RXD] 
[1538739397.61][CONN][RXD] >>> Running case #1: 'Flash - init'...
[1538739397.61][CONN][INF] found KV pair in stream: {{__testcase_name;Flash - init}}, queued...
[1538739397.61][CONN][INF] found KV pair in stream: {{__testcase_name;Flash - mapping alignment}}, queued...
[1538739397.61][CONN][INF] found KV pair in stream: {{__testcase_name;Flash - erase sector}}, queued...
[1538739397.61][CONN][INF] found KV pair in stream: {{__testcase_name;Flash - program page}}, queued...
[1538739397.61][CONN][INF] found KV pair in stream: {{__testcase_name;Flash - clock and cache test}}, queued...
[1538739397.66][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - init}}, queued...
[1538739398.75][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - init;1;0}}, queued...
[1538739398.85][CONN][RXD] >>> 'Flash - init': 1 passed, 0 failed
[1538739398.85][CONN][RXD] 
[1538739398.95][CONN][RXD] >>> Running case #2: 'Flash - mapping alignment'...
[1538739398.95][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - mapping alignment}}, queued...
[1538739399.05][CONN][RXD] >>> 'Flash - mapping alignment': 1 passed, 0 failed
[1538739399.05][CONN][RXD] 
[1538739399.05][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - mapping alignment;1;0}}, queued...
[1538739399.15][CONN][RXD] >>> Running case #3: 'Flash - erase sector'...
[1538739399.15][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - erase sector}}, queued...
[1538739399.25][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - erase sector;1;0}}, queued...
[1538739399.36][CONN][RXD] >>> 'Flash - erase sector': 1 passed, 0 failed
[1538739399.36][CONN][RXD] 
[1538739399.36][CONN][RXD] >>> Running case #4: 'Flash - program page'...
[1538739399.46][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - program page}}, queued...
[1538739399.56][CONN][RXD] >>> 'Flash - program page': 1 passed, 0 failed
[1538739399.56][CONN][RXD] 
[1538739399.56][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - program page;1;0}}, queued...
[1538739399.66][CONN][RXD] >>> Running case #5: 'Flash - clock and cache test'...
[1538739399.75][CONN][INF] found KV pair in stream: {{__testcase_start;Flash - clock and cache test}}, queued...
[1538739401.03][CONN][RXD] :241::FAIL: Values Not Within Delta 2542 Expected 508585 Was 1153863
[1538739401.03][CONN][INF] found KV pair in stream: {{__testcase_finish;Flash - clock and cache test;0;1}}, queued...
[1538739401.11][CONN][RXD] >>> 'Flash - clock and cache test': 0 passed, 1 failed with reason 'Assertion Failed'
[1538739401.11][CONN][RXD] 
[1538739401.19][CONN][RXD] >>> Test cases: 4 passed, 1 failed with reason 'Assertion Failed'
[1538739401.19][CONN][RXD] >>> TESTS FAILED!
[1538739401.27][CONN][INF] found KV pair in stream: {{__testcase_summary;4;1}}, queued...
[1538739401.27][CONN][INF] found KV pair in stream: {{max_heap_usage;16}}, queued...
[1538739401.27][CONN][INF] found KV pair in stream: {{reserved_heap;11172}}, queued...
[1538739401.27][HTST][ERR] orphan event in main phase: {{max_heap_usage;16}}, timestamp=1538739401.274590
[1538739401.27][HTST][ERR] orphan event in main phase: {{reserved_heap;11172}}, timestamp=1538739401.274593
[1538739401.36][CONN][INF] found KV pair in stream: {{__thread_info;"0x0200045fc",956,4096}}, queued...
[1538739401.36][CONN][INF] found KV pair in stream: {{__thread_info;"0x0200405b4",64,512}}, queued...
[1538739401.36][HTST][ERR] orphan event in main phase: {{__thread_info;"0x0200045fc",956,4096}}, timestamp=1538739401.359284
[1538739401.36][HTST][ERR] orphan event in main phase: {{__thread_info;"0x0200405b4",64,512}}, timestamp=1538739401.359288
[1538739401.46][CONN][RXD] {{__cpu_info        up time;0}}
[1538739401.46][CONN][RXD] {{__cpu_info     sleep time;0}}
[1538739401.46][CONN][INF] found KV pair in stream: {{__thread_info;"0x020040570",104,768}}, queued...
[1538739401.46][HTST][ERR] orphan event in main phase: {{__thread_info;"0x020040570",104,768}}, timestamp=1538739401.458579
[1538739401.56][CONN][RXD] {{__cpu_info deepsleep time;0}}
[1538739401.56][CONN][RXD] {{__cpu_info  %  sleep/deep;0;0}}
[1538739401.56][CONN][INF] found KV pair in stream: {{end;failure}}, queued...
[1538739401.56][HTST][INF] __notify_complete(False)
[1538739401.56][HTST][INF] __exit_event_queue received
[1538739401.56][HTST][INF] test suite run finished after 4.43 sec...
[1538739401.56][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1538739401.56][urllib3.connectionpool]Starting new HTTP connection (1): iron-gatekeeper
[1538739401.65][urllib3.connectionpool]http://iron-gatekeeper:8000 "PUT /resource/0602000041114e4500173003b60f003da6e1000097969900/disconnect HTTP/1.1" 200 2
[1538739401.65][urllib3.connectionpool]Starting new HTTP connection (1): iron-gatekeeper
[1538739404.82][urllib3.connectionpool]http://iron-gatekeeper:8000 "PUT /resource/0602000041114e4500173003b60f003da6e1000097969900/release HTTP/1.1" 200 66
[1538739404.82][HTST][INF] CONN exited with code: 0
[1538739404.82][HTST][INF] No events in queue
[1538739404.82][HTST][INF] stopped consuming events
[1538739404.82][HTST][INF] host test result() call skipped, received: False
[1538739404.82][HTST][WRN] missing __exit event from DUT
[1538739404.82][HTST][INF] calling blocking teardown()
[1538739404.82][HTST][INF] teardown() finished
[1538739404.82][HTST][INF] {{result;failure}}

CC : @maclobdell @bentcooke

Issue request type

[ ] Question
[ ] Enhancement
[x] Bug

[bentcooke]

@ARMmbed/team-analogdevices

[studavekar]

Updated the ticket to make bot happy and hopefully it off HEADER FORMATTING ISSUE

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOCUSTRIA-119

[bentcooke]

I believe that the flash in that device may be past its usable life and has begun to fail. I have run the test five times in a row on another 3029 board with no failures.

[studavekar]

thanks @ben the devices in the current system are present for a long time. @OPpuolitaival whats the status on devices in new infra coming up?

[OPpuolitaival]

@studavekar we are still resolving some problems with new infra. It should be ready soon

[donatieng]

Is this still an issue?

[OPpuolitaival]

We have not seen this in new CI setup. This can be closed from my point of view. We can create new issue if still exists

[studavekar]

We have not seen this in new CI setup. This can be closed from my point of view. We can create new issue if still exists

@donatieng @OPpuolitaival issue is not since because this is not running in ci? Reference https://github.com/ARMmbed/mbed-os-ci/blob/master/mbed-os-jenkins/mbed-os-ci-greentea-test/Jenkinsfile.groovy#L68

if (["EV_COG_AD4050LZ", "EV_COG_AD3029LZ"].contains(target)) {
    // TODO: Add jira issue
    testsToSkip += ",tests-mbed_hal-flash"
}

[cmonr]

Second @studavekar's comments. This hasn't been an issue because the test isn't enabled in CI.

Would prefer to see the instances of // TODO: Add jira issue in the mbed-os-ci repo that disable tests to each have Jira issues before closing any in Mbed OS.

[OPpuolitaival]

@studavekar @cmonr we run nightly tests without ignore. Seems to be passing there. @alekla01 check the longer history

[studavekar]

@studavekar @cmonr we run nightly tests without ignore. Seems to be passing there. @alekla01 check the longer history

Unfortunately, above is not true test report says it still fails https://mbed-os.mbedcloudtesting.com/job/mbed-os-ci_greentea-test-nightly/78/testReport/junit/EV_COG_AD4050LZ-GCC_ARM/tests-mbed_hal-flash/EV_COG_AD4050LZ_arm_none_eabi_gcc___Flash___clock_and_cache_test/

[0xc0170]

Latest nightly run today (number 155) failed again. Logs are here http://mbed-os-ci.s3-website-eu-west-1.amazonaws.com/?prefix=jenkins-ci/ARMmbed/mbed-os/mbed-os-ci-nightly/artifacts/master/126/greentea-test/155/FAIL/ . To fix the nightly tests, these 2 targets shall be fixed or flashiap removed until it's fixed.

[0xc0170]

Latest nightly still show this error , logs can be found http://mbed-os-ci.s3-website-eu-west-1.amazonaws.com/?prefix=jenkins-ci/ARMmbed/mbed-os/mbed-os-ci-nightly/artifacts/master/224/greentea-test-HAL-Core/78/FAIL/EV_COG_AD3029LZ/

I suggest removing flash from device_has.

@bentcooke @ARMmbed/team-analogdevices

[bentcooke]

@0xc0170 were these boards ever replaced / refreshed in the CI? The flash endurance is ~10k cycles and at >500 tests per run the limit is hit rather quickly.

[0xc0170]

@0xc0170 were these boards ever replaced / refreshed in the CI? The flash endurance is ~10k cycles and at >500 tests per run the limit is hit rather quickly.

@ARMmbed/mbed-os-test Can you please verify?

[OPpuolitaival]

I think that we can close this now. I will reopen or create new one with fresh information if can see this happening again.

[0xc0170]

@OPpuolitaival If you look at nightly, latest results fail - can we test fresh new device to take out "worn flash" ?

I've checked as above 224, 226, 228 jobs and all show the failures.

the new ticket would help..

[li-ho]

Thanks for informing me. My GCC_ARM tests are totally passed as seen in attached file
190606-mbed-os-5.12.4.zip. My cog boards have not reached end of life.