wifi ap loss packages by wps_softap_registrar example (IDFGH-11609)

[qjy0129]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.0.4-319-ga6afbb38a4

Espressif SoC revision.

esp32

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

esp32-wroom-32e

Power Supply used.

USB

What is the expected behavior?

laptop wifi requests a dhcp request, and an esp32 hotspot returns a dhcp ack message

What is the actual behavior?

Laptop wifi DHCP request multiple times and the DHCP ack message replied by ESP32 are not equal.
From packet capture analysis, it can be seen that EPS32 responds less to DHCP ack messages.

Steps to reproduce.

1. run esp-idf/examples/wifi/wps_softap_registrar example
2. Starting wireshark tool on the laptop
3. laptop wifi connection to EPS32 hotspot
4. If there is no reproducible problem, connect repeatedly

Debug Logs.

I (27) boot: ESP-IDF v5.0.4-319-ga6afbb38a4 2nd stage bootloader
I (27) boot: compile time 13:40:45
I (27) boot: Multicore bootloader
I (32) boot: chip revision: v3.1
I (36) boot.esp32: SPI Speed      : 40MHz
I (40) boot.esp32: SPI Mode       : DIO
I (45) boot.esp32: SPI Flash Size : 2MB
I (49) boot: Enabling RNG early entropy source...
I (55) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (66) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (73) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (81) boot:  2 factory          factory app      00 00 00010000 00100000
I (88) boot: End of partition table
I (92) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=1dba8h (121768) map
I (145) esp_image: segment 1: paddr=0002dbd0 vaddr=3ffb0000 size=02448h (  9288) load
I (149) esp_image: segment 2: paddr=00030020 vaddr=400d0020 size=83ef8h (540408) map
I (346) esp_image: segment 3: paddr=000b3f20 vaddr=3ffb2448 size=01080h (  4224) load
I (348) esp_image: segment 4: paddr=000b4fa8 vaddr=40080000 size=1553ch ( 87356) load
I (398) boot: Loaded app from partition at offset 0x10000
I (398) boot: Disabling RNG early entropy source...
I (410) cpu_start: Multicore app
I (410) cpu_start: Pro cpu up.
I (410) cpu_start: Starting app cpu, entry point is 0x400812bc
0x400812bc: call_start_cpu1 at /home/qjy/pro/esp32/env/esp-gitee-tools/esp-idf/components/esp_system/port/cpu_start.c:147

