ESP-IDF cannot reconnect after AP initiated leave (IDFGH-13776)

[xoores]

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.4-dev

Espressif SoC revision.

ESP32-S2 (revision v0.0)

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.

Olimex ESP32-S2-DevKit-Lipo-USB

Power Supply used.

USB

What is the expected behavior?

When AP disconnects client, the client (ESP) should be able to reconnect.

What is the actual behavior?

ESP fails to reconnect with reson 210: NO_AP_W_COMPAT_SECURITY and cannot reconnect until whole wifi stack is restarted or the device rebooted.

Steps to reproduce.

1. Have AP kick out ESP32
2. Wait for ESP32 to reconnect
3. ESP32 fails to reconnect

Debug Logs.

(called esp_wifi_connect() here)
26.09 22:05:49.035| +WIFI: Connecting to 'xxxxxxx'
D (106367) wifi:clear blacklist
D (106377) wifi:Start wifi connect
D (106377) wifi:connect status 3 -> 0
D (106377) wifi:connect chan=0
D (106377) wifi:first chan=1
D (106377) wifi:connect status 0 -> 1
D (106387) wifi:filter: set rx policy=3
D (106387) wifi:clear scan ap list
D (106387) wifi:start scan: type=0x50f, priority=2, cb=0x400df3c8, arg=0x0, ss_state=0x1, time=106388797, index=0
--- 0x400df3c8: cnx_start_handoff_cb at ??:?

V (106397) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (106407) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (106407) wifi:change: chan<1,0>, dur<0,120>
V (106407) wifi:enter start op, arg=0x3ffd393c
V (106417) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffd393c, status=0
V (106417) wifi:scan specific ssid=xxxxxxx
V (106427) wifi:start max timer
D (106437) wifi:AKM mismatch: AP is not Enterprise
D (106437) wifi:AKM mismatch: AP is not Enterprise
D (106507) wifi:AKM mismatch: AP is not Enterprise

^------- These lines do not appear in the first (successful) connection

