First couple of Wi-Fi connection attempt fails (IDFGH-11148)

[rechrtb]

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.

General issue report

Using https://github.com/espressif/esp-idf/tree/master/examples/wifi/getting_started/station.
Logs indicate first couple of attempts of connecting to a network fails. Access point is an RPi 4 with OpenWRT 22.03.5.

IDF version.

v5.2-dev-3065-g272b4091f1

Operating System used.

PopOS 22.04

How did you build your project?

idf.py

What is the expected behavior?

Connection to WiFi (WPA2-PSK) with correct credentials succeeds on first try.

What is the actual behavior?

First couple of attempts fail, then eventually succeeds.

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0x178c
load:0x403c9700,len:0x4
load:0x403c9704,len:0xc20
load:0x403cc700,len:0x2ee8
entry 0x403c9910
I (27) boot: ESP-IDF v5.2-dev-3065-g272b4091f1 2nd stage bootloader
I (27) boot: compile time Sep 27 2023 20:45:50
I (27) boot: Multicore bootloader
I (31) boot: chip revision: v0.0
I (35) boot.esp32s3: Boot SPI Speed : 80MHz
I (40) boot.esp32s3: SPI Mode       : DIO
I (45) boot.esp32s3: SPI Flash Size : 2MB
I (50) boot: Enabling RNG early entropy source...
I (55) boot: Partition Table:
I (59) 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=3c080020 size=208c8h (133320) map
I (125) esp_image: segment 1: paddr=000308f0 vaddr=3fc97b00 size=0450ch ( 17676) load
I (129) esp_image: segment 2: paddr=00034e04 vaddr=40374000 size=0b214h ( 45588) load
I (141) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=746b0h (476848) map
I (227) esp_image: segment 4: paddr=000b46d8 vaddr=4037f214 size=08820h ( 34848) load
I (243) boot: Loaded app from partition at offset 0x10000
I (243) boot: Disabling RNG early entropy source...
I (254) cpu_start: Multicore app
I (255) cpu_start: Pro cpu up.
I (255) cpu_start: Starting app cpu, entry point is 0x40375324
0x40375324: call_start_cpu1 at /home/rechrtb/Projects/esp-idf/components/esp_system/port/cpu_start.c:178

I (0) cpu_start: App cpu up.
I (272) cpu_start: Pro cpu start user code
I (272) cpu_start: cpu freq: 160000000 Hz
I (272) cpu_start: Application information:
I (275) cpu_start: Project name:     wifi_station
I (281) cpu_start: App version:      v5.2-dev-3065-g272b4091f1
I (287) cpu_start: Compile time:     Sep 27 2023 20:47:21
I (293) cpu_start: ELF file SHA256:  1c2603772...
I (299) cpu_start: ESP-IDF:          v5.2-dev-3065-g272b4091f1
I (305) cpu_start: Min chip rev:     v0.0
I (310) cpu_start: Max chip rev:     v0.99 
I (315) cpu_start: Chip rev:         v0.0
I (319) heap_init: Initializing. RAM available for dynamic allocation:
I (327) heap_init: At 3FC9F998 len 00049D78 (295 KiB): DRAM
I (333) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (339) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (346) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (353) spi_flash: detected chip: generic
I (357) spi_flash: flash io: dio
W (361) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (374) sleep: Configure to isolate all GPIO pins in sleep state
I (381) sleep: Enable automatic switching of GPIO sleep configuration
I (388) app_start: Starting scheduler on CPU0
I (393) app_start: Starting scheduler on CPU1
I (393) main_task: Started on CPU0
I (403) main_task: Calling app_main()
I (433) wifi station: ESP_WIFI_MODE_STA
I (433) pp: pp rom version: e7ae62f
I (433) net80211: net80211 rom version: e7ae62f
I (443) wifi:wifi driver task: 3fca9b58, prio:23, stack:6656, core=0
I (453) wifi:wifi firmware version: cb43ccc
I (453) wifi:wifi certification version: v7.0
I (453) wifi:config NVS flash: enabled
I (453) wifi:config nano formating: disabled
I (463) wifi:Init data frame dynamic rx buffer num: 32
I (463) wifi:Init static rx mgmt buffer num: 5
I (463) wifi:Init management short buffer num: 32
I (473) wifi:Init dynamic tx buffer num: 32
I (473) wifi:Init static tx FG buffer num: 2
I (483) wifi:Init static rx buffer size: 1600
I (483) wifi:Init static rx buffer num: 10
I (483) wifi:Init dynamic rx buffer num: 32
I (493) wifi_init: rx ba win: 6
I (493) wifi_init: tcpip mbox: 32
I (503) wifi_init: udp mbox: 6
I (503) wifi_init: tcp mbox: 6
I (503) wifi_init: tcp tx win: 5744
I (513) wifi_init: tcp rx win: 5744
I (513) wifi_init: tcp mss: 1440
I (523) wifi_init: WiFi IRAM OP enabled
I (523) wifi_init: WiFi RX IRAM OP enabled
I (533) phy_init: phy_version 610,2bff4c8,Jul 27 2023,20:22:14
I (573) wifi:mode : sta (84:f7:03:a0:0b:b8)
I (573) wifi:enable tsf
I (573) wifi station: wifi_init_sta finished.
I (583) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1
I (583) wifi:state: init -> auth (b0)
I (593) wifi:state: auth -> assoc (0)
I (593) wifi:state: assoc -> init (2c0)
I (593) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1
W (603) wifi station: retry to connect to the AP
W (603) wifi station: connect to the AP fail
W (3003) wifi station: retry to connect to the AP
W (3013) wifi station: connect to the AP fail
I (3013) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1
I (3013) wifi:state: init -> auth (b0)
I (3023) wifi:state: auth -> assoc (0)
I (3033) wifi:state: assoc -> run (10)
I (3043) wifi:connected with demo-wifi, aid = 1, channel 2, BW20, bssid = d8:3a:dd:2a:30:dd
I (3043) wifi:security: WPA2-PSK, phy: bgn, rssi: -51
I (3053) wifi:pm start, type: 1

