esp-idf: Since latest esp-idf we cannot connect to wifi sta anymore, unless log output is enabled (IDFGH-9787)

I had to do another esp-idf rebase for our firmware repo and since then, connecting to STA networks stopped working. My wifi logic first scans for wifis, and then checks which found ssids are contained in our 10 wifi config slots. It then tries to connect to the strongest (configured) wifi with password. This stopped working only for release builds without log output, but works still totally fine with log output enabled. The error I get from the esp wifi blob is NO_AP_FOUND. I have introduced a few log statements that are still visible even with log output disabled (the errors with WIFI_STACK tag). I have no clue how to debug this any further:

W (2288) wifi: [pp.c,3513] wifi driver task: 3ffd0a70, prio:23, stack:6656, core=0
W (2288) wifi: [ieee80211_ioctl.c,2248] wifi firmware version: 9a04d3b
W (2288) wifi: [ieee80211_ioctl.c,2249] wifi certification version: v7.0
W (2288) wifi: [ieee80211_ioctl.c,2250] config NVS flash: disabled
W (2298) wifi: [ieee80211_ioctl.c,2251] config nano formating: disabled
W (2308) wifi: [esf_buf.c,423] Init data frame dynamic rx buffer num: 8
W (2308) wifi: [esf_buf.c,430] Init management frame dynamic rx buffer num: 8
W (2318) wifi: [esf_buf.c,437] Init management short buffer num: 32
W (2328) wifi: [esf_buf.c,455] Init dynamic tx buffer num: 8
W (2328) wifi: [wdev.c,2386] Init static rx buffer size: 1600
W (2338) wifi: [wdev.c,2393] Init static rx buffer num: 4
W (2338) wifi: [wdev.c,2394] Init dynamic rx buffer num: 8
E (2348) phy_init phy_init.c:517 esp_phy_get_init_data(): failed to validate PHY data partition, restoring default data into flash...
W (2458) wifi: [hal_mac.c,606] WDEVBBRXHUNG:0xc00000f0, en:1, timer:240(3840 us)
W (2458) wifi: [hal_mac.c,608] WDEVBBTXHUNG:0x800000f0, en:1, timer:240(3840 us)
W (2468) wifi: [hal_mac.c,610] WDEVBBCCAHUNG:0x800000f0, en:1, timer:240(3840 us)
W (2468) wifi: [hal_mac.c,615] WDEVHUNGRECOVER:0xffff0fff, rxHungRecover[en:1, timer:32767 cycles(409 us)], txHungRecover[en:0, timer:4095 cycles(51 us)]
W (2488) wifi: [ieee80211.c,553] mode : sta (e8:31:cd:69:2a:8c) + softAP (e8:31:cd:69:2a:8d)
W (2498) wifi: [ieee80211_sta.c,3076] enable tsf
W (2498) wifi: [ieee80211_power.c,111] Total power save buffer number: 4
W (2508) wifi: [ieee80211_ets.c,89] Init max length of beacon: 752/752
W (2508) wifi: [ieee80211_ets.c,89] Init max length of beacon: 752/752
E (2518) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=2
E (2528) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=12
W (3388) wifi: [ieee80211_ioctl.c,1738] Cannot set pmf to required when in wpa-wpa2 mixed mode! Setting pmf to optional mode.
W (3398) wifi: [ieee80211_power.c,111] Total power save buffer number: 4
E (3398) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=13
E (3408) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=12
E (3708) esp_ota_ops esp_ota_ops.c:541 esp_ota_get_boot_partition(): ota data invalid, no current app. Assuming factory
E (3708) esp_image esp_image_format.c:328 verify_image_header(): image at 0x4a0000 has invalid magic byte (nothing flashed here?)
W (3768) wifi: [pm.c,3526] Set ps type: 0

