WiFi connection delay on CB3S module (BK7231N)

[shadow578]

when using the CB3S module (which utilizes the BK7231N) with ESPHome firmware, the WiFi connection process takes a very long time.
the module seems to fail to connect multiple times before finally establishing a connection.
the issue occurs both after a cold boot as well as after a OTA update.

except from esphome config:

bk72xx:
  board: cb3s
  framework: 
    loglevel: DEBUG
    debug:
      - WIFI
    sdk_silent: auto

wifi:
  fast_connect: true
  ssid: !secret wifi_ssid
  password: !secret wifi_password
  ap:
    ssid: "${device_name} Fallback"
captive_portal:

Logs

note: some sensitive information has been redacted for privacy reasons.

Click to expand

V:BK7231N_1.0.1
REG:cpsr     spsr     r13      r14
SVC:000000D3          00401C1C 000033AC
IRQ:000000d2 00000010 00401e0c 00803600
FIR:000000d1 00000010 00401ffc 16c01822
SYS:000000df          0040192c 00000158
ST:00000000
J 0x10000

[...]

[C][wifi:048]: Setting up WiFi...
[C][wifi:061]: Starting WiFi...
[C][wifi:062]:   Local MAC: XX:XX:XX:XX:XX:XX
D [      0.074] WIFI: Mode changing NULL -> STA
D [      0.078] WIFI: Initializing func&app
D [      0.412] WIFI: Init OK
D [      0.412] WIFI: Wakeup RF
D [      0.412] WIFI: Enabling STA
D [      0.420] WIFI: BK event 130
D [      0.430] WIFI: WiFi sleep mode 0
[D][wifi:760]: Loaded saved fast_connect wifi settings
[I][wifi:313]: WiFi Connecting to 'XXX'...
D [      0.434] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
D [      0.442] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
I [      0.450] WIFI: Connecting to XX:XX:XX:XX:XX:XX 
D [      0.456] WIFI: Data = (nil)
D [      0.460] WIFI: Using DHCP
D [      0.464] WIFI: Starting WiFi...
D [      0.492] WIFI: Start OK
wpa_supplicant_scan
wpa_drv_scan
wpa_send_scan_req
no ht in scan
scan_start_req_handler
wpa_driver_scan_start_cb
scan_cancel_req_handler
scan_send_cancel_cfm
wpa_driver_scan_cb
Scan completed in 0.100000 seconds
wpa_get_scan_rst:2
cipher2security 2 2 16 16
PSKC: end
cipher2security 2 2 16 16
wpa_supplicant_connect
Cancelling scan request
wpa_driver_associate
D [      4.630] WIFI: BK event 1
found scan rst rssi -42 > -50 0
sm_auth_send:1
sm_disassoc_handler
sm_disassoc_handler reason=8,vif=0
SM_DISCONNECTING status=1
sm_disassoc_handler
sm_disassoc_handler reason=8,vif=0
---------SM_CONNECT_IND_fail
D [      4.648] WIFI: BK event 6
[W][wifi_lt:296][wifievent]: Event: Disconnected ssid='' bssid=00:00:00:00:00:00 reason='Association Leave'
[W][wifi:674]: WiFi Unknown connection status 0
[I][wifi:313]: WiFi Connecting to 'XXX'...
D [      4.680] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
D [      4.682] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
I [      4.690] WIFI: Connecting to XX:XX:XX:XX:XX:XX 
D [      4.696] WIFI: Data = (nil)
D [      4.700] WIFI: Using DHCP
D [      4.704] WIFI: Starting WiFi...
D [      4.710] WIFI: BK event 6
[W][wifi_lt:296][wifievent]: Event: Disconnected ssid='' bssid=00:00:00:00:00:00 reason='Association Leave'
D [      4.726] WIFI: Start OK
Cancelling scan request
[W][wifi:674]: WiFi Unknown connection status 0
wpa_driver_associate
D [   found scan rst rssi -42 > -50 0
sm_auth_send:1
   4.738] WIFI: BK event 1
sm_auth_handler
ht in assoc req
sm_assoc_rsp_handler
rc_init: station_id=1 format_mod=2 pre_type=0 short_gi=1 max_bw=0
rc_init: nss_max=0 mcs_max=7 r_idx_min=0 r_idx_max=3 no_samples=10
mm_set_vif_state_req_handler
chan_bcn_detect_start
---------SM_CONNECT_IND_ok
Not associated - Delay processing of received EAPOL frame (state=ASSOCIATING bssid=00:00:00:00:00:00 )
Cancelling scan request
WPA: TK 6ea1d1da3e40885b00419f03c2c39161
new ie: 0 : 4e 69 65 6e 68 61 75 73 
new ie: 1 : 82 84 8b 96 8c 12 98 24 
new ie: 3 : 1 
new ie: 2d : ef 11 1b ff ff ff 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 
new ie: 30 : 1 0 0 f ac 4 1 0 0 f ac 4 2 0 0 f ac 2 0 f ac 8 80 0 
hapd_intf_add_key CCMP
add sta_mgmt_get_sta
sta:1, vif:0, key:0
sta_mgmt_add_key
add hw key idx:25
WPA: GTK 2a5b2886034cd18188a6bb5d5534c032
hapd_intf_add_key CCMP
add is_broadcast_ether_addr
sta:255, vif:0, key:2
add hw key idx:2
ctrl_port_hdl:1
me_set_ps_disable:869 0 0 0 0 1
dis set ps 1!!
D [     WLAN_EVENT_CONNECTED
sta 4.838] WIFI: BK ev_ip_start
configurinent 8
g interface mlan (with DHCP client)
[I][wifi:313]: WiFi Connecting to 'XXX'...
D [      9.748] WIFI: Disconnecting from XXX (wifiOff=0)
bk_wlan_connection_loss vif:0
sta_ip_down
mm_connection_loss_ind_handler
sm_disconnect_process reason=40
me_set_ps_disable:869 0 0 1 0 8
me_set_ps_disable_req_handler 8!!
mm_set_vif_state_req_handler
mm_set_vif_state pass
SM_DISCONNECT_IND
mI [      9.770] hdr_disconnect_ind reasWIFI: Connecting toon_code=40
deassoc_evt_ XXX
D [  cb
    9.778] WIFI: Data = 0x65694e01
D [      9.782] WIFI: Using DHCP
D [      9.786] WIFI: Starting WiFi...
D [      9.792] WIFI: BK event 2
[W][wifi_lt:296][wifievent]: Event: Disconnected ssid='' bssid=00:00:00:00:00:00 reason='Beacon Timeout'
D [      9.808] WIFI: Disconnecting from  (wifiOff=0)
D [      9.814] WIFI: Start OK
wpa_sup[W][wifi:653]: Error while connecting to network.
plicant_scan
wpa_drv_scan
wpa_send_scan_req
no ht in scan
scan_start_req_handler
wpa_driver_sca[D][wifi:697]: Retrying with hidden networks...
n_start_cb[I][wifi:313]: WiFi Connecting to 'XXX'...
D [      9.842] WIFIscan_cancel_req_handler
: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
D [      9.852] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
I [      9.862] WIFI: Connecting to XX:XX:XX:XX:XX:XX 
D [      9.866] WIFI: Data = 0x65694e01
D [      9.872] WIFI: Using DHCP
D [      9.876] WIFI: Starting WiFi...

D [      9.882] WIFI: Start OK
wpa_supplicant_[W][wifi:669]: Connecting to WiFi network failed. Are the credentials wrong?
scan
wpa_supplicant_req_scan
Setting scan request: 1.000000 sec
scan_send_cancel_cfm
wpa_driver_scan_cb
Scan completed in 0.052000 seconds
wpa_get_scan_rst:2
cipher2security 2 2 16 16
cipher2security 2 2 16 16
wpa_supplicant_connect
Cancelling scan request
wpa_driver_associate
D [     found scan rst rssi -40 > -50 0
sm_auth_send:1
sm_disassoc_handler
sm_disassoc_handler reason=8,vif=0
SM_DISCONNECTING status=1
sm_disassoc_handler
sm_disassoc_handler reason=8,vif=0
---------SM_CONNECT_IND_fail
 9.940] WIFI: BK event 1
D [      9.972] WIFI: BK event 6
[W][wifi_lt:296][wifievent]: Event: Disconnected ssid='' bssid=00:00:00:00:00:00 reason='Association Leave'

