ESP32-S3 WiFi Failure

[EricNRS]

I am seeing WiFi failures on ESP32-S3 hardware. If I build the WiFi example for the xiao_esp32s3 and then flood the WiFi network.

west build --pristine -b xiao_esp32s3 samples/net/wifi

Connect to WiFi:
wifi connect "ESSID" PSK

# assuming device is at 192.168.1.61, then run the following from a host machine (Linux commands here)
# note the highly variable ping times
$ ping 192.168.1.61
PING 192.168.1.61 (192.168.1.61) 56(84) bytes of data.
64 bytes from 192.168.1.61: icmp_seq=10 ttl=64 time=104 ms
64 bytes from 192.168.1.61: icmp_seq=11 ttl=64 time=312 ms
64 bytes from 192.168.1.61: icmp_seq=12 ttl=64 time=46.2 ms
64 bytes from 192.168.1.61: icmp_seq=13 ttl=64 time=67.9 ms
^C
--- 192.168.1.61 ping statistics ---
14 packets transmitted, 4 received, 71.4286% packet loss, time 13201ms
rtt min/avg/max/mdev = 46.168/132.527/312.150/105.735 ms

If I then do a flood ping, the system sometimes stops responding after a while and the serial console is locked up. However, if a background task is added that blinks an LED, then that continues, so the processor has not hit an exception.

# do a flood ping - keep this running for about 15 seconds.
sudo ping 192.168.1.100 -s $((1500-42)) -f

# after 15 seconds, hit Ctrl-C to stop the pin and then run a stanrdard ping test again.
ping 192.168.1.61

Often after doing the ping flood, an error will be logged from esp32_wifi_send() with error code 257 (ESP_ERR_NO_MEM). Networking will often fail at this point and require a reset to recover. The serial console will sometimes lock up at this point as well. I added a workqueue item to toggle a LED and that continues to work even though the serial console and WiFi are not responding.

If you are not seeing the issue, try to increase the buffer count by editingzephyr/samples/net/wifi/boards/xiao_esp32s3.conf and adding:

CONFIG_NET_BUF_RX_COUNT=32
CONFIG_NET_BUF_TX_COUNT=32
CONFIG_NET_BUF_DATA_SIZE=512

CONFIG_NET_RX_STACK_SIZE=4096
CONFIG_NET_TX_STACK_SIZE=4096
CONFIG_NET_PKT_RX_COUNT=64
CONFIG_NET_PKT_TX_COUNT=64

Any suggestions on how to debug this or assitance in resolving this would be greatly appreciated!

[rftafas]

Did you try this?

CONFIG_ESP_SPIRAM=y
CONFIG_ESP32_WIFI_NET_ALLOC_SPIRAM=y

[sylvioalves]

@EricNRS, I suggest you to run kernel stacks and check TCP and other stacks sizes. I guess the issue is related to lack of memory. You can try modifying the below:

CONFIG_NET_MGMT_EVENT_QUEUE_SIZE=10
CONFIG_NET_TCP_WORKQ_STACK_SIZE=2048

[EricNRS]

@sylvioalves Yes, I have tried the following configuration and still see the issue. The stacks in this case are all fine:

CONFIG_INIT_STACKS=y
CONFIG_STACK_CANARIES=y
CONFIG_STACK_SENTINEL=y
CONFIG_MAIN_STACK_SIZE=2048
CONFIG_IDLE_STACK_SIZE=2048
CONFIG_INPUT_THREAD_STACK_SIZE=2048
CONFIG_SHELL_STACK_SIZE=4096
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_NET_CONNECTION_MANAGER_STACK_SIZE=4096

I also have tried @rftafas recommendation of SPIRAM since I am using that on my actual application, but I wanted to exclude that from the minimised test just to rule out SPIRAM.

CONFIG_ESP_SPIRAM=y
CONFIG_ESP32_WIFI_NET_ALLOC_SPIRAM=y

It seems like the internal network queue structures used by esp_wifi_internal_tx() are filling up and then not properly draining or being reset. How can this be debugged?

[sylvioalves]

@EricNRS, I have tried the same test and I get no errors or locked console. I tested on a esp32s3_devkitm. Is there anything else that could be causing this?

[sylvioalves]

Rf libraries are the same for a while, I don't think that would be the root cause in this scenario. Unless you have been using Zephyr v3.2.0. Are you using latest main or v3.4.0?

[sylvioalves]

Would you screenshot/copy&past stacks/heap size in that scenario? At least right after it starts to fail or if possible when failing? I re-tried running the ping flooding and I really get no issues with my esp32s3_devkitm.

