esp-idf: WPA-enterprise reauthentication is not working (IDFGH-7762)

Environment

Development Kit: ESP32-DevKitC
Kit version (for WroverKit/PicoKit/DevKitC): v4
Module or chip used: ESP32-WROOM-32D
IDF version v4.4.1
Build System: idf.py
Compiler version xtensa-esp32-elf esp-2021r2-patch3-8.4.0
Operating System: Windows
Using an IDE?: VS Code 1.68.1
Power Supply: USB

WPA enterprise authenticates reliably but never reauthenticates

We can authenticate through phase 1 and 2 and the 4 way handshake, but the reauth gets through to the very last handshake and fails. We’ve collected debug logs from the esp32 and logs from the router. We’ve tried a variety of versions, code, and hardware, including the enterprise example code. This example is for simple test code based on the example code.

Expected behavior: Reauthentication completes

Actual behavior: The fourth and last handshake, the response to the third handshake, is never sent.

Steps to reproduce:

Configure an esp32 with code to connect to an enterprise network
Configure the network to reauthenticate periodically
Allow it to connect and authenticate, and wait for the reauth.
Observe sending 3/4 msg of 4-Way Handshake from the router and corresponding entries from esp-idf, near the line wifi:recv deauth, reason=0x2

We are using a Netgear WAX620 router and freeRADIUS 3.0.25 running on linux mint.

Code to reproduce this issue


//After this is called there is just an infinite loop along with a simple event handler function. If needed,
//I will share that too.

bool WIFI_Connect(void)
{
    esp_err_t err;

    printf("WIFI_Connect: connecting\n");

    err = esp_netif_init();

    if(err){
        printf("WIFI_Connect, esp_netif_init error %X\n", err);
        return false;
    }

    //Wifi_event_group = xEventGroupCreate();
    err = esp_event_loop_create_default();
    if(err){
        printf("WIFI_Connect, esp_event_loop_create_default error %X\n", err);
        return false;
    }

    Sta_netif = esp_netif_create_default_wifi_sta();
    if(Sta_netif == NULL){
        printf("WIFI_Connect, esp_netif_create_default_wifi_sta error\n");
        return false;
    }

    esp_netif_dhcps_stop(Sta_netif);

    esp_netif_ip_info_t info_t;
    memset(&info_t, 0, sizeof(esp_netif_ip_info_t));
    info_t.ip.addr = esp_ip4addr_aton((const char *)STATIC_IP_ADDR);
    info_t.gw.addr = esp_ip4addr_aton((const char *)GATEWAY);
    info_t.netmask.addr = esp_ip4addr_aton((const char *)NETMASK);
    esp_netif_set_ip_info(Sta_netif, &info_t);

    wifi_init_config_t cfg = WIFI_INIT_CONFIG_DEFAULT();
    err = esp_wifi_init(&cfg);
    if(err){
        printf("WIFI_Connect, esp_wifi_init error %X\n", err);
        return false;
    }

    err = esp_event_handler_instance_register(WIFI_EVENT, ESP_EVENT_ANY_ID, &_event_cb, NULL, NULL);
    if(err){
        printf("WIFI_Connect, esp_event_handler_instance_register error %X\n", err);
        return false;
    }

    err = esp_event_handler_instance_register(IP_EVENT, ESP_EVENT_ANY_ID, &_event_cb, NULL, NULL);
    if(err){
        printf("WIFI_Connect, esp_event_handler_instance_register error %X\n", err);
        return false;
    }

    err = esp_wifi_set_storage(WIFI_STORAGE_RAM);

    if(err){
        printf("WIFI_Connect, esp_wifi_set_storage error %X\n", err);
        return false;
    }


    wifi_config_t wifi_configure = {0};
    strcpy((char *)wifi_configure.sta.ssid, SSID);
    strcpy((char *)wifi_configure.sta.password, PASSWORD); 

    wifi_configure.sta.channel = 0;
    wifi_configure.sta.listen_interval = 0;
    wifi_configure.sta.scan_method = WIFI_ALL_CHANNEL_SCAN; //WIFI_ALL_CHANNEL_SCAN or WIFI_FAST_SCAN
    wifi_configure.sta.sort_method = WIFI_CONNECT_AP_BY_SIGNAL; //WIFI_CONNECT_AP_BY_SIGNAL or WIFI_CONNECT_AP_BY_SECURITY
    wifi_configure.sta.threshold.rssi = -127;
    wifi_configure.sta.pmf_cfg.capable = true;
    wifi_configure.sta.pmf_cfg.required = false;
    wifi_configure.sta.bssid_set = 0;
    memset(wifi_configure.sta.bssid, 0, 6);

    wifi_configure.sta.threshold.authmode = WIFI_AUTH_WPA2_ENTERPRISE;

    err = esp_wifi_set_mode(WIFI_MODE_STA);
    if(err){
        printf("WIFI_Connect, esp_wifi_set_mode error %X\n", err);
        return false;
    }

    err = esp_wifi_set_config(WIFI_IF_STA, &wifi_configure);
    if(err){
        printf("WIFI_Connect, esp_wifi_set_config error %X\n", err);
        return false;
    }
    
    err = esp_netif_set_hostname(Sta_netif, "somehostname");
    if(err){
        printf("WIFI_Connect, esp_netif_set_hostname error %X\n", err);
        return false;
    }

    err = esp_wifi_sta_wpa2_ent_set_identity((uint8_t *)IDENT, strlen(IDENT));
    if(err){
            printf("WIFI_Connect, esp_wifi_sta_wpa2_ent_set_identity %s, error %X\n", IDENT, err);
            return false;
    }

    err = esp_wifi_sta_wpa2_ent_set_username((uint8_t *)IDENT, strlen(IDENT));
    if(err){
            printf("WIFI_Connect, esp_wifi_sta_wpa2_ent_set_username %s, error %X\n", IDENT, err);
            return false;
    }

    err = esp_wifi_sta_wpa2_ent_set_password((uint8_t *)PASSWORD, strlen(PASSWORD));
    if(err){
            printf("WIFI_Connect, esp_wifi_sta_wpa2_ent_set_password error %X\n", err);
            return false;
    }

    err = esp_wifi_sta_wpa2_ent_enable();
    if(err){
            printf("WIFI_Connect, esp_wifi_sta_wpa2_ent_enable error %X\n", err);
            return false;
    }

    err = esp_wifi_start();
    if(err){
        printf("WIFI_Connect, esp_wifi_start error %X\n", err);
        return false;
    }   

    printf("WIFI_Connect: should connect now.\r\n");

    return true;
}