D (33007) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33007) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (33007) wifi:change: chan<2,0>, dur<0,120>
V (33017) wifi:ht20 freq=2417, chan=2
V (33017) wifi:enter start op, arg=0x3ffd393c
V (33017) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3ffd393c, status=0
V (33027) wifi:scan specific ssid=xxxxxxx
V (33027) wifi:start max timer
D (33147) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33147) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (33147) wifi:change: chan<3,0>, dur<0,120>
V (33157) wifi:ht20 freq=2422, chan=3
V (33167) wifi:enter start op, arg=0x3ffd393c
V (33167) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3ffd393c, status=0
V (33177) wifi:scan specific ssid=xxxxxxx
V (33177) wifi:start max timer
D (33297) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33297) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (33297) wifi:change: chan<4,0>, dur<0,120>
V (33307) wifi:ht20 freq=2427, chan=4
V (33307) wifi:enter start op, arg=0x3ffd393c
V (33307) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3ffd393c, status=0
V (33317) wifi:scan specific ssid=xxxxxxx
V (33317) wifi:start max timer
D (33447) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33447) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (33447) wifi:change: chan<5,0>, dur<0,120>
V (33457) wifi:ht20 freq=2432, chan=5
V (33457) wifi:enter start op, arg=0x3ffd393c
V (33457) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3ffd393c, status=0
V (33467) wifi:scan specific ssid=xxxxxxx
V (33467) wifi:start max timer
D (33587) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33587) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
V (33587) wifi:change: chan<6,0>, dur<0,120>
V (33597) wifi:ht20 freq=2437, chan=6
V (33607) wifi:enter start op, arg=0x3ffd393c
V (33607) wifi:scan operation: state=0x3, chan<6,0>, arg=0x3ffd393c, status=0
V (33617) wifi:scan specific ssid=xxxxxxx
V (33617) wifi:start max timer
D (33737) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33737) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
V (33737) wifi:change: chan<7,0>, dur<0,120>
V (33747) wifi:ht20 freq=2442, chan=7
V (33747) wifi:enter start op, arg=0x3ffd393c
V (33747) wifi:scan operation: state=0x3, chan<7,0>, arg=0x3ffd393c, status=0
V (33757) wifi:scan specific ssid=xxxxxxx
V (33767) wifi:start max timer
D (33887) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (33887) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
V (33887) wifi:change: chan<8,0>, dur<0,120>
V (33897) wifi:ht20 freq=2447, chan=8
V (33897) wifi:enter start op, arg=0x3ffd393c
V (33897) wifi:scan operation: state=0x3, chan<8,0>, arg=0x3ffd393c, status=0
V (33907) wifi:scan specific ssid=xxxxxxx
V (33907) wifi:start max timer
D (34027) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (34027) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
V (34027) wifi:change: chan<9,0>, dur<0,120>
V (34037) wifi:ht20 freq=2452, chan=9
V (34047) wifi:enter start op, arg=0x3ffd393c
V (34047) wifi:scan operation: state=0x3, chan<9,0>, arg=0x3ffd393c, status=0
V (34057) wifi:scan specific ssid=xxxxxxx
V (34057) wifi:start max timer
D (34177) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (34177) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
V (34177) wifi:change: chan<10,0>, dur<0,120>
V (34187) wifi:ht20 freq=2457, chan=10
V (34187) wifi:enter start op, arg=0x3ffd393c
V (34187) wifi:scan operation: state=0x3, chan<10,0>, arg=0x3ffd393c, status=0
V (34197) wifi:scan specific ssid=xxxxxxx
V (34207) wifi:start max timer
D (34327) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (34327) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (34327) wifi:change: chan<11,0>, dur<0,120>
V (34337) wifi:ht20 freq=2462, chan=11
V (34337) wifi:enter start op, arg=0x3ffd393c
V (34337) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3ffd393c, status=0
V (34347) wifi:scan specific ssid=xxxxxxx
V (34347) wifi:start max timer
D (34467) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (34467) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
V (34467) wifi:change: chan<12,0>, dur<360,360>
V (34477) wifi:ht20 freq=2467, chan=12
V (34487) wifi:enter start op, arg=0x3ffd393c
V (34487) wifi:scan operation: state=0x3, chan<12,0>, arg=0x3ffd393c, status=0
V (34497) wifi:passive scan, listen only
V (34497) wifi:start max timer
D (34857) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (34857) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
V (34857) wifi:change: chan<13,0>, dur<360,360>
V (34867) wifi:ht20 freq=2472, chan=13
V (34867) wifi:enter start op, arg=0x3ffd393c
V (34867) wifi:scan operation: state=0x3, chan<13,0>, arg=0x3ffd393c, status=0
V (34877) wifi:passive scan, listen only
V (34877) wifi:start max timer
D (35237) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (35247) wifi:perform scan: ss_state=0x9, chan<14,0>, dur<360,360>
V (35247) wifi:change: chan<14,0>, dur<360,360>
V (35257) wifi:ht20 freq=2484, chan=14
V (35257) wifi:enter start op, arg=0x3ffd393c
V (35257) wifi:scan operation: state=0x3, chan<14,0>, arg=0x3ffd393c, status=0
V (35267) wifi:passive scan, listen only
V (35267) wifi:start max timer
D (35627) wifi:scan end: arg=0x0, status=0, ss_state=0x3
V (35627) wifi:back home chan=<1,0>, current chan=<14,0>
V (35627) wifi:ht20 freq=2412, chan=1
D (35637) wifi:filter: set rx policy=4
D (35637) wifi:first chan=1
V (35637) wifi:scan_done: arg=0x0, status=0, cur_time=35644737, scan_id=129, scan state=0
V (35657) wifi:call scan_done cb, arg=0x0
D (35657) wifi:handoff_cb: status=0
D (35657) wifi:clear rc list
D (35657) wifi:clear blacklist
D (35667) wifi:Send disconnect event, reason=210
D (35667) wifi:connect status 1 -> 3
D (35667) wifi:disable connect timer
D (35677) wifi:clear scan ap list

More Information.

When comparing logs from successful vs unsuccessful connection, there is an immediate error about AKM mismatch: AP is not Enterprise - however the network is not enterprise, it is WPA2.

Dump of WLANs that are seen by the ESP:

26.09 22:32:52.921| +WLAN: +--+-----------------+---+---+---+----------+---+------+------------~
26.09 22:32:52.922| +WLAN: |ID|BSSID            |dBm|Ch |TTL| SECURITY |Pts|Flags |SSID
26.09 22:32:52.934| +WLAN: +--+-----------------+---+---+---+----------+---+------+------------~
26.09 22:32:52.946| +WLAN: |00|XX:XX:XX:XX:38:f2|-70| 11| 70|WPA2_PSK  | 20|KST...|xxxxxxx
26.09 22:32:52.947| +WLAN: |01|XX:XX:XX:XX:27:d1|-75|  1|255|WPA2_PSK  | 23|KS...*|xxxxxxx
26.09 22:32:52.959| +WLAN: |02|XX:XX:XX:XX:b9:c6|-88|  4| 30|WPA2_PSK  |  0|......|yyyyyyy
26.09 22:32:52.972| +WLAN: +--+-----------------+---+---+---+----------+---+------+------------~

There are 2 WLANs that have the same SSID and are broadcasted by two different APs.

I even put the wifi_config_t as a global variable to rule out that I changed something on accident. No change in behavior, the first esp_wifi_connect() is successful, but any other subsequent fails with the same wifi_config_t...

Log from successful connection to the same network:

