Getting hardfault when running netsocket tests on nuc472

[aashishc1988]

Description

• Type: Bug
• Priority: Major

---

Bug

Target
NUMAKER_PFM_NUC472

Toolchain:
GCC_ARM

Tests we are failing:
tests-netsocket-dns

Steps to reproduce

mbed test -m NUMAKER_PFM_NUC472 -t GCC_ARM -n tests-netsocket-dns -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLED=1 -DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED -v

log snippet

> 
mbedgt: greentea test automation tool ver. 1.4.0
mbedgt: using multiple test specifications from current directory!
        using 'BUILD\tests\NUMAKER_PFM_NUC472\GCC_ARM\test_spec.json'
mbedgt: detecting connected mbed-enabled devices...
mbedgt: entering global resource manager mbed-ls dummy mode!
        adding dummy platform 'NUMAKER_PFM_NUC472'
mbedgt: detected 1 device
        +--------------------+-----------------------+-------------+-------------+-----------+
        | platform_name      | platform_name_unique  | serial_port | mount_point | target_id |
        +--------------------+-----------------------+-------------+-------------+-----------+
        | NUMAKER_PFM_NUC472 | NUMAKER_PFM_NUC472[0] | DUMMY       | DUMMY       | DUMMY     |
        +--------------------+-----------------------+-------------+-------------+-----------+
mbedgt: processing target 'NUMAKER_PFM_NUC472' toolchain 'GCC_ARM' compatible platforms... (note: switch set to --parallel 1)
        +--------------------+-----------------------+-------------+-------------+-----------+
        | platform_name      | platform_name_unique  | serial_port | mount_point | target_id |
        +--------------------+-----------------------+-------------+-------------+-----------+
        | NUMAKER_PFM_NUC472 | NUMAKER_PFM_NUC472[0] | DUMMY:9600  | DUMMY       | DUMMY     |
        +--------------------+-----------------------+-------------+-------------+-----------+
mbedgt: test case filter (specified with -n option)
        tests-netsocket-dns
        test filtered in 'tests-netsocket-dns'
mbedgt: running 1 test for platform 'NUMAKER_PFM_NUC472' and toolchain 'GCC_ARM'
        use 1 instance of execution threads for testing
mbedgt: checking for 'host_tests' directory above image directory structure
        found 'host_tests' directory in: 'TESTS\host_tests'
mbedgt: selecting test case observer...
        calling mbedhtrun: mbedhtrun -m NUMAKER_PFM_NUC472 -p DUMMY:9600 -f "BUILD/tests/NUMAKER_PFM_NUC472/GCC_ARM/TESTS/netsocket/dns/dns.bin" -e "TESTS\host_tests" --grm raas_client:10.118.12.100:8000 -C 4 --sync 5 -P 60
