Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Failing flashiap tests on DISCO_L475VG_IOT01A #7867

Closed
aashishc1988 opened this issue Aug 22, 2018 · 20 comments
Closed

Failing flashiap tests on DISCO_L475VG_IOT01A #7867

aashishc1988 opened this issue Aug 22, 2018 · 20 comments

Comments

@aashishc1988
Copy link
Contributor

Description

  • Type: Bug
  • Priority: Major

Bug

Target
DISCO_L475VG_IOT01A

Toolchain:
GCC_ARM

Tests we are failing:
tests-mbed_drivers-flashiap

Steps to reproduce

mbed test -m DISCO_L475VG_IOT01A -t GCC_ARM -n tests-mbed_drivers-flashiap -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLED=1 -DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED -v

log snippet

> 
00:36:46.718 	calling mbedhtrun: mbedhtrun -m DISCO_L475VG_IOT01A -p DUMMY:9600 -f "BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.bin" -e "TESTS/host_tests" --grm raas_client:goku.austin.arm.com:8000 -C 4 --sync 10 -P 120
00:36:46.718 mbedgt: mbed-host-test-runner: started
00:36:47.637 [1534961277.58][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
00:36:47.697 [1534961277.64][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
00:36:47.727 [1534961277.67][HTST][INF] host test executor ver. 1.4.0
00:36:47.727 [1534961277.67][HTST][INF] copy image onto target... SKIPPED!
00:36:47.728 [1534961277.67][HTST][INF] starting host test process...
00:36:47.766 [1534961277.71][CONN][INF] starting connection process...
00:36:47.766 [1534961277.71][CONN][INF] notify event queue about extra 120 sec timeout for serial port pooling
00:36:47.766 [1534961277.71][CONN][INF] initializing global resource mgr listener...
00:36:47.783 [1534961277.73][HTST][INF] setting timeout to: 120 sec
00:36:47.873 [1534961277.82][GLRM][INF] remote resources initialization: remote(host=goku.austin.arm.com, port=8000)
00:36:47.874 [1534961277.82][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.884 [1534961277.83][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /login HTTP/1.1" 200 213
00:36:47.887 [1534961277.83][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.890 [1534961277.83][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzQ5NjEyNzcsImV4cCI6MTUzNTU2NjA3N30.8QnknQdsau-q88KX7wmRBUfkmaFbPEfwRpMkvo7kluQ&EIO=3&transport=polling&t=1534961277829-0 HTTP/1.1" 200 101
00:36:47.936 [1534961277.88][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.938 [1534961277.88][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /this/resource HTTP/1.1" 200 3660
00:36:47.939 [1534961277.88][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.950 [1534961277.89][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource HTTP/1.1" 200 60033
00:36:47.950 [1534961277.89][GLRM][INF] remote resources count: 40
00:36:47.959 [1534961277.90][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.963 [1534961277.90][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource/07640221144368082B07FE51 HTTP/1.1" 200 1626
00:36:47.963 [1534961277.91][GLRM][INF] remote resources flashing with 'BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.bin'...
00:36:47.963 [1534961277.91][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:36:47.967 [1534961277.91][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /file HTTP/1.1" 200 244
00:37:00.060 [1534961290.00][GLRM][INF] opening connection to platform at baudrate='9600'
00:37:00.060 [1534961290.00][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:37:00.251 [1534961290.19][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/connect HTTP/1.1" 200 15
00:37:00.251 [1534961290.19][GLRM][INF] remote resources reset...
00:37:02.572 [1534961292.51][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
00:37:02.572 [1534961292.51][CONN][INF] sending up to 10 __sync packets (specified with --sync=10)
00:37:02.572 [1534961292.51][CONN][INF] sending preamble '5550bb3e-1f57-481b-a077-e24267829bde'
00:37:02.573 [1534961292.52][GLRM][TXD] {{__sync;5550bb3e-1f57-481b-a077-e24267829bde}}
00:37:03.657 [1534961293.60][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
00:37:03.657 [1534961293.60][CONN][INF] found SYNC in stream: {{__sync;5550bb3e-1f57-481b-a077-e24267829bde}} it is #0 sent, queued...
00:37:03.657 [1534961293.60][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
00:37:03.657 [1534961293.60][HTST][INF] sync KV found, uuid=5550bb3e-1f57-481b-a077-e24267829bde, timestamp=1534961293.600190
00:37:03.657 [1534961293.60][HTST][INF] DUT greentea-client version: 1.3.0
00:37:03.883 [1534961293.83][CONN][INF] found KV pair in stream: {{__timeout;120}}, queued...
00:37:03.883 [1534961293.83][HTST][INF] setting timeout to: 120 sec
00:37:03.883 [1534961293.83][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
00:37:03.883 [1534961293.83][HTST][INF] host test setup() call...
00:37:03.883 [1534961293.83][HTST][INF] CALLBACKs updated
00:37:03.883 [1534961293.83][HTST][INF] host test detected: default_auto
00:37:03.883 [1534961293.83][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
00:37:03.884 [1534961293.83][CONN][INF] found KV pair in stream: {{__testcase_count;5}}, queued...
00:37:03.919 [1534961293.86][CONN][RXD] >>> Running 5 test cases...
00:37:03.919 [1534961293.86][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - init}}, queued...
00:37:03.919 [1534961293.86][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program}}, queued...
00:37:03.989 [1534961293.93][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program across sectors}}, queued...
00:37:03.989 [1534961293.93][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program errors}}, queued...
00:37:04.069 [1534961294.01][CONN][RXD]
00:37:04.069 [1534961294.01][CONN][RXD] >>> Running case #1: 'FlashIAP - init'...
00:37:04.070 [1534961294.01][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - timing}}, queued...
00:37:04.152 [1534961294.10][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - init}}, queued...
00:37:04.152 [1534961294.10][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - init;1;0}}, queued...
00:37:04.252 [1534961294.20][CONN][RXD] >>> 'FlashIAP - init': 1 passed, 0 failed
00:37:04.252 [1534961294.20][CONN][RXD]
00:37:04.252 [1534961294.20][CONN][RXD] >>> Running case #2: 'FlashIAP - program'...
00:37:04.253 [1534961294.20][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program}}, queued...
00:37:04.453 [1534961294.40][CONN][RXD] >>> 'FlashIAP - program': 1 passed, 0 failed
00:37:04.453 [1534961294.40][CONN][RXD]
00:37:04.453 [1534961294.40][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program;1;0}}, queued...
00:37:04.554 [1534961294.50][CONN][RXD] >>> Running case #3: 'FlashIAP - program across sectors'...
00:37:04.554 [1534961294.50][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program across sectors}}, queued...
00:37:04.654 [1534961294.60][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program across sectors;1;0}}, queued...
00:37:04.753 [1534961294.70][CONN][RXD] >>> 'FlashIAP - program across sectors': 1 passed, 0 failed
00:37:04.753 [1534961294.70][CONN][RXD]
00:37:04.853 [1534961294.80][CONN][RXD] >>> Running case #4: 'FlashIAP - program errors'...
00:37:04.853 [1534961294.80][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program errors}}, queued...
00:37:04.953 [1534961294.90][CONN][RXD] >>> 'FlashIAP - program errors': 1 passed, 0 failed
00:37:04.953 [1534961294.90][CONN][RXD]
00:37:04.953 [1534961294.90][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program errors;1;0}}, queued...
00:37:05.056 [1534961295.00][CONN][RXD] >>> Running case #5: 'FlashIAP - timing'...
00:37:05.056 [1534961295.00][CONN][RXD]
00:37:05.056 [1534961295.00][CONN][RXD] Flash timing:
00:37:05.056 [1534961295.00][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - timing}}, queued...
00:37:05.156 [1534961295.10][CONN][RXD] Write size      8 bytes: avg        121, min        118, max        125 (usec)
00:37:05.356 [1534961295.30][CONN][RXD] Write size     32 bytes: avg        424, min        421, max        432 (usec)
00:37:05.456 [1534961295.40][CONN][RXD] Write size    128 bytes: avg       1636, min       1633, max       1645 (usec)
00:37:05.456 [1534961295.40][CONN][RXD]
00:37:05.457 [1534961295.40][CONN][RXD] ++ MbedOS Fault Handler ++
00:37:05.457 [1534961295.40][CONN][RXD]
00:37:05.568 [1534961295.51][CONN][RXD] FaultType: HardFault
00:37:05.568 [1534961295.51][CONN][RXD]
00:37:05.568 [1534961295.51][CONN][RXD] Context:
00:37:05.568 [1534961295.51][CONN][RXD] R0   : 00000000
00:37:05.568 [1534961295.51][CONN][RXD] R1   : 2000079C
00:37:05.568 [1534961295.51][CONN][RXD] R2   : 1FFD1F5A
00:37:05.568 [1534961295.51][CONN][RXD] R3   : FFFCF12A
00:37:05.568 [1534961295.51][CONN][RXD] R4   : 20002E30
00:37:05.679 [1534961295.62][CONN][RXD] R5   : 20002E38
00:37:05.679 [1534961295.62][CONN][RXD] R6   : 20003020
00:37:05.680 [1534961295.62][CONN][RXD] R7   : FFFCF12B
00:37:05.680 [1534961295.62][CONN][RXD] R8   : 20000208
00:37:05.680 [1534961295.62][CONN][RXD] R9   : 00000FE0
00:37:05.680 [1534961295.62][CONN][RXD] R10  : 00000008
00:37:05.766 [1534961295.71][CONN][RXD] R11  : 00001000
00:37:05.767 [1534961295.71][CONN][RXD] R12  : 08005555
00:37:05.767 [1534961295.71][CONN][RXD] SP   : 200028D0
00:37:05.767 [1534961295.71][CONN][RXD] LR   : 0800575F
00:37:05.768 [1534961295.71][CONN][RXD] PC   : 080097FA
00:37:05.769 [1534961295.71][CONN][RXD] xPSR : 21010000
00:37:05.924 [1534961295.87][CONN][RXD] PSP  : 20002868
00:37:05.924 [1534961295.87][CONN][RXD] MSP  : 10007FD8
00:37:05.924 [1534961295.87][CONN][RXD] CPUID: 410FC241
00:37:05.924 [1534961295.87][CONN][RXD] HFSR : 40000000
00:37:05.925 [1534961295.87][CONN][RXD] MMFSR: 00000000
00:37:05.925 [1534961295.87][CONN][RXD] BFSR : 00000082
00:37:05.956 [1534961295.90][CONN][RXD] UFSR : 00000000
00:37:05.957 [1534961295.90][CONN][RXD] DFSR : 00000008
00:37:05.957 [1534961295.90][CONN][RXD] AFSR : 00000000
00:37:05.957 [1534961295.90][CONN][RXD] BFAR : 1FFD1F5E
00:37:05.957 [1534961295.90][CONN][RXD] Mode : Thread
00:37:05.958 [1534961295.90][CONN][RXD] Priv : Privileged
00:37:06.088 [1534961296.03][CONN][RXD] Stack: PSP
00:37:06.088 [1534961296.03][CONN][RXD]
00:37:06.089 [1534961296.03][CONN][RXD] -- MbedOS Fault Handler --
00:37:06.089 [1534961296.03][CONN][RXD]
00:37:06.089 [1534961296.03][CONN][RXD]
00:37:06.089 [1534961296.03][CONN][RXD]
00:37:06.090 [1534961296.03][CONN][RXD] ++ MbedOS Error Info ++
00:37:06.198 [1534961296.14][CONN][RXD] Error Status: 0x80FF013D Code: 317 Module: 255
00:37:06.198 [1534961296.14][CONN][RXD] Error Message: Fault exception
00:37:06.198 [1534961296.14][CONN][RXD] Location: 0x80045D3
00:37:06.198 [1534961296.14][CONN][RXD] Error Value: 0x80097FA
00:37:06.528 [1534961296.47][CONN][RXD] Current Thread: Id: 0x20001A0C Entry: 0x8004629 StackSize: 0x1000 StackMem: 0x20001A58 SP: 0x10007F70
00:37:06.528 [1534961296.47][CONN][RXD] -- MbedOS Error Info --
00:39:04.710 [1534961414.65][HTST][INF] test suite run finished after 120.82 sec...
00:39:04.710 [1534961414.65][CONN][INF] received special event '__host_test_finished' value='True', finishing
00:39:04.711 [1534961414.65][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:04.763 [1534961414.70][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/disconnect HTTP/1.1" 200 2
00:39:04.768 [1534961414.71][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:07.926 [1534961417.86][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/release HTTP/1.1" 200 42
00:39:07.932 [1534961417.87][HTST][INF] CONN exited with code: 0
00:39:07.932 [1534961417.87][HTST][INF] No events in queue
00:39:07.932 [1534961417.87][HTST][INF] stopped consuming events
00:39:07.932 [1534961417.87][HTST][INF] host test result(): None
00:39:07.932 [1534961417.87][HTST][WRN] missing __exit event from DUT
00:39:07.932 [1534961417.87][HTST][WRN] missing __exit_event_queue event from host test
00:39:07.932 [1534961417.87][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
00:39:07.932 [1534961417.87][HTST][INF] calling blocking teardown()
00:39:07.932 [1534961417.87][HTST][INF] teardown() finished
00:39:07.932 [1534961417.87][HTST][INF] {{result;timeout}}
00:39:07.959 mbedgt: retry mbedhtrun 1/3
00:39:08.361 [1534961418.30][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
00:39:08.396 [1534961418.33][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
00:39:08.402 [1534961418.34][HTST][INF] host test executor ver. 1.4.0
00:39:08.402 [1534961418.34][HTST][INF] copy image onto target... SKIPPED!
00:39:08.406 [1534961418.34][HTST][INF] starting host test process...
00:39:08.407 [1534961418.35][CONN][INF] starting connection process...
00:39:08.429 [1534961418.36][CONN][INF] notify event queue about extra 120 sec timeout for serial port pooling
00:39:08.429 [1534961418.36][CONN][INF] initializing global resource mgr listener...
00:39:08.441 [1534961418.38][HTST][INF] setting timeout to: 120 sec
00:39:08.527 [1534961418.46][GLRM][INF] remote resources initialization: remote(host=goku.austin.arm.com, port=8000)
00:39:08.527 [1534961418.47][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.528 [1534961418.47][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /login HTTP/1.1" 200 213
00:39:08.534 [1534961418.47][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.537 [1534961418.48][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzQ5NjE0MTgsImV4cCI6MTUzNTU2NjIxOH0.p5gWM99RQMbJehTa5t02Ih9nTN9OVv0fX67AKI54EzY&EIO=3&transport=polling&t=1534961418470-0 HTTP/1.1" 200 101
00:39:08.598 [1534961418.54][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.602 [1534961418.54][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /this/resource HTTP/1.1" 200 3660
00:39:08.603 [1534961418.54][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.612 [1534961418.55][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource HTTP/1.1" 200 59858
00:39:08.616 [1534961418.56][GLRM][INF] remote resources count: 40
00:39:08.627 [1534961418.57][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.640 [1534961418.58][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource/07640221144368082B07FE51 HTTP/1.1" 200 1619
00:39:08.645 [1534961418.58][GLRM][INF] remote resources flashing with 'BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.bin'...
00:39:08.645 [1534961418.58][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:08.645 [1534961418.59][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /file HTTP/1.1" 200 244
00:39:20.677 [1534961430.62][GLRM][INF] opening connection to platform at baudrate='9600'
00:39:20.678 [1534961430.62][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:39:20.811 [1534961430.75][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/connect HTTP/1.1" 200 15
00:39:20.812 [1534961430.75][GLRM][INF] remote resources reset...
00:39:23.022 [1534961432.96][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
00:39:23.022 [1534961432.96][CONN][INF] sending up to 10 __sync packets (specified with --sync=10)
00:39:23.022 [1534961432.96][CONN][INF] sending preamble '2dd3b104-e35a-4acd-990b-4bd25c98964b'
00:39:23.023 [1534961432.96][GLRM][TXD] {{__sync;2dd3b104-e35a-4acd-990b-4bd25c98964b}}
00:39:24.220 [1534961434.16][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
00:39:24.220 [1534961434.16][CONN][INF] found SYNC in stream: {{__sync;2dd3b104-e35a-4acd-990b-4bd25c98964b}} it is #0 sent, queued...
00:39:24.221 [1534961434.16][HTST][INF] sync KV found, uuid=2dd3b104-e35a-4acd-990b-4bd25c98964b, timestamp=1534961434.161482
00:39:24.320 [1534961434.26][HTST][INF] DUT greentea-client version: 1.3.0
00:39:24.320 [1534961434.26][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
00:39:24.320 [1534961434.26][CONN][INF] found KV pair in stream: {{__timeout;120}}, queued...
00:39:24.321 [1534961434.26][HTST][INF] setting timeout to: 120 sec
00:39:24.321 [1534961434.26][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
00:39:24.321 [1534961434.26][CONN][INF] found KV pair in stream: {{__testcase_count;5}}, queued...
00:39:24.321 [1534961434.26][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
00:39:24.321 [1534961434.26][HTST][INF] host test setup() call...
00:39:24.321 [1534961434.26][HTST][INF] CALLBACKs updated
00:39:24.321 [1534961434.26][HTST][INF] host test detected: default_auto
00:39:24.420 [1534961434.36][CONN][RXD] >>> Running 5 test cases...
00:39:24.420 [1534961434.36][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - init}}, queued...
00:39:24.420 [1534961434.36][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program}}, queued...
00:39:24.599 [1534961434.54][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program across sectors}}, queued...
00:39:24.599 [1534961434.54][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program errors}}, queued...
00:39:24.628 [1534961434.57][CONN][RXD]
00:39:24.628 [1534961434.57][CONN][RXD] >>> Running case #1: 'FlashIAP - init'...
00:39:24.629 [1534961434.57][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - timing}}, queued...
00:39:24.720 [1534961434.66][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - init}}, queued...
00:39:24.721 [1534961434.66][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - init;1;0}}, queued...
00:39:24.820 [1534961434.76][CONN][RXD] >>> 'FlashIAP - init': 1 passed, 0 failed
00:39:24.820 [1534961434.76][CONN][RXD]
00:39:24.821 [1534961434.76][CONN][RXD] >>> Running case #2: 'FlashIAP - program'...
00:39:24.821 [1534961434.76][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program}}, queued...
00:39:25.021 [1534961434.96][CONN][RXD] >>> 'FlashIAP - program': 1 passed, 0 failed
00:39:25.021 [1534961434.96][CONN][RXD]
00:39:25.021 [1534961434.96][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program;1;0}}, queued...
00:39:25.122 [1534961435.06][CONN][RXD] >>> Running case #3: 'FlashIAP - program across sectors'...
00:39:25.122 [1534961435.06][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program across sectors}}, queued...
00:39:25.221 [1534961435.16][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program across sectors;1;0}}, queued...
00:39:25.323 [1534961435.26][CONN][RXD] >>> 'FlashIAP - program across sectors': 1 passed, 0 failed
00:39:25.323 [1534961435.26][CONN][RXD]
00:39:25.421 [1534961435.36][CONN][RXD] >>> Running case #4: 'FlashIAP - program errors'...
00:39:25.422 [1534961435.36][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program errors}}, queued...
00:39:25.521 [1534961435.46][CONN][RXD] >>> 'FlashIAP - program errors': 1 passed, 0 failed
00:39:25.522 [1534961435.46][CONN][RXD]
00:39:25.522 [1534961435.46][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program errors;1;0}}, queued...
00:39:25.622 [1534961435.56][CONN][RXD] >>> Running case #5: 'FlashIAP - timing'...
00:39:25.622 [1534961435.56][CONN][RXD]
00:39:25.622 [1534961435.56][CONN][RXD] Flash timing:
00:39:25.622 [1534961435.56][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - timing}}, queued...
00:39:25.722 [1534961435.66][CONN][RXD] Write size      8 bytes: avg        121, min        118, max        125 (usec)
00:39:25.922 [1534961435.86][CONN][RXD] Write size     32 bytes: avg        424, min        421, max        431 (usec)
00:39:26.173 [1534961436.11][CONN][RXD] Write size    128 bytes: avg       1636, min       1632, max       1645 (usec)
00:39:26.174 [1534961436.11][CONN][RXD]
00:39:26.174 [1534961436.12][CONN][RXD] ++ MbedOS Fault Handler ++
00:39:26.174 [1534961436.12][CONN][RXD]
00:39:26.174 [1534961436.12][CONN][RXD] FaultType: HardFault
00:39:26.174 [1534961436.12][CONN][RXD]
00:39:26.174 [1534961436.12][CONN][RXD] Context:
00:39:26.174 [1534961436.12][CONN][RXD] R0   : 00000000
00:39:26.175 [1534961436.12][CONN][RXD] R1   : 2000079C
00:39:26.175 [1534961436.12][CONN][RXD] R2   : 1FFD1F5A
00:39:26.175 [1534961436.12][CONN][RXD] R3   : FFFCF12A
00:39:26.223 [1534961436.16][CONN][RXD] R4   : 20002E30
00:39:26.223 [1534961436.16][CONN][RXD] R5   : 20002E38
00:39:26.223 [1534961436.16][CONN][RXD] R6   : 20003020
00:39:26.223 [1534961436.16][CONN][RXD] R7   : FFFCF12B
00:39:26.223 [1534961436.16][CONN][RXD] R8   : 20000208
00:39:26.223 [1534961436.16][CONN][RXD] R9   : 00000FE0
00:39:26.322 [1534961436.26][CONN][RXD] R10  : 00000008
00:39:26.322 [1534961436.26][CONN][RXD] R11  : 00001000
00:39:26.322 [1534961436.26][CONN][RXD] R12  : 08005555
00:39:26.322 [1534961436.26][CONN][RXD] SP   : 200028D0
00:39:26.322 [1534961436.26][CONN][RXD] LR   : 0800575F
00:39:26.323 [1534961436.26][CONN][RXD] PC   : 080097FA
00:39:26.422 [1534961436.36][CONN][RXD] xPSR : 21010000
00:39:26.422 [1534961436.36][CONN][RXD] PSP  : 20002868
00:39:26.422 [1534961436.36][CONN][RXD] MSP  : 10007FD8
00:39:26.423 [1534961436.36][CONN][RXD] CPUID: 410FC241
00:39:26.423 [1534961436.36][CONN][RXD] HFSR : 40000000
00:39:26.423 [1534961436.36][CONN][RXD] MMFSR: 00000000
00:39:26.704 [1534961436.64][CONN][RXD] BFSR : 00000082
00:39:26.704 [1534961436.64][CONN][RXD] UFSR : 00000000
00:39:26.704 [1534961436.65][CONN][RXD] DFSR : 00000008
00:39:26.704 [1534961436.65][CONN][RXD] AFSR : 00000000
00:39:26.704 [1534961436.65][CONN][RXD] BFAR : 1FFD1F5E
00:39:26.704 [1534961436.65][CONN][RXD] Mode : Thread
00:39:26.705 [1534961436.65][CONN][RXD] Priv : Privileged
00:39:26.705 [1534961436.65][CONN][RXD] Stack: PSP
00:39:26.705 [1534961436.65][CONN][RXD]
00:39:26.705 [1534961436.65][CONN][RXD] -- MbedOS Fault Handler --
00:39:26.705 [1534961436.65][CONN][RXD]
00:39:26.705 [1534961436.65][CONN][RXD]
00:39:26.705 [1534961436.65][CONN][RXD]
00:39:26.705 [1534961436.65][CONN][RXD] ++ MbedOS Error Info ++
00:39:26.765 [1534961436.71][CONN][RXD] Error Status: 0x80FF013D Code: 317 Module: 255
00:39:26.765 [1534961436.71][CONN][RXD] Error Message: Fault exception
00:39:26.765 [1534961436.71][CONN][RXD] Location: 0x80045D3
00:39:26.765 [1534961436.71][CONN][RXD] Error Value: 0x80097FA
00:39:26.927 [1534961436.87][CONN][RXD] Current Thread: Id: 0x20001A0C Entry: 0x8004629 StackSize: 0x1000 StackMem: 0x20001A58 SP: 0x10007F70
00:39:26.927 [1534961436.87][CONN][RXD] -- MbedOS Error Info --
00:41:25.102 [1534961555.04][HTST][INF] test suite run finished after 120.78 sec...
00:41:25.118 [1534961555.06][CONN][INF] received special event '__host_test_finished' value='True', finishing
00:41:25.119 [1534961555.06][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:25.154 [1534961555.09][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/disconnect HTTP/1.1" 200 2
00:41:25.155 [1534961555.10][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.308 [1534961558.25][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/release HTTP/1.1" 200 42
00:41:28.313 [1534961558.25][HTST][INF] CONN exited with code: 0
00:41:28.313 [1534961558.25][HTST][INF] No events in queue
00:41:28.314 [1534961558.25][HTST][INF] stopped consuming events
00:41:28.314 [1534961558.25][HTST][INF] host test result(): None
00:41:28.314 [1534961558.25][HTST][WRN] missing __exit event from DUT
00:41:28.315 [1534961558.26][HTST][WRN] missing __exit_event_queue event from host test
00:41:28.315 [1534961558.26][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
00:41:28.315 [1534961558.26][HTST][INF] calling blocking teardown()
00:41:28.315 [1534961558.26][HTST][INF] teardown() finished
00:41:28.315 [1534961558.26][HTST][INF] {{result;timeout}}
00:41:28.341 mbedgt: retry mbedhtrun 2/3
00:41:28.620 [1534961558.56][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/Grammar.txt
00:41:28.635 [1534961558.58][root]Generating grammar tables from /usr/lib/python2.7/lib2to3/PatternGrammar.txt
00:41:28.642 [1534961558.58][HTST][INF] host test executor ver. 1.4.0
00:41:28.642 [1534961558.58][HTST][INF] copy image onto target... SKIPPED!
00:41:28.643 [1534961558.58][HTST][INF] starting host test process...
00:41:28.645 [1534961558.59][CONN][INF] starting connection process...
00:41:28.646 [1534961558.59][CONN][INF] notify event queue about extra 120 sec timeout for serial port pooling
00:41:28.646 [1534961558.59][CONN][INF] initializing global resource mgr listener...
00:41:28.647 [1534961558.59][HTST][INF] setting timeout to: 120 sec
00:41:28.684 [1534961558.62][GLRM][INF] remote resources initialization: remote(host=goku.austin.arm.com, port=8000)
00:41:28.688 [1534961558.63][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.688 [1534961558.63][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /login HTTP/1.1" 200 213
00:41:28.688 [1534961558.63][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.689 [1534961558.63][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzQ5NjE1NTgsImV4cCI6MTUzNTU2NjM1OH0.ofXR1hngENtEaj2SdJuPJmD11OWDSYknfQmTLTmNoJM&EIO=3&transport=polling&t=1534961558627-0 HTTP/1.1" 200 101
00:41:28.692 [1534961558.63][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.693 [1534961558.63][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /this/resource HTTP/1.1" 200 3660
00:41:28.694 [1534961558.63][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.699 [1534961558.64][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource HTTP/1.1" 200 59598
00:41:28.701 [1534961558.64][GLRM][INF] remote resources count: 40
00:41:28.710 [1534961558.65][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.711 [1534961558.65][urllib3.connectionpool]http://goku.austin.arm.com:8000 "GET /resource/07640221144368082B07FE51 HTTP/1.1" 200 1619
00:41:28.712 [1534961558.65][GLRM][INF] remote resources flashing with 'BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.bin'...
00:41:28.712 [1534961558.65][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:28.716 [1534961558.66][urllib3.connectionpool]http://goku.austin.arm.com:8000 "POST /file HTTP/1.1" 200 244
00:41:40.658 [1534961570.60][GLRM][INF] opening connection to platform at baudrate='9600'
00:41:40.659 [1534961570.60][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:41:40.801 [1534961570.74][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/connect HTTP/1.1" 200 15
00:41:40.802 [1534961570.74][GLRM][INF] remote resources reset...
00:41:42.975 [1534961572.92][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
00:41:42.975 [1534961572.92][CONN][INF] sending up to 10 __sync packets (specified with --sync=10)
00:41:42.976 [1534961572.92][CONN][INF] sending preamble '21003a3d-059e-4397-9621-511e808f3932'
00:41:42.977 [1534961572.92][GLRM][TXD] {{__sync;21003a3d-059e-4397-9621-511e808f3932}}
00:41:44.179 [1534961574.12][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
00:41:44.180 [1534961574.12][HTST][INF] sync KV found, uuid=21003a3d-059e-4397-9621-511e808f3932, timestamp=1534961574.120236
00:41:44.180 [1534961574.12][CONN][INF] found SYNC in stream: {{__sync;21003a3d-059e-4397-9621-511e808f3932}} it is #0 sent, queued...
00:41:44.279 [1534961574.22][HTST][INF] DUT greentea-client version: 1.3.0
00:41:44.279 [1534961574.22][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
00:41:44.280 [1534961574.22][HTST][INF] setting timeout to: 120 sec
00:41:44.280 [1534961574.22][CONN][INF] found KV pair in stream: {{__timeout;120}}, queued...
00:41:44.280 [1534961574.22][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
00:41:44.280 [1534961574.22][HTST][INF] host test setup() call...
00:41:44.280 [1534961574.22][HTST][INF] CALLBACKs updated
00:41:44.280 [1534961574.22][HTST][INF] host test detected: default_auto
00:41:44.281 [1534961574.22][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
00:41:44.281 [1534961574.22][CONN][INF] found KV pair in stream: {{__testcase_count;5}}, queued...
00:41:44.379 [1534961574.32][CONN][RXD] >>> Running 5 test cases...
00:41:44.379 [1534961574.32][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - init}}, queued...
00:41:44.508 [1534961574.45][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program}}, queued...
00:41:44.508 [1534961574.45][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program across sectors}}, queued...
00:41:44.588 [1534961574.53][CONN][RXD]
00:41:44.588 [1534961574.53][CONN][RXD] >>> Running case #1: 'FlashIAP - init'...
00:41:44.588 [1534961574.53][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - program errors}}, queued...
00:41:44.588 [1534961574.53][CONN][INF] found KV pair in stream: {{__testcase_name;FlashIAP - timing}}, queued...
00:41:44.681 [1534961574.62][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - init}}, queued...
00:41:44.681 [1534961574.62][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - init;1;0}}, queued...
00:41:44.782 [1534961574.72][CONN][RXD] >>> 'FlashIAP - init': 1 passed, 0 failed
00:41:44.783 [1534961574.72][CONN][RXD]
00:41:44.783 [1534961574.72][CONN][RXD] >>> Running case #2: 'FlashIAP - program'...
00:41:44.883 [1534961574.82][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program}}, queued...
00:41:44.981 [1534961574.92][CONN][RXD] >>> 'FlashIAP - program': 1 passed, 0 failed
00:41:44.981 [1534961574.92][CONN][RXD]
00:41:44.981 [1534961574.92][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program;1;0}}, queued...
00:41:45.087 [1534961575.03][CONN][RXD] >>> Running case #3: 'FlashIAP - program across sectors'...
00:41:45.182 [1534961575.12][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program across sectors}}, queued...
00:41:45.283 [1534961575.22][CONN][RXD] >>> 'FlashIAP - program across sectors': 1 passed, 0 failed
00:41:45.283 [1534961575.22][CONN][RXD]
00:41:45.283 [1534961575.22][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program across sectors;1;0}}, queued...
00:41:45.382 [1534961575.32][CONN][RXD] >>> Running case #4: 'FlashIAP - program errors'...
00:41:45.382 [1534961575.32][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - program errors}}, queued...
00:41:45.590 [1534961575.53][CONN][RXD] >>> 'FlashIAP - program errors': 1 passed, 0 failed
00:41:45.590 [1534961575.53][CONN][RXD]
00:41:45.590 [1534961575.53][CONN][INF] found KV pair in stream: {{__testcase_finish;FlashIAP - program errors;1;0}}, queued...
00:41:45.591 [1534961575.53][CONN][RXD] >>> Running case #5: 'FlashIAP - timing'...
00:41:45.591 [1534961575.53][CONN][RXD]
00:41:45.591 [1534961575.53][CONN][RXD] Flash timing:
00:41:45.591 [1534961575.53][CONN][INF] found KV pair in stream: {{__testcase_start;FlashIAP - timing}}, queued...
00:41:45.784 [1534961575.72][CONN][RXD] Write size      8 bytes: avg        121, min        118, max        125 (usec)
00:41:45.885 [1534961575.83][CONN][RXD] Write size     32 bytes: avg        424, min        421, max        429 (usec)
00:41:46.129 [1534961576.06][CONN][RXD] Write size    128 bytes: avg       1636, min       1632, max       1645 (usec)
00:41:46.129 [1534961576.06][CONN][RXD]
00:41:46.129 [1534961576.06][CONN][RXD] ++ MbedOS Fault Handler ++
00:41:46.129 [1534961576.06][CONN][RXD]
00:41:46.129 [1534961576.06][CONN][RXD] FaultType: HardFault
00:41:46.129 [1534961576.06][CONN][RXD]
00:41:46.129 [1534961576.06][CONN][RXD] Context:
00:41:46.129 [1534961576.06][CONN][RXD] R0   : 00000000
00:41:46.129 [1534961576.06][CONN][RXD] R1   : 2000079C
00:41:46.129 [1534961576.06][CONN][RXD] R2   : 1FFD1F5A
00:41:46.129 [1534961576.06][CONN][RXD] R3   : FFFCF12A
00:41:46.184 [1534961576.12][CONN][RXD] R4   : 20002E30
00:41:46.184 [1534961576.12][CONN][RXD] R5   : 20002E38
00:41:46.184 [1534961576.12][CONN][RXD] R6   : 20003020
00:41:46.184 [1534961576.12][CONN][RXD] R7   : FFFCF12B
00:41:46.184 [1534961576.12][CONN][RXD] R8   : 20000208
00:41:46.184 [1534961576.12][CONN][RXD] R9   : 00000FE0
00:41:46.284 [1534961576.22][CONN][RXD] R10  : 00000008
00:41:46.284 [1534961576.22][CONN][RXD] R11  : 00001000
00:41:46.284 [1534961576.22][CONN][RXD] R12  : 08005555
00:41:46.284 [1534961576.22][CONN][RXD] SP   : 200028D0
00:41:46.284 [1534961576.23][CONN][RXD] LR   : 0800575F
00:41:46.284 [1534961576.23][CONN][RXD] PC   : 080097FA
00:41:46.391 [1534961576.33][CONN][RXD] xPSR : 21010000
00:41:46.391 [1534961576.33][CONN][RXD] PSP  : 20002868
00:41:46.391 [1534961576.33][CONN][RXD] MSP  : 10007FD8
00:41:46.391 [1534961576.33][CONN][RXD] CPUID: 410FC241
00:41:46.397 [1534961576.34][CONN][RXD] HFSR : 40000000
00:41:46.397 [1534961576.34][CONN][RXD] MMFSR: 00000000
00:41:46.631 [1534961576.57][CONN][RXD] BFSR : 00000082
00:41:46.631 [1534961576.57][CONN][RXD] UFSR : 00000000
00:41:46.632 [1534961576.57][CONN][RXD] DFSR : 00000008
00:41:46.632 [1534961576.57][CONN][RXD] AFSR : 00000000
00:41:46.633 [1534961576.57][CONN][RXD] BFAR : 1FFD1F5E
00:41:46.633 [1534961576.57][CONN][RXD] Mode : Thread
00:41:46.633 [1534961576.57][CONN][RXD] Priv : Privileged
00:41:46.634 [1534961576.57][CONN][RXD] Stack: PSP
00:41:46.634 [1534961576.57][CONN][RXD]
00:41:46.634 [1534961576.58][CONN][RXD] -- MbedOS Fault Handler --
00:41:46.635 [1534961576.58][CONN][RXD]
00:41:46.635 [1534961576.58][CONN][RXD]
00:41:46.635 [1534961576.58][CONN][RXD]
00:41:46.636 [1534961576.58][CONN][RXD] ++ MbedOS Error Info ++
00:41:46.685 [1534961576.63][CONN][RXD] Error Status: 0x80FF013D Code: 317 Module: 255
00:41:46.685 [1534961576.63][CONN][RXD] Error Message: Fault exception
00:41:46.685 [1534961576.63][CONN][RXD] Location: 0x80045D3
00:41:46.785 [1534961576.73][CONN][RXD] Error Value: 0x80097FA
00:41:46.885 [1534961576.83][CONN][RXD] Current Thread: Id: 0x20001A0C Entry: 0x8004629 StackSize: 0x1000 StackMem: 0x20001A58 SP: 0x10007F70
00:41:46.886 [1534961576.83][CONN][RXD] -- MbedOS Error Info --
00:43:45.092 [1534961695.03][HTST][INF] test suite run finished after 120.81 sec...
00:43:45.095 [1534961695.04][CONN][INF] received special event '__host_test_finished' value='True', finishing
00:43:45.096 [1534961695.04][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:43:45.212 [1534961695.15][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/disconnect HTTP/1.1" 200 2
00:43:45.213 [1534961695.15][urllib3.connectionpool]Starting new HTTP connection (1): goku.austin.arm.com:8000
00:43:48.371 [1534961698.31][urllib3.connectionpool]http://goku.austin.arm.com:8000 "PUT /resource/07640221144368082B07FE51/release HTTP/1.1" 200 42
00:43:48.373 [1534961698.31][HTST][INF] CONN exited with code: 0
00:43:48.373 [1534961698.31][HTST][INF] No events in queue
00:43:48.373 [1534961698.31][HTST][INF] stopped consuming events
00:43:48.373 [1534961698.31][HTST][INF] host test result(): None
00:43:48.373 [1534961698.31][HTST][WRN] missing __exit event from DUT
00:43:48.373 [1534961698.31][HTST][WRN] missing __exit_event_queue event from host test
00:43:48.373 [1534961698.31][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
00:43:48.373 [1534961698.31][HTST][INF] calling blocking teardown()
00:43:48.373 [1534961698.31][HTST][INF] teardown() finished
00:43:48.373 [1534961698.31][HTST][INF] {{result;timeout}}
00:43:48.396 mbedgt: retry mbedhtrun 3/3
00:43:48.396 mbedgt: ['mbedhtrun', '-m', 'DISCO_L475VG_IOT01A', '-p', 'DUMMY:9600', '-f', u'"BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.bin"', '-e', u'"TESTS/host_tests"', '--grm', 'raas_client:goku.austin.arm.com:8000', '-C', '4', '--sync', '10', '-P', '120'] failed after 3 count
00:43:48.410 mbedgt: checking for GCOV data...
00:43:48.411 mbedgt: mbed-host-test-runner: stopped and returned 'TIMEOUT'
00:43:48.411 mbedgt: test on hardware with target id: DUMMY
00:43:48.411 mbedgt: test suite 'tests-mbed_drivers-flashiap' ..................................................... TIMEOUT in 140.06 sec
00:43:48.411 	test case: 'FlashIAP - init' ................................................................. OK in 0.00 sec
00:43:48.411 	test case: 'FlashIAP - program' .............................................................. OK in 0.10 sec
00:43:48.411 	test case: 'FlashIAP - program across sectors' ............................................... OK in 0.10 sec
00:43:48.411 	test case: 'FlashIAP - program errors' ....................................................... OK in 0.21 sec
00:43:48.411 	test case: 'FlashIAP - timing' ............................................................... ERROR in 0.00 sec
[ ] Question
[ ] Enhancement 
[X ] Bug 
@ciarmcom
Copy link
Member

ARM Internal Ref: MBOTRIAGE-1549

@0xc0170
Copy link
Contributor

0xc0170 commented Aug 23, 2018

cc @ARMmbed/team-st-mcd

@adustm
Copy link
Member

adustm commented Aug 23, 2018

Hello,
Could you precise your issue please ?
mbed test -m DISCO_L475VG_IOT01A -t GCC_ARM -n tests-mbed_drivers-flashiap -v
gives correct results

mbedgt: test suite 'tests-mbed_drivers-flashiap' ..................................................... OK in 17.08 sec
        test case: 'FlashIAP - init' ................................................................. OK in 0.05 sec
        test case: 'FlashIAP - program' .............................................................. OK in 0.17 sec
        test case: 'FlashIAP - program across sectors' ............................................... OK in 0.11 sec
        test case: 'FlashIAP - program errors' ....................................................... OK in 0.06 sec
        test case: 'FlashIAP - timing' ............................................................... OK in 0.78 sec
mbedgt: test case summary: 5 passes, 0 failures
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.0359470136
mbedgt: test suite report:
+-----------------------------+---------------------+-----------------------------+--------+--------------------+-------------+
| target                      | platform_name       | test suite                  | result | elapsed_time (sec) | copy_method |
+-----------------------------+---------------------+-----------------------------+--------+--------------------+-------------+
| DISCO_L475VG_IOT01A-GCC_ARM | DISCO_L475VG_IOT01A | tests-mbed_drivers-flashiap | OK     | 17.08              | default     |
+-----------------------------+---------------------+-----------------------------+--------+--------------------+-------------+

FYI my setup is the following
mbed-os sha1 = 603c4f9
GCC version is 6 2017-q2-update

mbed-cli                      1.7.5
mbed-connector-api            1.0.4
mbed-greentea                 1.4.0
mbed-host-tests               1.4.1
mbed-ls                       1.5.1
mbed-test-wrapper             1.0.0

I have tried your command line
mbed test -m DISCO_L475VG_IOT01A -t GCC_ARM -n tests-mbed_drivers-flashiap -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLED=1 -DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED -v
but it does not work

Build successes:
  * DISCO_L475VG_IOT01A::GCC_ARM::MBED-BUILD
  * DISCO_L475VG_IOT01A::GCC_ARM::TESTS-MBED_DRIVERS-FLASHIAP
[mbed] Exec "mbedgt --test-spec .\BUILD\tests\DISCO_L475VG_IOT01A\GCC_ARM\test_spec.json -n tests-mbed_drivers-flashiap -V -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLED=1
-DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED" in "C:\MCD8\mbed-os"
Usage: mbedgt [options]

mbedgt: error: no such option: -D
[mbed] ERROR: "mbedgt" returned error.
       Code: 2
       Path: "C:\MCD8\mbed-os"
       Command: "mbedgt --test-spec .\BUILD\tests\DISCO_L475VG_IOT01A\GCC_ARM\test_spec.json -n tests-mbed_drivers-flashiap -V -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLE
D=1 -DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED"
       Tip: You could retry the last command with "-v" flag for verbose output

I have created a mbed_app.json containing

{
    "macros": [
        "MBED_HEAP_STATS_ENABLED=1",
        "MBED_STACK_STATS_ENABLED=1",
        "MBED_TRAP_ERRORS_ENABLED=1",
	"MBED_ALL_STATS_ENABLED"
    ]
}

and it gives the same error as the one you described
Adding statistics is clearly impacting the results...

@aashishc1988
Copy link
Contributor Author

@adustm That's correct. My findings were along the similar lines as to adding just the flag to collect all the stats (-DMBED_ALL_STATS_ENABLED) causes the issue. I am still investigating as to why that is. My understanding is that that flag collects all memory information and might be doing some allocation/deallocation and may be much more, so at this point I am not completely sure if this is an issue with the target or something we are doing while collecting the stats.

@aashishc1988
Copy link
Contributor Author

aashishc1988 commented Aug 23, 2018

The issue here is memory. When all the stats are enabled, we dont have enough memory on this part to run this test. It fails to allocate 512 bytes. When trying to run flashiap_timing_test, we have to allocate bunch of memory, so we can add a change that would skip that test if we cannot get enough memory for it, something along the lines of this PR: #7696

Besides that, we would also need the change in this PR pulled in: #7730

@MateuszMaz
Copy link
Contributor

MateuszMaz commented Aug 24, 2018

Tested few other devices with tests-mbed_drivers-flashiap and those flags here is output:

device flash ram result
stm32f429zi (nucleo) 2048 KB 256 +4 KB ok
nucleo f070r0b 128 KB 16 KB ok
nucleo -l476rg 1 MB 128 KB error (timeout)
k64f 1 MB 256 KB ok
DISCO-F769NI 512 KB 128 KB ok
NRF52_DK (nrf52832) 512 KB 64 kB ok

looks like only targets stm32-47x have this issue

@0xc0170
Copy link
Contributor

0xc0170 commented Aug 24, 2018

Nucleo F070 does not have an issue (much smaller target) but L476 does? Is there also playing role memory regions (1 vs 2 RAM regions or something else) ?

@adustm
Copy link
Member

adustm commented Aug 24, 2018

Hi @MateuszMaz
Thanks for this test status.

Hi @0xc0170
This is the assumption I was having before reading this report also.
The test is using 76553 flash and 11844 ram, and the device has 1Mb flash + 128k ram. It is supposed to be able to use statistics
I am trying to print memory values with the following function, but it does not work

void print_heap(const char* info) {
    printf(info);
    mbed_stats_heap_get(&stats);
    printf("  current_size =  0x%8X\r\n", stats.current_size);
    printf("      max_size =  0x%8X\r\n", stats.max_size);
    printf("    total_size =  0x%8X\r\n", stats.total_size);
    printf(" reserved_size =  0x%8X\r\n", stats.reserved_size);
    printf("     alloc_cnt =  0x%8X\r\n", stats.alloc_cnt);
    printf("alloc_fail_cnt =  0x%8X\r\n", stats.alloc_fail_cnt);
}

Let's keep searching

@MateuszMaz
Copy link
Contributor

MateuszMaz commented Aug 24, 2018

To be a little more precise problem occurs for flag -DMBED_HEAP_STATS_ENABLED=1
(-DMBED_ALL_STATS_ENABLED=1 just sets sys, stack,cpu,heap,thread stats enable)

@adustm
Copy link
Member

adustm commented Aug 28, 2018

Hello,

Those devices (STM32L476 / 475 / 486 ) have 2 non contigous SRAMs.
Heap is located in SRAM1 (from 0x20000000) and stack is located in SRAM2 ( from 0x10000000).
Could someone check if the heap statistic code supports this split ?

Crash analysis document explains that

You can also use the stack size (Stack Size), stack top (Mem) and current stack pointer (SP) value to determine if there is thread stack overflow. For example, if the SP value is smaller than the Mem value, it indicates stack overflow for that thread.

The provided dump
00:39:26.927 [1534961436.87][CONN][RXD] Current Thread: Id: 0x20001A0C Entry: 0x8004629 StackSize: 0x1000 StackMem: 0x20001A58 SP: 0x10007F70
has sp pointer < StackMem... Is it an issue ?

Kind regards

@adustm
Copy link
Member

adustm commented Aug 30, 2018

hello again,
I would like to share some findings. We don't understand the impact of our modifications on the behavior of the test. Maybe some of you will.

Crash log parser says:

/c/mbed-os  (master)$ python tools/debug_tools/crash_log_parser/crash_log_parser.py hardfault.txt \
BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.elf \
BUILD/tests/DISCO_L475VG_IOT01A/GCC_ARM/TESTS/mbed_drivers/flashiap/flashiap.map.old

Crash Info:
        Crash location = _free_r [0x08009C2A] (based on PC value)
        Caller location = osMutexAcquire [0x08005B03] (based on LR value)
        Stack Pointer at the time of crash = [200028E0]
        Target and Fault Info:
                Processor Arch: ARM-V7M or above
                Processor Variant: C24
                Forced exception, a fault with configurable priority has been escalated to HardFault
                A precise data access error has occurred. Faulting address: 1FFD1F5E

This mean that the error occurs here in mbed_alloc_wrappers.cpp

extern "C" void free_wrapper(struct _reent *r, void *ptr, void *caller)
{
#ifdef MBED_MEM_TRACING_ENABLED
    mbed_mem_trace_lock();
#endif
#ifdef MBED_HEAP_STATS_ENABLED
    malloc_stats_mutex->lock();                  // * * * * * ERROR OCCURS HERE
    alloc_info_t *alloc_info = NULL;
    if (ptr != NULL) {
        alloc_info = ((alloc_info_t *)ptr) - 1;
        heap_stats.current_size -= alloc_info->size;
        heap_stats.alloc_cnt -= 1;
    }

We've been able to find 2 ways of fixing the problem (no explanation so far...)
1/ mbed_alloc_wrappers.cpp

diff --git a/platform/mbed_alloc_wrappers.cpp b/platform/mbed_alloc_wrappers.cpp
index 87fcd95..cf9965f 100644
--- a/platform/mbed_alloc_wrappers.cpp
+++ b/platform/mbed_alloc_wrappers.cpp
@@ -43,7 +43,7 @@ are active, the second one (MBED_MEM_TRACING_ENABLED) will trace the first one's
 /* Size must be a multiple of 8 to keep alignment */
 typedef struct {
     uint32_t size;
-    uint32_t pad;
+    //uint32_t pad;
 } alloc_info_t;

=> test is ok
2/ l4_retarget.c

diff --git a/targets/TARGET_STM/TARGET_STM32L4/l4_retarget.c b/targets/TARGET_STM/TARGET_STM32L4/l4_retarget.c
index c80d087..b14cff1 100644
--- a/targets/TARGET_STM/TARGET_STM32L4/l4_retarget.c
+++ b/targets/TARGET_STM/TARGET_STM32L4/l4_retarget.c
@@ -38,7 +38,7 @@
 extern uint32_t __mbed_sbrk_start;
 extern uint32_t __mbed_krbs_start;

-#define STM32L4_HEAP_ALIGN               32
+#define STM32L4_HEAP_ALIGN               4
 #define STM32L4_ALIGN_UP(X, ALIGN)       (((X) + (ALIGN) - 1) & ~((ALIGN) - 1))

=> test is ok

Both modifications fixes the test.

Please note that adding a printf in main.cpp / flashiap_init_test function makes the program fail during flashiap_init function instead of flashiap_timing_test function

On the other hand, we 've checked heap settings

__heap_size = 0x   151f8  
__mbed_sbrk_start  = 0x20002e08
__mbed_krbs_start  = 0x20018000
__HeapLimit = 0x20018000

There is 84k of heap... should be sufficient...

I hope this will help you finding the issue.
Kind regards

@MateuszMaz
Copy link
Contributor

I found that this problem is not related neither to greentea nor FlashIAP, and thanks to @maciejbocianski help I also know that it occurs only for GCC_ARM. It is indeed related to memory allocation.

Just make a simple program, and compile it with -DMBED_HEAP_STATS_ENABLED=1 -t GCC_ARM

#include "mbed.h"


int main(){

int FIRST_SIZE = 8;
int SECOND_SIZE = 2000;

uint8_t *table1 = new uint8_t[FIRST_SIZE];
uint8_t *table2 = new uint8_t[SECOND_SIZE];

return 0;
}

this one will result in something similar:

++ MbedOS Error Info ++
Error Status: 0x80FF013D Code: 317 Module: 255
Error Message: Fault exception
Location: 0x80014B7
Error Value: 0x8005A4A
Current Thread: Id: 0x200014BC Entry: 0x800150D StackSize: 0x1000 StackMem: 0x20001508 SP: 0x10007F70
-- MbedOS Error Info --

@LMESTM
Copy link
Contributor

LMESTM commented Aug 30, 2018

HI all
Can someone explain why alloc_info_t NEEDS to be aligned to 8 ?

diff --git a/platform/mbed_alloc_wrappers.cpp b/platform/mbed_alloc_wrappers.cpp
index 87fcd95..cf9965f 100644
--- a/platform/mbed_alloc_wrappers.cpp
+++ b/platform/mbed_alloc_wrappers.cpp
@@ -43,7 +43,7 @@ are active, the second one (MBED_MEM_TRACING_ENABLED) will trace the first one's
 /* Size must be a multiple of 8 to keep alignment */
 typedef struct {
     uint32_t size;
-    uint32_t pad;
+    //uint32_t pad;
 } alloc_info_t;

@LMESTM
Copy link
Contributor

LMESTM commented Aug 31, 2018

@bogdanm @c1728p9 @Heky
I think that you 3 were at the origin of the code for handling memory tracing. We have an issue here and a question about why alloc_info_t must be aligned to 8 - could you maybe help out ?
thanks
Laurent

@c1728p9
Copy link
Contributor

c1728p9 commented Aug 31, 2018

Hi @LMESTM this was done in an abundance of caution. The default implementation only returns 8 byte aligned data and some things, such as stacks require 8 byte aligned memory. To ensure there were no regressions the 8 byte alignment was kept.

@LMESTM
Copy link
Contributor

LMESTM commented Aug 31, 2018

Thanks for quick feedback @c1728p9. In our particular case, removing the padding, therefore removing this extra caution step and keeping structure with 4 bytes only, somehow solves our issue ...
and I have no why ... any idea ? could it be that the pad in structure is sometimes optimized out as this is never used nor referenced ?

@c1728p9
Copy link
Contributor

c1728p9 commented Aug 31, 2018

It appears that this failures is caused by a mismatch between the allocation size newlib expects and the size actually allocated. Depending on the size of the first allocation (if it is a multiple of 32 bytes) then the alignment done in __wrap__sbrk won't match what newlib expected, which is likely the cause of the crash. The code which is potentially causing the mismatch can be found here:

void *__wrap__sbrk(int incr)
{
static uint32_t heap_ind = (uint32_t) &__mbed_sbrk_start;
uint32_t heap_ind_old = STM32L4_ALIGN_UP(heap_ind, STM32L4_HEAP_ALIGN);
uint32_t heap_ind_new = STM32L4_ALIGN_UP(heap_ind_old + incr, STM32L4_HEAP_ALIGN);
if (heap_ind_new > &__mbed_krbs_start) {
errno = ENOMEM;
return (void *) - 1;
}
heap_ind = heap_ind_new;
return (void *) heap_ind_old;
}

I took the DISCO_L475VG_IOT01A board and was able to reproduce the crash when heap stats was turned on. I recorded the values inside of __wrap__sbrk (see below) to debug this. In the failing case the expected return value (incr + heap_ind_old of the previous allocation) of __wrap__sbrk was off in two cases (marked with * below). Note - heap_ind_old is the same as the return value of __wrap__sbrk.

Successful run without heap stats enabled:

incr=32 heap_ind_old=0x20002b40, heap_ind_new=0x20002b60        incr + heap_ind_old = 0x20002B60
incr=1184 heap_ind_old=0x20002b60, heap_ind_new=0x20003000      incr + heap_ind_old = 0x20003000
incr=4096 heap_ind_old=0x20003000, heap_ind_new=0x20004000      incr + heap_ind_old = 0x20004000

Crash when heap stats is turned on:

incr=40 heap_ind_old=0x20002B80, heap_ind_new=0x20002BC0        incr + heap_ind_old = 0x20002BA8*
incr=1112 heap_ind_old=0x20002BC0, heap_ind_new=0x20003020      incr + heap_ind_old = 0x20003018*
incr=4096 heap_ind_old=0x20003020, heap_ind_new=0x20004020      incr + heap_ind_old = 0x20004020
incr=4064 heap_ind_old=0x20004020, heap_ind_new=0x20005000      incr + heap_ind_old = 0x20005000

If I modify __wrap__sbrk to remove the alignment I no longer get a crash in any case. I suspect that this is unrelated to MBED_HEAP_STATS_ENABLED and that it will manifest even with this off if the size allocated, FIRST_SIZE and SECOND_SIZE in the example, is increased by 8 bytes. @MateuszMaz can you test this? I no longer have access to the DISCO_L475VG_IOT01A I was using.

@c1728p9
Copy link
Contributor

c1728p9 commented Aug 31, 2018

I created #7950 to fix this. Please test and confirm it fixes the problem.

@LMESTM
Copy link
Contributor

LMESTM commented Sep 3, 2018

@c1728p9 based on recent observations, we were heading in a similar direction and planned to remove the alignment but we can not explain why the alignment was causing the failure. you suggestion is :

the alignment done in __wrap__sbrk won't match what newlib expected, which is likely the cause of the crash

so ok we'll consider sbrk needs to allocate exactly what is requested and no more. Fine with me.

@aashishc1988
Copy link
Contributor Author

@c1728p9 I have verified that #7950 fixes the problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants