ESP32S3 may join bad signal AP when set WIFI_CONNECT_AP_BY_SIGNAL (IDFGH-13008)

[AxelLin]

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.2.2-89-gcc9edf2085 and master

Espressif SoC revision.

ESP32S3

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.

ESP32S3-WROOM-1

Power Supply used.

USB

What is the expected behavior?

When WIFI_CONNECT_AP_BY_SIGNAL is set, the device should select AP with best signal to join.

What is the actual behavior?

Sometimes, the esp32s3 (as a STA) will select AP with bad signal to join.

Steps to reproduce.

I test with a few TP-Link Deco AP around my esp32s3.

I use below setting in my wifi_config:
.scan_method = WIFI_ALL_CHANNEL_SCAN,
.sort_method = WIFI_CONNECT_AP_BY_SIGNAL,

However, it seems the esp32s3 does not always connect to the best signal AP.
In my test environment, the AP ac:84:c6:32:1a:26 and ac:84:c6:32:14:77 are closed to the test device.
d8:47:32:7c:37:ae is far away.
However, sometimes the ESP32S3 will join d8:47:32:7c:37:ae, but it's not the best signal AP.
Also note, testing at the same place the ESP32 works fine which won't select d8:47:32:7c:37:ae to join.
Only ESP32S3 has this issue.

Debug Logs.

D (4536) wifi:Start wifi connect
D (4539) wifi:connect status 0 -> 0
D (4542) wifi:connect chan=0
D (4544) wifi:first chan=1
D (4547) wifi:connect status 0 -> 1
D (4550) wifi:filter: set rx policy=3
D (4553) wifi:clear scan ap list
D (4556) wifi:start scan: type=0x50f, priority=2, cb=0x42089ce0, arg=0x0, ss_state=0x1, time=4561856, index=0
0x42089ce0: cnx_start_handoff_cb at ??:?

D (4566) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
D (4692) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (4693) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
D (4813) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (4814) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
D (4935) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (4935) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
D (5056) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5057) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
D (5178) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5178) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
D (5299) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5300) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
D (5421) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5421) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
D (5542) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5543) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
D (5664) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5664) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
D (5681) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:1a:26
D (5682) wifi:profile match: ss_state=0x7
D (5701) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:14:77
D (5702) wifi:profile match: ss_state=0x7
D (5706) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:1a:26
D (5708) wifi:profile match: ss_state=0x7
D (5756) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=d8:47:32:7c:37:ae
D (5756) wifi:profile match: ss_state=0x7
D (5764) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:14:77
D (5764) wifi:profile match: ss_state=0x7
D (5785) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (5786) wifi:perform scan: ss_state=0xd, chan<11,0>, dur<0,120>
D (5907) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (5907) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
D (6268) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6268) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
D (6629) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6629) wifi:perform scan: ss_state=0xd, chan<14,0>, dur<360,360>
D (6990) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6990) wifi:filter: set rx policy=4
D (6991) wifi:first chan=1
D (6991) wifi:handoff_cb: status=0
D (6993) wifi:ap found, mac=d8:47:32:7c:37:ae
D (7362) wifi:going for connection with bssid=d8:47:32:7c:37:ae
D (7362) wifi:new_bss=0x3fca5288, cur_bss=0x0, new_chan=<10,2>, cur_chan=1
D (7363) wifi:filter: set rx policy=5
I (7367) wifi:new:<10,2>, old:<1,0>, ap:<255,255>, sta:<10,2>, prof:1
D (7373) wifi:connect_op: status=0, auth=5, cipher=3 
D (7378) wifi:auth mode is not none
D (7381) wifi:connect_bss: auth=1, reconnect=0
I (7385) wifi:state: init -> auth (b0)
D (7389) wifi:start 1s AUTH timer
D (7392) wifi:clear scan ap list
D (7395) event: running post WIFI_EVENT:41 with handler 0x42011e50 and context 0x3fcbc40c on loop 0x3fcb5b14
I (7404) app_got_event: WIFI_EVENT_HOME_CHANNEL_CHANGE: old_chan=1/old_snd=0, new_chan=10/new_snd=2
D (7405) wifi:recv auth: seq=2, status=0
I (7417) wifi:state: auth -> assoc (0)
D (7421) wifi:restart connect 1s timer for assoc
D (7436) wifi:recv assoc: type=0x10
D (7437) wifi:filter: set rx policy=6
I (7437) wifi:state: assoc -> run (10)
D (7437) wifi:start 10s connect timer for 4 way handshake
I (7464) wifi:connected with IGS-MESH, aid = 5, channel 10, 40D, bssid = d8:47:32:7c:37:ae
I (7465) wifi:security: WPA2-PSK, phy: bgn, rssi: -57
D (7466) wifi:remove all except d8:47:32:7c:37:ae from rc list
D (7472) wifi:clear blacklist
D (7474) wifi:filter: set rx policy=7
I (7478) wifi:pm start, type: 1

