K64F Ethernet TCP through a sys_mutex_lock error

[nalmakhd]

Description

• Target: K64F
• Toolchain: GCC (arm-none-eabi-gcc/g++)
• Tools: Using make.(Custom built make file for mbed-os)
• mbed-os version: mbed-os 5.6.5

When running TCP on Ethernet, K64F will through one of the following error after sending or receiving a large number of packets:

• sys_mutex_lock error
• sys_arch_protect error

I had this tested on a large application (with UART/file system/RTC). I will get either of the two error messages for various runs of the application. Note that I will get NSAPI_ERROR_WOULD_BLOCK multiple times here before the error halts the execution. The <sys_mutex_lock error> occurred with the following stack back-trace:

---

STACK BACKTRACE

#0 0x00002ca0 in ticker_read_us (ticker=ticker@entry=0x26a34 <us_data>) at mbed-os/hal/mbed_ticker_api.c:267

#1 0x00002cb2 in ticker_read (ticker=ticker@entry=0x26a34 <us_data>) at mbed-os/hal/mbed_ticker_api.c:261

#2 0x0001339e in wait_us (us=us@entry=400000) at /mbed-os/platform/mbed_wait_api_rtos.cpp:48

#3 0x000133ce in wait_ms (ms=ms@entry=400) at mbed-os/platform/mbed_wait_api_rtos.cpp:32

#4 0x00002d40 in mbed_die () at mbed-os/platform/mbed_board.c:47

#5 0x000130a8 in _exit (return_code=1) at os-lib/mbed-os/platform/mbed_retarget.cpp:798

#6 0x000130ba in __wrap_exit (return_code=) at /mbed-os/platform/mbed_retarget.cpp:849

#7 0x00002eaa in error (format=0x28278 "sys_mutex_lock error\n") at /mbed-os/platform/mbed_error.c:42

#8 0x0000a3b4 in sys_mutex_lock (mutex=mutex@entry=0x2000efcc <lock_tcpip_core>) at FEATURES/FEATURE_LWIP/lwip-interface/lwip-sys/arch/lwip_sys_arch.c:392

#9 0x0000b876 in tcpip_send_msg_wait_sem (fn=0x1 <__isr_vector+1>, apimsg=apimsg@entry=0x20005b04 <_main_stack+3244>, sem=)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip/src/api/lwip_tcpip.c:333

#10 0x0000a520 in netconn_apimsg (fn=, apimsg=apimsg@entry=0x20005b04 <_main_stack+3244>)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip/src/api/lwip_api_lib.c:105

#11 0x0000a8a8 in netconn_write_partly (conn=, dataptr=, size=128, apiflags=apiflags@entry=1 '\001', bytes_written=bytes_written@entry=0x20005b34 <_main_stack+3292>)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip/src/api/lwip_api_lib.c:778

#12 0x00008fc4 in mbed_lwip_socket_send (stack=, handle=, data=, size=)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip_stack.c:1010

#13 0x00018196 in TCPSocket::send (this=this@entry=0x20005d84 <_main_stack+3884>, data=data@entry=0x20005c7c <_main_stack+3620>, size=size@entry=128)

END OF BACKTRACE

---

I tried it on a simpler tcp-echo application to make sure the problem is not related to a specific application . The error here is <sys_arch_protect error> and it occurred at the 451 received packet, the stack back-trace for the error from gdb is below:

---

STACK BACKTRACE

#0 ticker_read_us (ticker=ticker@entry=0x1c918 <us_data>) at /mbed-os/hal/mbed_ticker_api.c:267
#1 0x00001f2e in ticker_read (ticker=ticker@entry=0x1c918 <us_data>) at mbed-os/hal/mbed_ticker_api.c:261

#2 0x00010a52 in wait_us (us=us@entry=400000) at mbed-os/platform/mbed_wait_api_rtos.cpp:48

#3 0x00010a64 in wait_ms (ms=ms@entry=400) at mbed-os/platform/mbed_wait_api_rtos.cpp:32

#4 0x00001fac in mbed_die () at mbed-os/platform/mbed_board.c:45

#5 0x00010840 in _exit (return_code=1) at /mbed-os/platform/mbed_retarget.cpp:798

#6 0x00010852 in __wrap_exit (return_code=) at mbed-os/platform/mbed_retarget.cpp:849

#7 0x00002126 in error (format=0x1dab2 "sys_arch_protect error\n") at mbed-os/platform/mbed_error.c:42

#8 0x00007f9a in sys_arch_protect () at FEATURES/FEATURE_LWIP/lwip-interface/lwip-sys/arch/lwip_sys_arch.c:459

#9 0x00006c10 in mbed_lwip_socket_callback (nc=0x1 <__isr_vector+1>, eh=, len=) at FEATURES/FEATURE_LWIP/lwip-interface/lwip_stack.c:96

#10 0x00008174 in netconn_recv_data (conn=conn@entry=0x2000ddd0 <memp_memory_NETCONN_base+426>, new_buf=new_buf@entry=0x200034ec <_main_stack+3300>)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip/src/api/lwip_api_lib.c:583

#11 0x00008374 in netconn_recv (conn=0x2000ddd0 <memp_memory_NETCONN_base+426>, new_buf=new_buf@entry=0x20001450 <lwip_arena+32>)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip/src/api/lwip_api_lib.c:645

#12 0x00006adc in mbed_lwip_socket_recv (stack=, handle=0x20001448 <lwip_arena+24>, data=0x200036f0 <_main_stack+3816>, size=256)
at FEATURES/FEATURE_LWIP/lwip-interface/lwip_stack.c:1023

#13 0x00011ba6 in TCPSocket::recv (this=this@entry=0x20003664 <_main_stack+3676>, data=data@entry=0x200036f0 <_main_stack+3816>, size=size@entry=256)
at FEATURES/netsocket/TCPSocket.cpp:185

END OF BACKTRACE

---

I had an issue with an STM board but was solved with this patch (#5823 (comment)). I am wondering if this is related to K64F ticker fix here (#6287), because it appears that send/recv are delaying or are being preempted by another interrupt, and ticker can be a candidate for that.

Thanks!

Issue request type

[ ] Question
[ ] Enhancement
[X] Bug

[0xc0170]

@kjbracey-arm @mikaleppanen Please review

[nalmakhd]

Any update on this issue ?

[kjbracey]

There's been a lot of work on Ethernet drivers, including the K64F, in mbed OS 5.9. Could you retest with 5.9.1?

[kjbracey]

What context are the TCPSocket::recv calls being made from - I see no backtrace there. Is this from main()?

[nalmakhd]

I would like to avoid moving to 5.9 as I have quite some code relying on 5.6, but will do so if I have to.

As for the other comment, yes recv is called from main()

[SeppoTakalo]

This should be closed as not patch releases for Mbed OS 5.6 are submitted anymore.

Can be re-opened if appear in 5.9.