[I][wifi:313]: WiFi Connecting to 'XXX'...
D [     14.904] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
D [     14.906] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
I [     14.914] WIFI: Connecting to XXX
D [     14.918] WIFI: Data = 0x65694e01
D [     14.924] WIFI: Using DHCP
D [     14.928] WIFI: Starting WiFi...
D [     14.932] WIFI: BK event 6
[W][wifi_lt:296][wifievent]: Event: Disconnected ssid='' bssid=00:00:00:00:00:00 reason='Association Leave'
D [     14.948] WIFI: Start OK
wpa_supplicant_sc[W][wifi:674]: WiFi Unknown connection status 0
an
wpa_drv_scan
wpa_send_scan_req
no ht in scan
scan_start_req_handler
wpa_driver_scan_start_cb
[D][wifi:697]: Retrying with hidden networks...
[I][wifi:313]: WiFi Connecting to 'XXX'...
D [     14.978] WIFI: Disconnecscan_cancel_req_handler
ting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
D [     14.988] WIFI: Disconnecting from  (wifiOff=0)
bk_wlan_connection_loss vif:0
I [     14.996] WIFI: Connecting to XX:XX:XX:XX:XX:XX
D [     15.002] WIFI: Data = 0x65694e01
D [     15.006] WIFI: Using DHCP
D [     15.010] WIFI: Starting WiFi...
D [     15.018] WIFI: Start OK
wpa_supplicant_scan
wpa_supplicant_req_scan
Setting scan request: 1.000000 sec
scan_send_cancel_cfm
wpa_driver_scan_cb
Scan completed in 0.102000 seconds
wpa_get_scan_rst:2
cipher2security 2 2 16 16
cipher2security 2 2 16 16
wpa_supplicant_connect
Cancelling scan request
wpa_driver_associate
found scan rst rssi -41 > -50 0
sm_auth_send:1
D [     15.076] WIFI: BK event 1
sm_auth_handler
ht in assoc req
sm_assoc_rsp_handler
rc_init: station_id=1 format_mod=2 pre_type=0 short_gi=1 max_bw=0
rc_init: nss_max=0 mcs_max=7 r_idx_min=0 r_idx_max=3 no_samples=10
mm_set_vif_state_req_handler
chan_bcn_detect_start
---------SM_CONNECT_IND_ok
Not associated - Delay processing of received EAPOL frame (state=ASSOCIATING bssid=00:00:00:00:00:00 )
Cancelling scan request
WPA: TK a30b92505cf42faa97b8809ede382b83

old ie: 0 : 4e 69 65 6e 68 61 75 73 
new ie: 0 : 4e 69 65 6e 68 61 75 73 
old ie: 1 : 82 84 8b 96 8c 12 98 24 
new ie: 1 : 82 84 8b 96 8c 12 98 24 
old ie: 3 : 1 
new ie: 3 : 1 
old ie: 2d : ef 11 1b ff ff ff 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 
new ie: 2d : ef 11 1b ff ff ff 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0 0 
old ie: 30 : 1 0 0 f ac 4 1 0 0 f ac 4 2 0 0 f ac 2 0 f ac 8 80 0 
new ie: 30 : 1 0 0 f ac 4 1 0 0 f ac 4 2 0 0 f ac 2 0 f ac 8 80 0 

hapd_intf_add_key CCMP
add sta_mgmt_get_sta
sta:1, vif:0, key:0
sta_mgmt_add_key
add hw key idx:25
WPA: GTK 2a5b2886034cd18188a6bb5d5534c032
hapd_intf_add_key CCMP
add is_broadcast_ether_addr
sta:255, vif:0, key:2
add hw key idx:2
ctrl_port_hdl:1
me_set_ps_disable:869 0 0 0 0 1
dis set ps 1!!
D WLAN_EVENT_CONNECTED
st[     15.200] WIFI:a_ip_start
configuri BK event 8
ng interface mlan (with DHCP client)
ip_addr: 827ba8c0
D [     22.806] WIFI: BK event 9
[I][wifi:617]: WiFi Connected!
[C][wifi:428]:   Local MAC: XX:XX:XX:XX:XX:XX
[C][wifi:433]:   SSID: 'XXX'
[C][wifi:436]:   IP Address: XXX
[C][wifi:439]:   BSSID: XX:XX:XX:XX:XX:XX
[C][wifi:441]:   Hostname: 'motion-sensor'
[C][wifi:443]:   Signal strength: -44 dB 
[C][wifi:447]:   Channel: 1
[C][wifi:448]:   Subnet: 255.255.255.0
[C][wifi:449]:   Gateway: XXX
[C][wifi:450]:   DNS1: XXX
[C][wifi:451]:   DNS2: XXX
[D][wifi:626]: Disabling AP...