I (7481) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (7489) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
D (7497) wifi:Send sta connected event
D (7500) wifi:connect status 1 -> 5
D (7504) wifi:obss scan is disabled
D (7507) wifi:start obss scan: obss scan is stopped
I (7512) wifi:AP's beacon interval = 102400 us, DTIM period = 1
D (7518) event: running post WIFI_EVENT:4 with handler 0x42055fc0 and context 0x3fcbc1e8 on loop 0x3fcb5b14
0x42055fc0: wifi_default_action_sta_connected at /home/axel/esp/esp-idf/components/esp_wifi/src/wifi_default.c:85

D (7527) esp_netif_handlers: esp_netif action connected with netif0x3fcbc2dc from event_id=4
D (7535) esp_netif_lwip: check: remote, if=0x3fcbc2dc fn=0x4203e434
0x4203e434: esp_netif_up_api at /home/axel/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1647

D (7542) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fcbc2dc
D (7548) esp_netif_lwip: check: local, if=0x3fcbc2dc fn=0x4203ed44
0x4203ed44: esp_netif_update_default_netif_lwip at /home/axel/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (7554) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcbc2dc
D (7561) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (7566) esp_netif_lwip: check: remote, if=0x3fcbc2dc fn=0x4203e854
0x4203e854: esp_netif_dhcpc_start_api at /home/axel/esp/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1439

D (7573) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fcbc2dc
D (7579) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcbc2dc
D (7586) esp_netif_lwip: if0x3fcbc2dc start ip lost tmr: interval=120
D (7593) esp_netif_lwip: starting dhcp client
D (7598) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (7598) wifi:eb is dhcp or dns sport = 68, dport = 67
D (7608) event: running post WIFI_EVENT:4 with handler 0x42011e50 and context 0x3fcbc40c on loop 0x3fcb5b14
I (7629) wifi:<ba-add>idx:0 (ifx:0, d8:47:32:7c:37:ae), tid:6, ssn:2, winSize:64
D (7633) wifi:eb is dhcp or dns sport = 68, dport = 67
D (8598) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcbc360
D (8599) esp_netif_lwip: if0x3fcbc2dc ip changed=1
D (8599) event: running post IP_EVENT:0 with handler 0x42056018 and context 0x3fcbc2bc on loop 0x3fcb5b14
0x42056018: wifi_default_action_sta_got_ip at /home/axel/esp/esp-idf/components/esp_wifi/src/wifi_default.c:127

D (8609) wifi_init_default: Got IP wifi default handler entered
D (8615) esp_netif_handlers: esp_netif action got_ip with netif0x3fcbc2dc from event_id=0
I (8623) esp_netif_handlers: sta ip: 192.168.1.135, mask: 255.255.255.0, gw: 192.168.1.1

More Information.

No response

[AxelLin]

D (5664) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
D (5681) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:1a:26
D (5682) wifi:profile match: ss_state=0x7
D (5701) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:14:77
D (5702) wifi:profile match: ss_state=0x7
D (5706) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:1a:26
D (5708) wifi:profile match: ss_state=0x7
D (5756) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=d8:47:32:7c:37:ae
D (5756) wifi:profile match: ss_state=0x7
D (5764) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=ac:84:c6:32:14:77
D (5764) wifi:profile match: ss_state=0x7
D (5785) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (5786) wifi:perform scan: ss_state=0xd, chan<11,0>, dur<0,120>
D (5907) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (5907) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
D (6268) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6268) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
D (6629) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6629) wifi:perform scan: ss_state=0xd, chan<14,0>, dur<360,360>
D (6990) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (6990) wifi:filter: set rx policy=4
D (6991) wifi:first chan=1
D (6991) wifi:handoff_cb: status=0
D (6993) wifi:ap found, mac=d8:47:32:7c:37:ae
D (7362) wifi:going for connection with bssid=d8:47:32:7c:37:ae

Above wifi log only shows the AP's mac, but does not show the AP's rssi.
It would be hlepful for debug if also print the AP's rssi. (Then you can verify this issue)

[cy18]

I tried IDF 5.3.2 and IDF 5.4.0rc, the issue still exists.