Debug Logs

Router:

Jun  1 09:46:48 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c IEEE 802.11: authenticated
Jun  1 09:46:48 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c IEEE 802.11: associated (aid 1)
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 1/4 msg of 4-Way Handshake
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: received EAPOL-Key frame (2/4 Pairwise)
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 3/4 msg of 4-Way Handshake
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: received EAPOL-Key frame (4/4 Pairwise)
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: pairwise key handshake completed (RSN)
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c IEEE 802.1X: authenticated - EAP type: 25 (PEAP)
Jun  1 09:46:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: Added PMKSA cache entry (IEEE 802.1X)
Jun  1 09:46:49 nddmp[5395]: alarm : seqNo-[22480], level-[INFO], info-[10-97-BD-D4-A1-8C wireless client connected]
Jun  1 09:46:49 nddmp[5395]: alarm : seqNo-[22481], level-[OTHER], info-[{"ip":"-","mac":"10-97-BD-D4-A1-8C","hname":"10-97-BD-D4-A1-8C","txR":"1 Mbps","rxR":"72.20 Mbps","ssid":"VMC-ENTERPRISE-1","dOs":"Unknown Device OS","dType":"Unknown Device Type","mode":"11NG","status":"Authenticated","bssid":"6C-CD-D6-5F-A9-C1","chnl":"6","chWidth":"20 MHz","rssi":"64","state":"QOS/ERP/HT","type":"wpa2","idle":"0","time":"00:00:00","txB":"350","rxB":"3632","pmf":"none","vlanID":"1","Username":"TBD5","radio":"0"}]
Jun  1 09:47:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:47:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:47:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:47:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:24 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:24 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:48:52 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 1/2 msg of Group Key Handshake
Jun  1 09:48:52 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: received EAPOL-Key frame (2/2 Group)
Jun  1 09:49:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:49:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:49:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:49:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:50:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:50:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:50:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:50:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:51:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:51:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:51:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:51:36 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:51:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c IEEE 802.1X: authenticated - EAP type: 25 (PEAP)
Jun  1 09:51:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: Added PMKSA cache entry (IEEE 802.1X)
Jun  1 09:51:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 1/4 msg of 4-Way Handshake
Jun  1 09:51:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: received EAPOL-Key frame (2/4 Pairwise)
Jun  1 09:51:49 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 3/4 msg of 4-Way Handshake
Jun  1 09:51:50 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 3/4 msg of 4-Way Handshake
Jun  1 09:51:51 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c WPA: sending 3/4 msg of 4-Way Handshake
Jun  1 09:51:52 hostapd: wifi0vap0: STA 10:97:bd:d4:a1:8c IEEE 802.11: disconnected
Jun  1 09:51:52 nddmp[5395]: alarm : seqNo-[22482], level-[INFO], info-[10-97-BD-D4-A1-8C wireless client could not obtain IP address]
Jun  1 09:51:52 nddmp[5395]: alarm : seqNo-[22483], level-[INFO], info-[10-97-BD-D4-A1-8C wireless client disconnected]
Jun  1 09:52:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1
Jun  1 09:52:06 configd[5330]: get_cur_channel: None of the interfaces are in UP state for wifi1