I (0) cpu_start: App cpu up.
I (428) cpu_start: Pro cpu start user code
I (428) cpu_start: cpu freq: 160000000 Hz
I (428) cpu_start: Application information:
I (433) cpu_start: Project name:     wps_softap_registrar
I (439) cpu_start: App version:      v5.0.4-319-ga6afbb38a4
I (445) cpu_start: Compile time:     Dec  5 2023 13:42:28
I (451) cpu_start: ELF file SHA256:  0a659d3f6dd8b692...
I (457) cpu_start: ESP-IDF:          v5.0.4-319-ga6afbb38a4
I (463) cpu_start: Min chip rev:     v0.0
I (468) cpu_start: Max chip rev:     v3.99 
I (473) cpu_start: Chip rev:         v3.1
I (478) heap_init: Initializing. RAM available for dynamic allocation:
I (485) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (491) heap_init: At 3FFB7238 len 00028DC8 (163 KiB): DRAM
I (497) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (504) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (510) heap_init: At 4009553C len 0000AAC4 (42 KiB): IRAM
I (518) spi_flash: detected chip: generic
I (521) spi_flash: flash io: dio
W (525) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (539) app_start: Starting scheduler on CPU0
I (543) app_start: Starting scheduler on CPU1
mI (543) main_task: Started on CPU0
I (553) main_task: Calling app_main()
I (593) wifi:wifi driver task: 3ffbf224, prio:23, stack:6656, core=0
I (593) system_api: Base MAC address is not set
I (593) system_api: read default base MAC address from EFUSE
I (603) wifi:wifi firmware version: c67464b
I (603) wifi:wifi certification version: v7.0
I (603) wifi:config NVS flash: enabled
I (603) wifi:config nano formating: disabled
I (613) wifi:Init data frame dynamic rx buffer num: 32
I (613) wifi:Init static rx mgmt buffer num: 5
I (623) wifi:Init management short buffer num: 32
I (623) wifi:Init dynamic tx buffer num: 32
I (633) wifi:Init static rx buffer size: 1600
I (633) wifi:Init static rx buffer num: 10
I (633) wifi:Init dynamic rx buffer num: 32
I (643) wifi_init: rx ba win: 6
I (643) wifi_init: tcpip mbox: 32
I (643) wifi_init: udp mbox: 6
I (653) wifi_init: tcp mbox: 6
I (653) wifi_init: tcp tx win: 5744
I (663) wifi_init: tcp rx win: 5744
I (663) wifi_init: tcp mss: 1440
I (663) wifi_init: WiFi IRAM OP enabled
I (673) wifi_init: WiFi RX IRAM OP enabled
I (683) phy_init: phy_version 4771,450c73b,Aug 16 2023,11:03:10
I (773) wifi:mode : softAP (64:b7:08:69:86:45)
I (783) wifi:Total power save buffer number: 16
I (783) wifi:Init max length of beacon: 752/752
I (783) wifi:Init max length of beacon: 752/752
I (783) example_wps_registrar: start wps...
I (783) example_wps_registrar: WIFI_EVENT_AP_START
I (793) example_wps_registrar: Staring WPS registrar in PBC mode
I (803) main_task: Returned from app_main()
I (67113) wifi:new:<1,1>, old:<1,1>, ap:<1,1>, sta:<255,255>, prof:1
I (67113) wifi:station: 34:f6:4b:c2:02:db join, AID=1, bgn, 40U
I (67143) example_wps_registrar: WIFI_EVENT_AP_STACONNECTED
I (67143) example_wps_registrar: station 34:f6:4b:c2:02:db join, AID=1
I (69213) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.2
I (69393) wifi:<ba-add>idx:2 (ifx:1, 34:f6:4b:c2:02:db), tid:0, ssn:20, winSize:64
I (80193) wifi:new:<1,1>, old:<1,1>, ap:<1,1>, sta:<255,255>, prof:1
I (80203) wifi:station: 58:ce:2a:14:44:7a join, AID=2, bgn, 40U
I (80233) example_wps_registrar: WIFI_EVENT_AP_STACONNECTED
I (80233) example_wps_registrar: station 58:ce:2a:14:44:7a join, AID=2
I (80303) wifi:<ba-add>idx:3 (ifx:1, 58:ce:2a:14:44:7a), tid:0, ssn:8, winSize:64
I (117833) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.10
I (120763) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.10
I (120803) example_wps_registrar: WIFI_EVENT_AP_WPS_RG_TIMEOUT

More Information.

No response

[qjy0129]

Additional information
This was first discovered in your other projects
espressif/esp-hosted#289

[qjy0129]

Is there still someone in your company investigating this issue? I haven't heard any news for a long time.

[kapilkedawat]

Please attach sniffer capture.

[qjy0129]

This involves message/packet capturing：espressif/esp-hosted#289
Can't this issue be reproduced internally by your team? It seems to be relatively easy to reproduce.

[kapilkedawat]

Please do a capture over the air instead of capturing at different places.

[qjy0129]

Can you take a careful look at the previous analysis process? espressif/esp-hosted#289
At the same time，I will re-capture the packet.

[qjy0129]

Re-captured the packet.
Esp32 run wps_softap_registrar example.
The message was captured on a laptop, which was connected to the eps32 hotspot via wireless.
By filtering DHCP messages, it was found that there were two consecutive DHCP Discovery messages sent. Within the first two seconds timeout, no DHCP Offer message was received, so it was re-sent again. This is likely caused by the eps32 air interface losing the Offer message.

esp32.txt
Due to upload attachment limitations, the esp32.txt needs to be renamed to esp32.pcapng so that it can be opened via Wireshark

[kapilkedawat]