[EricNRS]

Here is a partial failure that the system recovered from. I am trying to figure out who is using the heap in this case.

uart:~$ kernel heap
free:           39196
allocated:      25980
max. allocated: 52572

[00:15:16.915,000] <dbg> golioth_system: golioth_system_client_main: Event in eventfd
[00:15:16.915,000] <dbg> golioth_system: golioth_system_client_main: Sending PING
[00:15:16.918,000] <dbg> golioth_system: golioth_system_client_main: Next timeout: 119997
[00:15:17.324,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.324,000] <err> net_tcp: conn: 0x3d91beac packet allocation failed, len=1460
[00:15:17.324,000] <err> net_tcp: TCP failed to allocate buffer in retransmission
[00:15:17.425,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.425,000] <err> esp32_wifi: Failed to get net buffer
[00:15:17.526,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.526,000] <err> esp32_wifi: Failed to get net buffer
[00:15:17.626,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.626,000] <err> esp32_wifi: Failed to get net buffer
[00:15:17.726,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.726,000] <err> esp32_wifi: Failed to get net buffer
[00:15:17.812,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.812,000] <err> net_tcp: conn: 0x3d91beac packet allocation failed, len=1460
[00:15:17.812,000] <err> net_tcp: TCP failed to allocate buffer in retransmission
[00:15:17.826,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.826,000] <err> esp32_wifi: Failed to get net buffer
[00:15:17.926,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:17.926,000] <err> esp32_wifi: Failed to get net buffer

uart:~$ kernel heap
free:           15068
allocated:      50036
max. allocated: 53452
[00:15:18.021,000] <err> net_pkt: Data buffer (1486) allocation failed.
[00:15:18.038,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.038,000] <err> net_ctx: Failed to allocate net_pkt
[00:15:18.122,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.122,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.139,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.139,000] <err> net_tcp: conn: 0x3d91beac packet allocation failed, len=1460
[00:15:18.240,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.240,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.340,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.340,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.371,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.371,000] <err> net_tcp: conn: 0x3d91beac packet allocation failed, len=1460
[00:15:18.371,000] <err> net_tcp: TCP failed to allocate buffer in retransmission
[00:15:18.441,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.441,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.541,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.541,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.641,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.641,000] <err> esp32_wifi: Failed to get net buffer
[00:15:18.741,000] <err> net_pkt: Data buffer (1500) allocation failed.
[00:15:18.741,000] <err> esp32_wifi: Failed to get net buffer

uart:~$ kernel heap
free:           10272
allocated:      54824
max. allocated: 63700

uart:~$ kernel stacks
0x3fc968d0                                  (real size 4096):	unused  264	usage 3832 / 4096 (93 %)
0x3fc96820 tcp4_thread_id                   (real size 4096):	unused 2864	usage 1232 / 4096 (30 %)
0x3fc974d0 input                            (real size 2048):	unused 1352	usage  696 / 2048 (33 %)
0x3fc97290 golioth_system                   (real size 8192):	unused 5120	usage 3072 / 8192 (37 %)
0x3fc97958                                  (real size 4096):	unused 3232	usage  864 / 4096 (21 %)
0x3fc976b0 rx_q[0]                          (real size 8192):	unused 6136	usage 2056 / 8192 (25 %)
0x3fc973f0 wifi                             (real size 6656):	unused 4144	usage 2512 / 6656 (37 %)
0x3fc975e0 net_mgmt                         (real size 2048):	unused  440	usage 1608 / 2048 (78 %)
0x3fc97798 tcp_work                         (real size 2048):	unused  488	usage 1560 / 2048 (76 %)
0x3fc98240 esp_event                        (real size 4096):	unused 2656	usage 1440 / 4096 (35 %)
0x3fc97340 esp_timer                        (real size 4096):	unused 2928	usage 1168 / 4096 (28 %)
0x3fc984a8 sysworkq                         (real size 4096):	unused 2624	usage 1472 / 4096 (35 %)
0x3fc971a0 shell_uart                       (real size 4096):	unused 1040	usage 3056 / 4096 (74 %)
0x3fc96b90 logging                          (real size 4096):	unused 2960	usage 1136 / 4096 (27 %)
0x3fc982f0 idle                             (real size 2048):	unused 1344	usage  704 / 2048 (34 %)
0x3fcb0ab0 IRQ 00                           (real size 2048):	unused 1256	usage  792 / 2048 (38 %)

