esp-idf: WPA2: Incorrect initialisation behind slow WiFi connection times? (IDFGH-1520)
Slow WPA2 connection times have long been an issue for many ESP32 users. I think I may have a small clue as to where to look for the problem, and a bandaid to fix it for now. Today I was able to reduce connection time on my home WPA2 network from the usual ~1100ms down to ~350ms (240MHz, CONFIG_LWIP_DHCP_DOES_ARP_CHECK=0). Those times are using Arduino’s millis(), the debug output below might have more meaningful timestamps. All it took was this seemingly redundant fix:
wifi_config_t conf;
esp_wifi_get_config(WIFI_IF_STA, &conf);
esp_wifi_set_config(WIFI_IF_STA, &conf);
Often I get this additional debug output (the indicated line): Without fix:
I (722) wifi: n:11 0, o:1 0, ap:255 255, sta:11 0, prof:1
D (1472) nvs: nvs_set_blob sta.apinfo 700[1B][0m <-------
I (1522) wifi: state: init -> auth (b0)
I (1532) wifi: state: auth -> assoc (0)
I (1542) wifi: state: assoc -> run (10)
I (1582) wifi: connected with MYSSID, channel 11
D (1582) nvs: nvs_set sta.chan 1 11[1B][0m
D (1582) nvs: nvs_set_blob sta.apinfo 700[1B][0m
I (1592) wifi: pm start, type: 1
D (1592) event: SYSTEM_EVENT_STA_CONNECTED
With fix, for comparison:
I (722) wifi: n:11 0, o:1 0, ap:255 255, sta:11 0, prof:1
I (722) wifi: state: init -> auth (b0)
I (732) wifi: state: auth -> assoc (0)
I (732) wifi: state: assoc -> run (10)
I (782) wifi: connected with MYSSID, channel 11
D (782) nvs: nvs_set sta.chan 1 11[1B][0m
D (782) nvs: nvs_set_blob sta.apinfo 700[1B][0m
I (792) wifi: pm start, type: 1
D (792) event: SYSTEM_EVENT_STA_CONNECTED
That additional “nvs_set_blob sta.apinfo” doesn’t seem to occur every time though, so maybe a red herring. The ~750ms mysterious delay unfortunately does.
In fact, I realised just now that I see this delay and ‘apinfo’ output when no NVS data exists for the current WiFi config. Indeed, if I erase the NVS partition, I’m sure to see this exact behaviour next boot, every time. Maybe WPA2 cryptographic data isn’t being loaded properly on WiFi init so it goes through the whole process with the AP every time?
Whatever it is, this fixes it:
esp_wifi_set_config(WIFI_IF_STA, &conf);
Tested with esp-idf (PlatformIO) , esp-idf+Arduino component (PlatformIO), Arduino (Arduino IDE and PlatformIO). IDF Test code:
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_system.h"
#include "esp_wifi.h"
#include "esp_event_loop.h"
#include "esp_log.h"
#include "nvs_flash.h"
#include "lwip/err.h"
#include "lwip/sys.h"
/**************************************** */
#define WIFI_SSID "MYSSID"
#define WIFI_PASSWORD "MYPASSWORD"
//Comment/Uncomment to toggle fix
#define APPLY_FIX
//Suggest CONFIG_LWIP_DHCP_DOES_ARP_CHECK=0
/**************************************** */
static const char *TAG = "WPA2_FIX";
static esp_err_t event_handler(void *ctx, system_event_t *event)
{
switch(event->event_id) {
case SYSTEM_EVENT_STA_START:
esp_wifi_connect();
break;
case SYSTEM_EVENT_STA_GOT_IP:
ESP_LOGI(TAG, "WiFi Connected. IP: %s", ip4addr_ntoa(&event->event_info.got_ip.ip_info.ip));
break;
case SYSTEM_EVENT_STA_DISCONNECTED:
ESP_LOGI(TAG, "Connection failed");
break;
default:
break;
}
return ESP_OK;
}
void app_main()
{
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);
tcpip_adapter_init();
ESP_ERROR_CHECK(esp_event_loop_init(event_handler, NULL) );
wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
ESP_ERROR_CHECK(esp_wifi_init(&cfg));
ESP_ERROR_CHECK(esp_wifi_set_mode(WIFI_MODE_STA) );
wifi_config_t wifi_config;
ESP_ERROR_CHECK(esp_wifi_get_config(ESP_IF_WIFI_STA, &wifi_config) );
if(strcmp(WIFI_SSID,(char*)wifi_config.sta.ssid) || strcmp(WIFI_PASSWORD,(char*)wifi_config.sta.password)) {
ESP_LOGI(TAG, "Setting new WiFi credentials");
wifi_config_t new_config = {
.sta = {
.ssid = WIFI_SSID,
.password = WIFI_PASSWORD,
},
};
ESP_ERROR_CHECK(esp_wifi_set_config(ESP_IF_WIFI_STA, &new_config) );
}
#ifdef APPLY_FIX
else {
ESP_LOGI(TAG, "Testing fix");
ESP_ERROR_CHECK(esp_wifi_set_config(ESP_IF_WIFI_STA, &wifi_config) );
}
#endif
ESP_ERROR_CHECK(esp_wifi_start() );
ESP_LOGI(TAG, "Connecting...");
vTaskDelete(NULL);
}
About this issue
- Original URL
- State: closed
- Created 5 years ago
- Comments: 21 (21 by maintainers)
@negativekelvin Definitely. We have marked this as an action item to be done.
After debugging, it was found that @adb820 commit mentioned by @negativekelvin, esp_wifi_set_config makes wifi library code to check if ap_info stored in NVS already has a valid PMK generated from previous connection. This is not the case, if you directly connect. As a result, PMK is always generated if you do wifi_init/start/connect sequence. PMK generation takes a lot of time. The corresponding latest code is here https://github.com/espressif/esp-idf/blob/master/components/wpa_supplicant/src/crypto/sha1-pbkdf2.c#L81-L101 @adb820 The above code was in the wifi library. With c139683 a lot of wpa_supplicant is moved out and initialisation flow has also changed. There is also a bug related to PMK not stored properly which is getting fixed and is in the process of getting merged (Refer to this issue for more details). In both the cases, root cause for the delay seems to be same. We will try to get this fixed in both new as well as old version soon. Thanks!
Able to reproduce here also
Is the delay due to the nvs write itself? Why is the wifi driver saving the apinfo when nothing has changed? It thinks apinfo has changed but when you esp_wifi_set_config it to the same value it correctly identifies that it hasn’t changed and doesn’t do a nvs write?