E (10078) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=1
E (10108) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=78:e3:6d:f1:44:79 ssid=Wattpilot_999920 primary=13 rssi=-18
E (10108) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=e8:31:cd:65:90:b9 ssid=go-e-210234 primary=1 rssi=-29
E (10128) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=c0:49:ef:36:be:79 ssid=Wattpilot_999919 primary=13 rssi=-30
E (10138) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=1c:9d:c2:52:08:ad ssid=go-echarger_999900 primary=13 rssi=-32
E (10148) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=7e:45:58:f2:48:06 ssid=goe-funkfeuer primary=13 rssi=-33
E (10168) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=82:45:58:f2:48:06 ssid=Funkfeuer Free WiFi primary=13 rssi=-33
E (10178) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=78:45:58:f2:48:06 ssid=goe-iot primary=13 rssi=-35
E (10188) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=c4:e9:84:f3:1c:32 ssid=ArschWlan primary=11 rssi=-37
E (10198) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=18:d6:c7:fc:f1:fb ssid=Channel13 primary=13 rssi=-41
E (10218) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=40:f5:20:5b:76:95 ssid=bobby_mick primary=1 rssi=-44
E (10228) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=52:81:40:d8:c9:c4 ssid=DIRECT-C4-HP Laser 179fnw primary=13 rssi=-54
E (10238) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=98:fc:84:10:02:25 ssid=go-econtroller_900137 primary=13 rssi=-57
E (10258) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=40:f5:20:56:c4:01 ssid=go-e-053644 primary=6 rssi=-59
E (10268) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=26:5a:4c:13:ee:14 ssid=goe-funkfeuer primary=6 rssi=-61
E (10278) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=44:17:93:dd:3a:49 ssid=go-econtroller_000021 primary=1 rssi=-61
E (10288) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=24:5a:4c:63:ee:14 ssid=goe-iot primary=6 rssi=-62
E (10308) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=26:5a:4c:23:ee:14 ssid=Funkfeuer Free WiFi primary=6 rssi=-62
E (10318) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=a8:03:2a:f3:0f:c9 ssid=go-echarger_00000003 primary=13 rssi=-64
E (10328) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=58:bf:25:28:69:81 ssid=go-econtroller-lite_000027 primary=13 rssi=-65
E (10348) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=98:fc:84:10:00:d9 ssid=go-econtroller_000054 primary=13 rssi=-67
E (10358) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=10:97:bd:cd:07:29 ssid=bobby_relay_cd0728 primary=1 rssi=-70
E (10368) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=d6:3b:f3:a1:80:3c ssid=thtgast primary=11 rssi=-70
E (10388) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=d4:3d:f3:a1:80:3b ssid=wl primary=11 rssi=-71
E (10398) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=0c:7b:c8:dd:0f:aa ssid=AT-WLAN primary=6 rssi=-72
E (10408) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=68:d7:9a:45:bc:be ssid=goe-iot primary=1 rssi=-73
E (10418) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=6a:d7:9a:25:bc:be ssid=Funkfeuer Free WiFi primary=1 rssi=-73
E (10428) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=6a:d7:9a:15:bc:be ssid=goe-funkfeuer primary=1 rssi=-73
E (10448) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=40:5f:7d:6d:4b:c2 ssid=HH71VM_4BC2_2.4G primary=6 rssi=-80
E (10458) WIFI_STACK espwifistack.cpp:1406 wifi_scan_done(): scan result bssid=e0:63:da:ba:ab:68 ssid=Ladenstein / ROLF BENZ Haus primary=6 rssi=-89
E (10478) WIFI_STACK espwifistack.cpp:2793 nextConnectPlanItem(): connecting to Channel13 (auth=WPA3_PSK, key=XXXXXXXX, channel=13, rssi=-41, bssid=18:D6:C7:FC:F1:FB)
E (17148) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=5
E (17148) WIFI_STACK espwifistack.cpp:1680 wifi_event_cb(): STA Disconnected: SSID: Channel13, BSSID: 00:00:00:00:00:00, Reason: 201
E (23878) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=5
E (23878) WIFI_STACK espwifistack.cpp:1680 wifi_event_cb(): STA Disconnected: SSID: Channel13, BSSID: 00:00:00:00:00:00, Reason: 201
E (30598) WIFI_STACK espwifistack.cpp:1638 wifi_event_cb(): event_base=WIFI_EVENT event_id=5
E (30598) WIFI_STACK espwifistack.cpp:1680 wifi_event_cb(): STA Disconnected: SSID: Channel13, BSSID: 00:00:00:00:00:00, Reason: 201

How does the closed source wifi blob even know if I have log output enabled or not and behave differently. When we completely shutdown wifi and re-enable it again, connecting to wifi also works fine again without log.

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Comments: 16 (10 by maintainers)

Most upvoted comments

ugh wtf is going on

Screenshot 2023-09-14 at 9 48 25 PM

*wm:[2] [SYS] WM version: v2.0.15-rc.1 *wm:[2] [SYS] Arduino version: 2.0.10 *wm:[2] [SYS] ESP SDK version: 4.4.5.230614 *wm:[2] [SYS] Free heap: 180620 *wm:[2] [SYS] Chip ID: 2665141460 *wm:[2] [SYS] Chip Model: ESP32-PICO-D4 *wm:[2] [SYS] Chip Cores: 2