Hi @qjy0129, these packets are captured on wired interface on station which doesn't give full picture. Could you please try to capture packets on a spare linux wifi system.

Linux:
sudo ifconfig down
sudo iwconfig mode monitor
sudo ifconfig up
sudo iwconfig channel <channel_number>

Also please disable your network manager before doing this.

[qjy0129]

esp32_cap.tar.gz
After decompressing the attachment, you can view the complete packet using the Wireshark tool.

[qjy0129]

Is it difficult for you to reproduce this issue on your side? I feel that it should be easily reproducible.
espressif/esp-hosted#289 In this discussion, your other team has also reproduced this issue.

[qjy0129]

@jgujarathi Hello, has there been any progress on this issue? If so, could you please inform me?

[jgujarathi]

Hi @qjy0129 ,
We are analysing the issue actively. We will get back to you with any updates.

[jgujarathi]

Hi @qjy0129 ,
We have tried reproducing the issue. While there are multiple DHCP requests sent by the station in the sniffer captures only a few are actually acknowledged by our wps softap registrar device. The acknowledgement implies that it is received by our Wi-Fi stack. In our experiments we have noticed that every DHCP Request that has been acknowledged is passed down to the DHCP server , a corresponding DHCP ACK/NAK is sent out and is visible in the sniffer capture. This means that the other DHCP packets you see are dropped in the air and not by the esp32 device. This can be due to several factors involved in wireless networking.

Please find attached a sample sniffer capture on our end.
example.zip
In this example there are 5 DHCP requests sent out but only 2 are actually acknowledged by our device. There are 2 corresponding DHCP ACKs as a result. Please add the decryption keys by following https://wiki.wireshark.org/HowToDecrypt802.11. (wpa-pwd -> mypassword:myssid). The station has the mac address 3e:8b:cc:08:d9:c0.

If you come across a case where the wps softAp registrar has acknowledged a DHCP Request and not generated a DHCP Ack/NAK please provide us with a sniffer capture and debug logs.

[qjy0129]

Hi @jgujarathi
espressif/esp-hosted#289
In this discussion, it has been clarified through log additions that the packets are being dropped at the esp esp_wifi_internel_tx interface.

[qjy0129]

In addition, run esp-idf/examples/wifi/iperf test case:
On the esp32, execute the command:

ap test 12345678

Connect the laptop to the 'test' hotspot, and it acquires an IP address of 192.168.4.2.
On the laptop, execute the command:

iperf -s -u -i 1

Then on the esp32, execute the following command:

iperf -c 192.168.4.2 -u -b 1 -i 1 -t 9999

From the iperf results on the laptop, packet loss is observed, even at a rate of 1Mbps. Have you guys used your esp's Wi-Fi module in commercial applications, or is it only suitable for personal DIY projects?

[jgujarathi]

Hi @qjy0129,
We hope you understand that in wireless networking there is always a possibility of dropping packets due to several factors that do not exist in wired mediums. When the rate is limited to 1mbps, it is impossible to achieve that rate in a real world environment due to several reasons for interference. Several APs and devices using the same medium can cause contention issues and it is quite tough to get the slot to send out packets, especially for the amount of time that bigger packets iperf uses will require. There are additional factors that can cause even more drop in rate, such as the RX capabilities of the intended target, it's buffer sizes and it's configuration.
In my previous comment I have attached sniffer captures in which we have measured that every DHCP message sent from the DHCP server does actually make it into the air (sent through esp_wifi_internal_tx). I am attaching further logs of a iperf throughput test we conducted following your steps but in a relatively quiet environment and were able to achieve near perfect 1mbps throughout the test.
throughput_quiet_env.txt

[qjy0129]

Hi @jgujarathi ，
Thank you very much for your response.
When ESP32 sends messages through esp_wifi_internal_tx interface, what device do you use to capture the packets transmitted over the air?
Currently, it seems that the issue might be due to either the antenna on my ESP32 development board or the Wi-Fi functionality of my laptop not functioning well?

[jgujarathi]

Hi @qjy0129 ,
We use a Linux desktop with it's wireless interface set in monitor mode. Please refer to this comment for the recommended setup.