I (3053) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
I (3053) wifi:AP's beacon interval = 102400 us, DTIM period = 2
I (3073) wifi:<ba-add>idx:0 (ifx:0, d8:3a:dd:2a:30:dd), tid:6, ssn:0, winSize:64
I (4063) esp_netif_handlers: sta ip: 192.168.111.203, mask: 255.255.255.0, gw: 192.168.111.1
I (4063) wifi station: got ip:192.168.111.203
I (4063) wifi station: connected to ap SSID:demo-wifi password:demo-pswd
I (4073) main_task: Returned from app_main()
I (8173) wifi:<ba-add>idx:1 (ifx:0, d8:3a:dd:2a:30:dd), tid:0, ssn:2, winSize:64

[rechrtb]

Looking into this issue more, this seems to happen when the ESP doesn't disconnect from AP cleanly.

For example, using the wifi/getting_started/station: If the reset button on the ESP32-S3 devkit is pressed after connection succeeded, the next 1 or 2 attempt after reboot will fail with WIFI_REASON_ASSOC_FAIL, reason 203 but eventually succeed.

If, however the example is modified to have esp_wifi_stop() called after connection succeeded, and the reset button is pressed, first connection after reboot attempt succeeds immediately.

[rechrtb]

Some more details in reproducing this issue. The wifi/getting_started/station example app_main is modified to the following:

void app_main(void)
{
    //Initialize NVS
    esp_err_t ret = nvs_flash_init();
    if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) {
      ESP_ERROR_CHECK(nvs_flash_erase());
      ret = nvs_flash_init();
    }
    ESP_ERROR_CHECK(ret);

    ESP_LOGI(TAG, "ESP_WIFI_MODE_STA");

    while (true)
    {
        wifi_init_sta();
        ESP_LOGI(TAG, "pre-stop pause...");
        vTaskDelay(pdMS_TO_TICKS(3000));
        esp_wifi_stop();
        ESP_LOGI(TAG, "post-stop pause...");
        vTaskDelay(pdMS_TO_TICKS(3000));
    }
}

pre-stop-reset:
If the devkit reset button is pressed during the pre-stop pause... period, on reboot the first one/two connection attempt will fail, but eventually succeed.

post-stop-reset:
But if the devkit reset button is pressed during the post-stop pause... period, on reboot the first connection attempt will succeed immediately.

Here are the verbose logs for each case:

pre-stop-reset.log
post-stop-reset.log