uart:~$ kernel heap
free:           3684
allocated:      61400
max. allocated: 63700

uart:~$ kernel stacks
0x3fc96820 tcp4_thread_id                   (real size 4096):	unused 2864	usage 1232 / 4096 (30 %)
0x3fc974d0 input                            (real size 2048):	unused 1352	usage  696 / 2048 (33 %)
0x3fc97290 golioth_system                   (real size 8192):	unused 5120	usage 3072 / 8192 (37 %)
0x3fc97958                                  (real size 4096):	unused 3232	usage  864 / 4096 (21 %)
0x3fc976b0 rx_q[0]                          (real size 8192):	unused 6136	usage 2056 / 8192 (25 %)
0x3fc973f0 wifi                             (real size 6656):	unused 4144	usage 2512 / 6656 (37 %)
0x3fc975e0 net_mgmt                         (real size 2048):	unused  440	usage 1608 / 2048 (78 %)
0x3fc97798 tcp_work                         (real size 2048):	unused  488	usage 1560 / 2048 (76 %)
0x3fc98240 esp_event                        (real size 4096):	unused 2656	usage 1440 / 4096 (35 %)
0x3fc97340 esp_timer                        (real size 4096):	unused 2928	usage 1168 / 4096 (28 %)
0x3fc984a8 sysworkq                         (real size 4096):	unused 2624	usage 1472 / 4096 (35 %)
0x3fc971a0 shell_uart                       (real size 4096):	unused 1040	usage 3056 / 4096 (74 %)
0x3fc96b90 logging                          (real size 4096):	unused 2960	usage 1136 / 4096 (27 %)
0x3fc982f0 idle                             (real size 2048):	unused 1344	usage  704 / 2048 (34 %)
0x3fcb0ab0 IRQ 00                           (real size 2048):	unused 1256	usage  792 / 2048 (38 %)

uart:~$ kernel heap
free:           15220
allocated:      49892
max. allocated: 63700

uart:~$ net mem
Fragment length 512 bytes
Network buffer pools:
Address		Total	Name
0x3fcc7398	128	RX
0x3fcc73d8	128	TX
0x3fcc777c	64	RX DATA
0x3fcc77ac	64	TX DATA
Set CONFIG_NET_BUF_POOL_USAGE to enable net_buf allocation support.

[EricNRS]

OK, what seems to be happening is that the WiFi library is calling wifi_malloc() (or wifi_calloc()) for every RX or TX packet. If the RX packets come in faster than the network stack can process them, then each new RX packet results in a heap allocation. If enough of these come in, then the heap allocation will fail because the heap is exhausted. For a 1500 byte ICMP packet, the allocation size appears to be around 1700 bytes, so if the heap remaining capacity is less than 1700 bytes, then the allocation will fail.

Likewise on the TX side, the esp_wifi_internal_tx() results in a heap allocation and if this fails, then an error message is logged which slows things down enough to result in a continuous failures until the RX packet flood stops at which point the system recovers. The best solution is probably to have wifi_malloc() use a buffer pool instead of the heap so that packet storms can be handled better. Ideally, there should be both an RX and TX buffer queue, but I don't know if that is an option with g_wifi_osi_funcs interface.

As a side note, if the main heap has been exhausted, the heap should return an address from SPIRAM, however when I tried forcing all allocations to be done from SPIRAM, a wifi connect request would just transition to the disconnected state. Does the wifi_malloc() memory need to always be from internal RAM?

With logging disabled on the network stack, the ESP32-S3 can normally keep up with the ICMP packet floods, so that is why this issue is sometimes hard to reproduce.

[EricNRS]

I added a local heap to modules/hal/espressif/zephyr/esp32s3/src/wifi/esp_wifi_adapter.c and the WiFi system correctly recovers from a packet storm without impacting other systems on the device. I can do a PR for review if this code isn't changing for the IDF 5.x upgrade that is in progress.

[sylvioalves]

@EricNRS, Please, submit a PR so we can take a look.

[EricNRS]

Pull request submitted for review.
Issue - #63043
PR - zephyrproject-rtos/hal_espressif#244

[sylvioalves]

@EricNRS, btw, are you using USB interface or UART? I only tested UART interface.

[EricNRS]

I am using the USB interface. Other options that help are to set logging mode to immediate to slow down the processing once an error occurs:

CONFIG_LOG_MODE_IMMEDIATE=y

You should see <err> esp32_wifi_adapter: memory allocation failed messages when the memory allocation fails.

[sylvioalves]

I guess that is the difference. I'll try to test using USB interface as well.