Serial Port:
(time zones don't match)

"6/1/2022 11:46:47 AM",D (8615) esp_netif_lwip: starting dhcp client[0m
"6/1/2022 11:46:47 AM",D (8625) esp_netif_lwip: call api in lwip: ret=0x0, give sem[0m
"6/1/2022 11:46:47 AM",D (8625) event: running post WIFI_EVENT:4 with handler 0x400d67f4 and context 0x3ffc4e74 on loop 0x3ffbcc54[0m
"6/1/2022 11:46:47 AM",[wifi] Event ................: STA_CONNECTED
"6/1/2022 11:48:50 AM",W (131655) wifi:<ba-add>idx:0 (ifx:0, 6c:cd:d6:5f:a9:c1), tid:6, ssn:15, winSize:64
"6/1/2022 11:48:50 AM",D (131665) wifi:obss scan is disabled
"6/1/2022 11:48:50 AM",D (131665) wifi:start obss scan: obss scan is stopped
"6/1/2022 11:51:47 AM",D (308825) wifi:obss scan is disabled
"6/1/2022 11:51:47 AM",D (308825) wifi:start obss scan: obss scan is stopped
"6/1/2022 11:51:50 AM",D (312085) wifi:recv deauth, reason=0x2
"6/1/2022 11:51:50 AM",I (312085) wifi:state: run -> init (2c0)
"6/1/2022 11:51:50 AM",D (312085) wifi:recv deauth/disassoc, stop beacon/connect timer
"6/1/2022 11:51:50 AM",D (312085) wifi:connect status 5 -> 4
"6/1/2022 11:51:50 AM",D (312095) wifi:sta leave
"6/1/2022 11:51:50 AM",I (312095) wifi:pm stop, total sleep time: 288383634 us / 303586331 us

"6/1/2022 11:51:50 AM",D (312095) wifi:stop CSA timer
"6/1/2022 11:51:50 AM",W (312105) wifi:<ba-del>idx
"6/1/2022 11:51:50 AM",D (312105) wifi:remove 6c:cd:d6:5f:a9:c1 from rc list
"6/1/2022 11:51:50 AM",I (312105) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
"6/1/2022 11:51:50 AM",D (312115) wifi:filter: set rx policy=8
"6/1/2022 11:51:50 AM",D (312115) wifi:Send disconnect event, reason=2, AP number=0
"6/1/2022 11:51:50 AM",D (312125) event: running post WIFI_EVENT:5 with handler 0x400e89d0 and context 0x3ffbde88 on loop 0x3ffbcc54[0m
"6/1/2022 11:51:50 AM",D (312135) esp_netif_handlers: esp_netif action disconnected with netif0x3ffbdb80 from event_id=5[0m
"6/1/2022 11:51:50 AM",D (312145) esp_netif_lwip: check: remote, if=0x3ffbdb80 fn=0x400dd494
"6/1/2022 11:51:50 AM",[0m
"6/1/2022 11:51:50 AM",D (312155) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffbdb80[0m
"6/1/2022 11:51:50 AM",D (312155) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffbdb80[0m
"6/1/2022 11:51:50 AM",D (312165) esp_netif_lwip: if0x3ffbdb80 start ip lost tmr: no need start because netif=0x3ffbdc00 interval=120 ip=0[0m
"6/1/2022 11:51:50 AM",D (312175) esp_netif_lwip: check: local, if=0x3ffbdb80 fn=0x400ddc6c
"6/1/2022 11:51:50 AM",[0m
"6/1/2022 11:51:50 AM",D (312185) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffbdb80[0m
"6/1/2022 11:51:50 AM",V (312185) esp_netif_objects: esp_netif_next_unsafe 0x0[0m
"6/1/2022 11:51:50 AM",V (312195) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffbdb80[0m
"6/1/2022 11:51:50 AM",V (312195) esp_netif_objects: esp_netif_next_unsafe 0x3ffbdb80[0m
"6/1/2022 11:51:50 AM",D (312205) esp_netif_lwip: call api in lwip: ret=0x0, give sem[0m
"6/1/2022 11:51:50 AM",D (312215) event: running post WIFI_EVENT:5 with handler 0x400d67f4 and context 0x3ffc4e74 on loop 0x3ffbcc54[0m
"6/1/2022 11:51:50 AM",[wifi] Event ................: STA_DISCONNECTED

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 38 (9 by maintainers)

Most upvoted comments

@kapilkedawat Thank you!

raysvmc on Nov 18, 2022

@raysvmc @AxelLin As seen in logs and sniffer capture AP sends EAPOL message 3 of 4 twice with different replay counters, we reply to the first one encrypting with older keys but AP expects 4 of 4 for the latest replay counter to which we reply encrypting using new keys. This situation cannot be handled at this moment, also you can observe the same behavior in upstream.

Shreyas0-7 on Nov 9, 2022

@Shreyas0-7 @AxelLin this last test seems to be working now, but I will share what we got on this one in case it’s of interest. We’ll have to see if this is repeatable. There are two tests, each of which reauths successfully with a few handshake resends. I summarized them in NotesFromSerialCapture.txt. Thanks! AuthIssue102722.zip

raysvmc on Oct 27, 2022

@AxelLin unfortunately not yet. There has been some kind of difficulty in making this work and I will see if I can help. Thanks for asking!

raysvmc on Oct 14, 2022

Hi, I am joining this conversation because I think we have the same problem (apologize if not; in that case, I will create a new post). One of our clients has a problem that all ESP32 devices gets disconnected precisely 3 hours after being connected to AP. AP is using WPA2-PSK authentication (different as used by @raysvmc). The disconnect reason is WIFI_REASON_AUTH_EXPIRE (2) or sometimes WIFI_REASON_NOT_AUTHED (6). After that, devices reconnect to AP and the same thing happens again after 180 minutes. We think that the AP requests some kind of re-authentication, but ESP fails to respond to it, so AP kicks him off. We are using esp-idf 4.4.3. We tried the patch from wpa2_reauth.zip, but sadly it did not help. We don’t have precise logs, but we are happy to help testing it.

se-k32 on Oct 2, 2022

Hey @raysvmc thanks for your patience and your co-ordination, can you please retry with this patch. wpa2_reauth.zip

Shreyas0-7 on Sep 28, 2022

Hey @raysvmc Can you please retry with this patch wpa_reauth.zip

Shreyas0-7 on Sep 22, 2022

Thank you @hpdhabe for looking into this. We’re trying to get set back up to make another test but it might take a week or so for various reasons I won’t bore you with. I have set WPA_DEBUG_PRINT and configured a laptop for monitor mode sniffing.

raysvmc on Jul 12, 2022