[Xiehanxin]

PopOS

This might be because the router takes some time to realize that the device has disconnected, possibly due to the device not sending a 'deauth' signal before rebooting. I think using esp_wifi_disconnect should work like esp_wifi_stop. It will be fixed upcoming versions.

[rechrtb]

More information for you @Xiehanxin.

It seems this behavior is not reproducible depending on the access point.
As mentioned in the initial post, I've tried this on an access point created with RPi 4 onboard WiFi chip running OpenWRT 22.03.5. On this, it's consistently reproducible.

But on my personal router running same version of OpenWRT but with MT7621A-based wifi (GL.iNet GL-MT1300), it doesn't happen at all.

[AxelLin]

PopOS

This might be because the router takes some time to realize that the device has disconnected, possibly due to the device not sending a 'deauth' signal before rebooting. I think using esp_wifi_disconnect should work like esp_wifi_stop. It will be fixed upcoming versions.

I don't quite understand your reply.
Could you clarify what will be fixed?

[rechrtb]

Hi @AxelLin, you mean this reply?

What I meant by that is, the issue is present on some access points but not on others. So if you want to reproduce the issue, I've encountered it with an access point created from RPI4.

[AxelLin]

Hi @AxelLin, you mean this reply?

No, my previous comment is for @Xiehanxin
Since he said that "it will be fixed upcoming versions.", I just don't understand what will be fixed?

[Xiehanxin]

hi @AxelLin , In fact, it was later discovered that there was no need for a fix because it was a compatibility issue with certain special routers. Simply disconnecting before stopping resolved the issue.

[rechrtb]

Hi @Xiehanxin, so is this issue not going to be fixed? I'm asking because "disconnecting before stopping" isn't exactly always doable, especially with embedded where power can be removed by user at any time.

[AxelLin]

@mhdong
Just remind the v5.2 still needs fix.

[AxelLin]

@mhdong

This issue seems not related to dns?
I'm curious what was fixed by 00c2767 "fix(wifi): fix reset connection dns fail issue" ?

[AxelLin]

@mhdong Just remind the v5.2 still needs fix.

@mhdong
In v5.0.7 release log, I found this:
Fixed the issue of DNS failure caused by continuously initiating connections to the same router (#12315) (17bdbed)
There is no way to kown if commit 17bdbed is related to this bug, the commit log tells nothing.
Please confirm if this is fixed by v5.2 branch or not since the commit log in esp_wifi does not help.

[AxelLin]

@mhdong

This issue seems not related to dns? I'm curious what was fixed by 00c2767 "fix(wifi): fix reset connection dns fail issue" ?

I don't understand why this fix is related to this issue, could you explain why it fixed below failure? @mhdong

I (593) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1
W (603) wifi station: retry to connect to the AP
W (603) wifi station: connect to the AP fail
W (3003) wifi station: retry to connect to the AP
W (3013) wifi station: connect to the AP fail
I (3013) wifi:new:<2,0>, old:<2,0>, ap:<255,255>, sta:<2,0>, prof:1
I (3013) wifi:state: init -> auth (b0)
I (3023) wifi:state: auth -> assoc (0)
I (3033) wifi:state: assoc -> run (10)

[mhdong]

Hi @AxelLin
If the router retains the previous connection information, it may cause various errors during the next connection attempt. The symptoms include no response to authentication, leading to auth timeout; no response to DHCP, leading to DHCP timeout; and no response to DNS, leading to DNS timeout. Different routers may exhibit different symptoms.
When PMF is disabled, STA send deauth before first connection. There are two situations with routers, one is not replying to the deauth, and the other is replying to the deauth. No matter reply or not, it is assumed that the router will clear previous connection.

[AxelLin]

@mhdong
Ok, so could you share if this is fixed in all impacted branches?
The thing is the backport commit log does not tell any useful information (e.g. fix(wifi): fix some wifi bugs 240715(Backport v5.0)) , people outside of espressif does not know if it is fixed or not on certain branches.

[rechrtb]

Hello, since there seems to be activity on this issue recently and a supposed fix - I'd like to try it out! What branch should I build with?

[mhdong]

Hi @rechrtb @AxelLin
v5.3 2c48120
v5.0 ab10ce0
other branchs have not benn backported yet. We will backport it to other branchs as soon as possible