mbedgt: mbed-host-test-runner: started
[1535475353.36][HTST][INF] host test executor ver. 1.4.0
[1535475353.36][HTST][INF] copy image onto target... SKIPPED!
[1535475353.36][HTST][INF] starting host test process...
[1535475354.00][CONN][INF] starting connection process...
[1535475354.00][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1535475354.00][CONN][INF] initializing global resource mgr listener...
[1535475354.02][HTST][INF] setting timeout to: 60 sec
[1535475354.13][GLRM][INF] remote resources initialization: remote(host=10.118.12.100, port=8000)
[1535475354.14][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.14][urllib3.connectionpool]http://10.118.12.100:8000 "POST /login HTTP/1.1" 200 213
[1535475354.14][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.14][urllib3.connectionpool]http://10.118.12.100:8000 "GET /socket.io/?token=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJ1c2VybmFtZSI6InVzZXIiLCJncm91cCI6InVzZXIiLCJpYXQiOjE1MzU0NzUzNTQsImV4cCI6MTUzNjA4MDE1NH0.BbBJxAzyVDQKWxwlDvFahT_YXcaTM7Jzy_FzRNcnOes&EIO=3&transport=polling&t=1535475354144-0 HTTP/1.1" 200 101
[1535475354.17][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.17][urllib3.connectionpool]http://10.118.12.100:8000 "GET /this/resource HTTP/1.1" 200 2274
[1535475354.17][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.17][urllib3.connectionpool]http://10.118.12.100:8000 "GET /resource HTTP/1.1" 200 5215
[1535475354.17][GLRM][INF] remote resources count: 4
[1535475354.18][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.18][urllib3.connectionpool]http://10.118.12.100:8000 "GET /resource HTTP/1.1" 200 5215
[1535475354.18][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.18][urllib3.connectionpool]http://10.118.12.100:8000 "PUT /resource/13020000006C0021011DAD0A00000167/allocate HTTP/1.1" 200 1342
[1535475354.18][GLRM][INF] remote resources flashing with 'BUILD/tests/NUMAKER_PFM_NUC472/GCC_ARM/TESTS/netsocket/dns/dns.bin'...
[1535475354.20][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475354.21][urllib3.connectionpool]http://10.118.12.100:8000 "POST /file HTTP/1.1" 200 239
[1535475366.55][GLRM][INF] opening connection to platform at baudrate='9600'
[1535475366.55][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475366.75][urllib3.connectionpool]http://10.118.12.100:8000 "PUT /resource/13020000006C0021011DAD0A00000167/connect HTTP/1.1" 200 15
[1535475366.77][GLRM][INF] remote resources reset...
[1535475369.09][GLRM][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1535475369.09][CONN][INF] sending up to 5 __sync packets (specified with --sync=5)
[1535475369.09][CONN][INF] sending preamble 'd59ab31b-8535-4997-ad8d-5ea82af096d3'
[1535475369.11][GLRM][TXD] {{__sync;d59ab31b-8535-4997-ad8d-5ea82af096d3}}
[1535475370.18][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1535475370.30][CONN][INF] found SYNC in stream: {{__sync;d59ab31b-8535-4997-ad8d-5ea82af096d3}} it is #0 sent, queued...
[1535475370.30][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1535475370.30][CONN][INF] found KV pair in stream: {{__timeout;120}}, queued...
[1535475370.30][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
[1535475370.31][HTST][INF] sync KV found, uuid=d59ab31b-8535-4997-ad8d-5ea82af096d3, timestamp=1535475370.296000
[1535475370.31][HTST][INF] DUT greentea-client version: 1.3.0
[1535475370.31][HTST][INF] setting timeout to: 120 sec
[1535475370.31][HTST][INF] host test class: '<class 'mbed_host_tests.host_tests.default_auto.DefaultAuto'>'
[1535475370.31][HTST][INF] host test setup() call...
[1535475370.31][HTST][INF] CALLBACKs updated
[1535475370.31][HTST][INF] host test detected: default_auto
[1535475370.40][CONN][RXD] mac address ee-0a-00-20-a1-67
[1535475372.30][CONN][RXD] PHY ID 1:0x243
[1535475372.30][CONN][RXD] PHY ID 2:0xc54
[1535475372.30][CONN][RXD]
[1535475372.40][CONN][RXD] ++ MbedOS Fault Handler ++
[1535475372.40][CONN][RXD]
[1535475372.40][CONN][RXD] FaultType: HardFault
[1535475372.40][CONN][RXD]
[1535475372.40][CONN][RXD] Context:
[1535475372.40][CONN][RXD] R0   : 00000000
[1535475372.40][CONN][RXD] R1   : 20001344
[1535475372.40][CONN][RXD] R2   : 800052A4
[1535475372.50][CONN][RXD] R3   : 2000235C
[1535475372.50][CONN][RXD] R4   : 60002F48
[1535475372.50][CONN][RXD] R5   : 60002F50
[1535475372.50][CONN][RXD] R6   : 60003020
[1535475372.50][CONN][RXD] R7   : 2000235C
[1535475372.50][CONN][RXD] R8   : 20000DB0
[1535475372.50][CONN][RXD] R9   : 00000FE0
[1535475372.62][CONN][RXD] R10  : 00000010
[1535475372.62][CONN][RXD] R11  : 00001000
[1535475372.62][CONN][RXD] R12  : 0001335D
[1535475372.62][CONN][RXD] SP   : 20008650
[1535475372.62][CONN][RXD] LR   : 0001362B
[1535475372.62][CONN][RXD] PC   : 000164F6
[1535475372.72][CONN][RXD] xPSR : 91070000
[1535475372.72][CONN][RXD] PSP  : 200085E8
[1535475372.72][CONN][RXD] MSP  : 200007D8
[1535475372.72][CONN][RXD] CPUID: 410FC241
[1535475372.72][CONN][RXD] HFSR : 40000000
[1535475372.72][CONN][RXD] MMFSR: 00000000
[1535475372.82][CONN][RXD] BFSR : 00000082
[1535475372.82][CONN][RXD] UFSR : 00000000
[1535475372.82][CONN][RXD] DFSR : 00000000
[1535475372.82][CONN][RXD] AFSR : 00000000
[1535475372.82][CONN][RXD] BFAR : 800052A8
[1535475372.82][CONN][RXD] Mode : Thread
[1535475372.92][CONN][RXD] Priv : Privileged
[1535475372.92][CONN][RXD] Stack: PSP
[1535475372.92][CONN][RXD]
[1535475372.92][CONN][RXD] -- MbedOS Fault Handler --
[1535475372.92][CONN][RXD]
[1535475372.92][CONN][RXD]
[1535475372.92][CONN][RXD]
[1535475372.92][CONN][RXD] ++ MbedOS Error Info ++
[1535475373.02][CONN][RXD] Error Status: 0x80FF013D Code: 317 Module: 255
[1535475373.02][CONN][RXD] Error Message: Fault exception
[1535475373.02][CONN][RXD] Location: 0x11E3B
[1535475373.02][CONN][RXD] Error Value: 0x164F6
[1535475373.12][CONN][RXD] Current Thread: Id: 0x200077D4 Entry: 0x11E91 StackSize: 0x1000 StackMem: 0x20007820 SP: 0x20000770
[1535475373.22][CONN][RXD] -- MbedOS Error Info --
[1535475491.07][HTST][INF] test suite run finished after 120.76 sec...
[1535475491.07][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1535475491.07][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475491.12][urllib3.connectionpool]http://10.118.12.100:8000 "PUT /resource/13020000006C0021011DAD0A00000167/disconnect HTTP/1.1" 200 2
[1535475491.12][urllib3.connectionpool]Starting new HTTP connection (1): 10.118.12.100:8000
[1535475494.37][urllib3.connectionpool]http://10.118.12.100:8000 "PUT /resource/13020000006C0021011DAD0A00000167/release HTTP/1.1" 200 50
[1535475494.37][HTST][INF] CONN exited with code: 0
[1535475494.37][HTST][INF] No events in queue
[1535475494.37][HTST][INF] stopped consuming events
[1535475494.37][HTST][INF] host test result(): None
[1535475494.37][HTST][WRN] missing __exit event from DUT
[1535475494.37][HTST][WRN] missing __exit_event_queue event from host test
[1535475494.37][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
[1535475494.37][HTST][INF] calling blocking teardown()
[1535475494.37][HTST][INF] teardown() finished
[1535475494.37][HTST][INF] {{result;timeout}}
mbedgt: retry mbedhtrun 1/1
mbedgt: ['mbedhtrun', '-m', 'NUMAKER_PFM_NUC472', '-p', 'DUMMY:9600', '-f', u'"BUILD/tests/NUMAKER_PFM_NUC472/GCC_ARM/TESTS/netsocket/dns/dns.bin"', '-e', u'"TESTS\\host_tests"', '--grm', 'raas_client:10.118.12.100:8000', '-C', '4', '--sync', '5', '-P', '60'] failed after 1 count
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'TIMEOUT'
mbedgt: test case summary event not found
        no test case report present, assuming test suite to be a single test case!
        test suite: tests-netsocket-dns
        test case: tests-netsocket-dns
mbedgt: test on hardware with target id: DUMMY
mbedgt: test suite 'tests-netsocket-dns' ............................................................. TIMEOUT in 141.70 sec
        test case: 'tests-netsocket-dns' ............................................................. ERROR in 141.70 sec
mbedgt: test case summary: 0 passes, 1 failure
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.8674081340
mbedgt: test suite report:
+----------------------------+--------------------+---------------------+---------+--------------------+-------------+
| target                     | platform_name      | test suite          | result  | elapsed_time (sec) | copy_method |
+----------------------------+--------------------+---------------------+---------+--------------------+-------------+
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | TIMEOUT | 141.7              | default     |
+----------------------------+--------------------+---------------------+---------+--------------------+-------------+
mbedgt: test suite results: 1 TIMEOUT
mbedgt: test case report:
+----------------------------+--------------------+---------------------+---------------------+--------+--------+--------+--------------------+
| target                     | platform_name      | test suite          | test case           | passed | failed | result | elapsed_time (sec) |
+----------------------------+--------------------+---------------------+---------------------+--------+--------+--------+--------------------+
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | tests-netsocket-dns | 0      | 1      | ERROR  | 141.7              |
+----------------------------+--------------------+---------------------+---------------------+--------+--------+--------+--------------------+
mbedgt: test case results: 1 ERROR
mbedgt: completed in 145.24 sec
mbedgt: exited with code 1

[ ] Question
[ ] Enhancement 
[X ] Bug 

[0xc0170]

@ARMmbed/team-nuvoton Please review

@absgomz66 ?
[Mirrored to Jira]

[cyliangtw]

I verified this DNS test on NUC472, it could work fine. please open the attached log file for details.

$mbed test -m NUMAKER_PFM_NUC472 -t GCC_ARM -n tests-netsocket-dns -v
.......
mbedgt: mbed-host-test-runner: stopped and returned 'OK'
mbedgt: test on hardware with target id: 1302000000EC0021011DAD3F000001D3
mbedgt: test suite 'tests-netsocket-dns' ............................................................. OK in 92.55 sec
        test case: 'ASYNCHRONOUS_DNS' ................................................................ OK in 0.36 sec
        test case: 'ASYNCHRONOUS_DNS_CACHE' .......................................................... OK in 0.35 sec
        test case: 'ASYNCHRONOUS_DNS_CANCEL' ......................................................... OK in 5.27 sec
        test case: 'ASYNCHRONOUS_DNS_EXTERNAL_EVENT_QUEUE' ........................................... OK in 2.94 sec
        test case: 'ASYNCHRONOUS_DNS_INVALID_HOST' ................................................... OK in 1.83 sec
        test case: 'ASYNCHRONOUS_DNS_NON_ASYNC_AND_ASYNC' ............................................ OK in 0.48 sec
        test case: 'ASYNCHRONOUS_DNS_SIMULTANEOUS' ................................................... OK in 0.86 sec
        test case: 'ASYNCHRONOUS_DNS_SIMULTANEOUS_CACHE' ............................................. OK in 2.00 sec
        test case: 'ASYNCHRONOUS_DNS_SIMULTANEOUS_REPEAT' ............................................ OK in 32.32 sec
        test case: 'ASYNCHRONOUS_DNS_TIMEOUTS' ....................................................... OK in 2.54 sec
mbedgt: test case summary: 10 passes, 0 failures
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.1734162282
mbedgt: test suite report:
+----------------------------+--------------------+---------------------+--------+--------------------+-------------+
| target                     | platform_name      | test suite          | result | elapsed_time (sec) | copy_method |
+----------------------------+--------------------+---------------------+--------+--------------------+-------------+
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | OK     | 92.55              | default     |
+----------------------------+--------------------+---------------------+--------+--------------------+-------------+
mbedgt: test suite results: 1 OK
mbedgt: test case report:
+----------------------------+--------------------+---------------------+---------------------------------------+--------+--------+--------+--------------------+
| target                     | platform_name      | test suite          | test case                             | passed | failed | result | elapsed_time (sec) |
+----------------------------+--------------------+---------------------+---------------------------------------+--------+--------+--------+--------------------+
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS                      | 1      | 0      | OK     | 0.36               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_CACHE                | 1      | 0      | OK     | 0.35               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_CANCEL               | 1      | 0      | OK     | 5.27               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_EXTERNAL_EVENT_QUEUE | 1      | 0      | OK     | 2.94               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_INVALID_HOST         | 1      | 0      | OK     | 1.83               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_NON_ASYNC_AND_ASYNC  | 1      | 0      | OK     | 0.48               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_SIMULTANEOUS         | 1      | 0      | OK     | 0.86               |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_SIMULTANEOUS_CACHE   | 1      | 0      | OK     | 2.0                |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_SIMULTANEOUS_REPEAT  | 1      | 0      | OK     | 32.32              |
| NUMAKER_PFM_NUC472-GCC_ARM | NUMAKER_PFM_NUC472 | tests-netsocket-dns | ASYNCHRONOUS_DNS_TIMEOUTS             | 1      | 0      | OK     | 2.54               |
+----------------------------+--------------------+---------------------+---------------------------------------+--------+--------+--------+--------------------+
mbedgt: test case results: 10 OK
mbedgt: completed in 94.26 sec

nuc472_netsocket_dns_gcc.txt

[Mirrored to Jira]

[deepikabhavnani]

@cyliangtw Build command for failure is not the same as success.

Fails with:
mbed test -m NUMAKER_PFM_NUC472 -t GCC_ARM -n tests-netsocket-dns -DMBED_HEAP_STATS_ENABLED=1 -DMBED_STACK_STATS_ENABLED=1 -DMBED_TRAP_ERRORS_ENABLED=1 -DMBED_ALL_STATS_ENABLED -v

Success:
mbed test -m NUMAKER_PFM_NUC472 -t GCC_ARM -n tests-netsocket-dns -v
[Mirrored to Jira]

[aashishc1988]

@cyliangtw As @deepikabhavnani indicated, the build command you used doesnt include stack/heap flags, which I am guessing end up using more memory to collect all the stats information.
[Mirrored to Jira]

[cyliangtw]

@deepikabhavnani @aashishc1988 , I traced this memory alloc/free wrap issue long time ago in some sample without networking, it's only found in GCC. I ignored it and workaround by referred other platforms to adjust heap as 32 bytes alignment temporarily at that time. After several weeks, Bridadan also saw this symptom and issued #3440. Identified the root cause as: In some unknown condition, __real__realloc_r will invocate _free_r, but it is __wrap__free_r rather than __real__free_r that gets called here.
Though heap as 32 bytes alignment could resolve temporarily at that time, however, it still can't resolve the root cause. So you suffered this symptom again in new combination.
So far, we regard it as GCC tool chain issue.
[Mirrored to Jira]

[deepikabhavnani]

@cyliangtw - As per the implementation of __wrap__realloc_r __real__realloc_r should never be called if MBED_HEAP_STATS_ENABLED is set.

__wrap__realloc_r does call free (https://github.com/ARMmbed/mbed-os/blob/master/platform/mbed_alloc_wrappers.cpp#L154) which will be diverted to __wrap__free_r and not __real__free_r . Is this your failing point?

adjust heap as 32 bytes alignment

Shouldn't heap be 32-byte aligned?
[Mirrored to Jira]

[deepikabhavnani]

@cyliangtw - I saw the issue while allocating memory for new thread

mbed-os/features/netsocket/emac-drivers/TARGET_NUVOTON_EMAC/numaker_emac.cpp

Line 65 in 63f6216

attr.stack_mem = malloc(stacksize);

Call flow is -> malloc_wrapper -> _malloc_r -> free_wrapper (This memory might be allocated internally hence we do not have stats header for it in wrapper call).

I skipped the three instructions in if condition here and it worked

mbed-os/platform/mbed_alloc_wrappers.cpp

Line 185 in 63f6216

alloc_info = ((alloc_info_t *)ptr) - 1;

I have a solution, we can keep signature in header to indicate wrap_malloc_r was used for allocation and not real_malloc_r.

@c1728p9 - Do you have any inputs ?
[Mirrored to Jira]

[cyliangtw]

@deepikabhavnani - This malloc is in cpp and should be called after c-runtime init, so it should be in wrapper call.
About the three instructions in if condition, it's really the key point. My suggestion is to check the signature in free_wrapper, if signature match, alloc_info = ((alloc_info_t *)ptr) - 1, else alloc_info = ((alloc_info_t *)ptr) .

[Mirrored to Jira]