+WIFI: Connecting to 'xxxxxxx'
D (4817) wifi:clear blacklist
D (4927) wifi:Start wifi connect
D (4927) wifi:connect status 0 -> 0
D (4927) wifi:connect chan=0
V (4927) wifi:nvs=0, ssid=xxxxxxx, channel=11
V (4937) wifi:ssid=xxxxxxx match nvs 0, channel=11
D (4937) wifi:first chan=11
D (4937) wifi:connect status 0 -> 1
D (4937) wifi:filter: set rx policy=3
D (4947) wifi:clear scan ap list
D (4947) wifi:start scan: type=0x50f, priority=2, cb=0x400df3c8, arg=0x0, ss_state=0x1, time=4950944, index=0
--- 0x400df3c8: cnx_start_handoff_cb at ??:?

V (4957) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (4957) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (4967) wifi:change: chan<11,0>, dur<0,120>
V (4967) wifi:ht20 freq=2462, chan=11
V (4977) wifi:enter start op, arg=0x3ffd393c
V (4987) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3ffd393c, status=0
V (4987) wifi:scan specific ssid=xxxxxxx
V (4997) wifi:start max timer
D (5117) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5127) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (5137) wifi:change: chan<1,0>, dur<0,120>
V (5137) wifi:ht20 freq=2412, chan=1
V (5137) wifi:enter start op, arg=0x3ffd393c
V (5147) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffd393c, status=0
V (5147) wifi:scan specific ssid=xxxxxxx
V (5157) wifi:start max timer
D (5167) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=XX:XX:XX:XX:27:d1
V (5167) wifi:updated connection retries to 0
D (5167) wifi:profile match: ss_state=0x7
V (5177) wifi:scan histroy table is not full yet, add
V (5177) wifi:add ssid=xxxxxxx, chan=1 to scan history
D (5177) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (5197) wifi:find first mathched ssid, scan done
V (5197) wifi:back home chan=<1,0>, current chan=<1,0>
D (5207) wifi:filter: set rx policy=4
D (5207) wifi:first chan=1
V (5207) wifi:scan_done: arg=0x0, status=0, cur_time=5208254, scan_id=128, scan state=0
V (5217) wifi:call scan_done cb, arg=0x0
D (5217) wifi:handoff_cb: status=0
V (5217) wifi:best bss has set.
D (5227) wifi:ap found, mac=XX:XX:XX:XX:27:d1
V (5227) wifi:bssid=XX:XX:XX:XX:27:d1, LR=0
D (5457) wifi:going for connection with bssid=XX:XX:XX:XX:27:d1
D (5457) wifi:new_bss=0x3ffd4b10, cur_bss=0x0, new_chan=<1,0>, cur_chan=1
D (5457) wifi:filter: set rx policy=5
I (5467) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1, snd_ch_cfg:0x0
D (5467) wifi:connect_op: status=0, auth=5, cipher=3 
D (5477) wifi:auth mode is not none
D (5477) wifi:connect_bss: auth=1, reconnect=0
I (5487) wifi:state: init -> auth (0xb0)
D (5497) wifi:start 1s AUTH timer
D (5497) wifi:clear scan ap list
D (5497) wifi:recv auth: seq=2, status=0
I (5507) wifi:state: auth -> assoc (0x0)
D (5507) wifi:restart connect 1s timer for assoc
D (5527) wifi:recv assoc: type=0x10
D (5537) wifi:filter: set rx policy=6
I (5537) wifi:state: assoc -> run (0x10)
D (5537) wifi:start 10s connect timer for 4 way handshake
V (5547) wifi:wpa_psk start
V (5547) wifi:wpa_psk handle succeed
V (5547) wifi:tx process: alloc static tx buf, pb=0x0 l=135 hdr=0 data=135
V (5567) wifi:wpa_psk start
V (5577) wifi:wpa_psk handle succeed
V (5577) wifi:tx process: alloc static tx buf, pb=0x0 l=113 hdr=0 data=113
I (5587) wifi:connected with xxxxxxx, aid = 8, channel 1, BW20, bssid = XX:XX:XX:XX:27:d1
I (5597) wifi:security: WPA2-PSK, phy: bgn, rssi: -78
D (5607) wifi:remove all except XX:XX:XX:XX:27:d1 from rc list
D (5617) wifi:clear blacklist
D (5687) wifi:filter: set rx policy=7
I (5687) wifi:pm start, type: 1

I (5687) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
D (5697) wifi:clear blacklist
D (5697) wifi:Send sta connected event
D (5697) wifi:connect status 1 -> 5
D (5697) wifi:obss scan is disabled
D (5697) wifi:start obss scan: obss scan is stopped
I (5717) wifi:AP's beacon interval = 102400 us, DTIM period = 1
V (5717) wifi:tx process: alloc static tx buf, pb=0x3f810334 l=350 hdr=0 data=350
D (5717) wifi:eb is dhcp or dns sport = 68, dport = 67
+WLAN[xxxxxxx]: Successfully connected

This issue exists atleast from 5.3 (I was on dev also, but upgraded to 5.4-dev to see if the issue was fixed or not).