espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.62k stars 7.27k forks source link

WPA2 Enterprise PEAP+MSCHAPv2 / TTLS+PAP not connecting with some login credentials (IDFGH-5060) #6845

Closed jmgraeffe closed 3 years ago

jmgraeffe commented 3 years ago

Environment

Problem Description

Expected Behavior

Connection to WPA2 Enterprise network (at university but not eduroam) can be established successfully with any valid login credentials using PEAP MSCHAPv2.

Actual Behavior

Weirdly, connecting works only with certain login credentials / accounts (personal uni accounts work but not special ones issued for a specific project) even though using the non-working username/password on Ubuntu 20.04 or Android works perfectly fine with same settings.

This could very well be a problem related to the infrastructure at place, but I don't have the knowledge nor time to figure that out.

Steps to reproduce

  1. idf.py menuconfig and do all example-related settings, enter login credentials
  2. idf.py build flash monitor

Nothing is connected to the ESP32 itself and it's powered over USB.

Code to reproduce this issue

Example in examples/wifi/wpa2_enterprise was used.

Debug Logs

Actual log (while using valid username/password not working on ESP32)

...
I (0) cpu_start: App cpu up.
I (455) cpu_start: Pro cpu start user code
I (455) cpu_start: cpu freq: 160000000
I (455) cpu_start: Application information:
I (459) cpu_start: Project name:     wpa2-enterprise
I (465) cpu_start: App version:      v4.4-dev-479-g1067b2870-dirty
I (472) cpu_start: Compile time:     Mar 23 2021 17:01:31
I (478) cpu_start: ELF file SHA256:  8c8287e510153bc9...
I (484) cpu_start: ESP-IDF:          v4.4-dev-479-g1067b2870-dirty
I (491) heap_init: Initializing. RAM available for dynamic allocation:
I (498) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (504) heap_init: At 3FFB7F80 len 00028080 (160 KiB): DRAM
I (510) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (516) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (523) heap_init: At 40095918 len 0000A6E8 (41 KiB): IRAM
I (530) spi_flash: detected chip: generic
I (534) spi_flash: flash io: dio
W (538) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (552) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (611) wifi:wifi driver task: 3ffc195c, prio:23, stack:6656, core=0
I (611) system_api: Base MAC address is not set
I (611) system_api: read default base MAC address from EFUSE
I (621) wifi:wifi firmware version: bb5a818
I (621) wifi:wifi certification version: v7.0
I (621) wifi:config NVS flash: enabled
I (621) wifi:config nano formating: disabled
I (631) wifi:Init data frame dynamic rx buffer num: 32
I (631) wifi:Init management frame dynamic rx buffer num: 32
I (641) wifi:Init management short buffer num: 32
I (641) wifi:Init dynamic tx buffer num: 32
I (651) wifi:Init static rx buffer size: 1600
I (651) wifi:Init static rx buffer num: 10
I (651) wifi:Init dynamic rx buffer num: 32
I (661) wifi_init: rx ba win: 6
I (661) wifi_init: tcpip mbox: 32
I (671) wifi_init: udp mbox: 6
I (671) wifi_init: tcp mbox: 6
I (671) wifi_init: tcp tx win: 5744
I (681) wifi_init: tcp rx win: 5744
I (681) wifi_init: tcp mss: 1440
I (691) wifi_init: WiFi IRAM OP enabled
I (691) wifi_init: WiFi RX IRAM OP enabled
I (701) example: Setting WiFi configuration SSID OvGU-802.1X...
I (701) wpa: WPA2 ENTERPRISE VERSION: [v2.0] enable

I (711) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (821) wifi:mode : sta (24:6f:28:97:48:f8)
I (821) wifi:enable tsf
I (831) wpa: BSS: Add new id 0 BSSID 1c:6a:7a:b9:12:f0 SSID 'OvGU-802.1X' chan 1
I (831) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1551) wifi:state: init -> auth (b0)
I (1561) wifi:state: auth -> assoc (0)
I (1561) wifi:state: assoc -> run (10)
I (1561) wpa: wpa2_task prio:2, stack:6656

I (1601) wpa: SSL: Need 5807 bytes more input data
I (1611) wpa: SSL: Need 4793 bytes more input data
I (1621) wpa: SSL: Need 3779 bytes more input data
I (1631) wpa: SSL: Need 2765 bytes more input data
I (1641) wpa: SSL: Need 1751 bytes more input data
I (1651) wpa: SSL: Need 737 bytes more input data
I (1741) wpa: application data is null, adding one byte for ack
I (2381) wpa: application data is null, adding one byte for ack
I (2421) wpa: EAP-TLV: TLV Result - Failure
I (3421) wpa: >>>>>wpa2 FAILED
...

Done

Expected log (while using valid username/password which are indeed working on ESP32)

...
I (0) cpu_start: App cpu up.
I (455) cpu_start: Pro cpu start user code
I (455) cpu_start: cpu freq: 160000000
I (455) cpu_start: Application information:
I (459) cpu_start: Project name:     wpa2-enterprise
I (465) cpu_start: App version:      v4.4-dev-479-g1067b2870-dirty
I (472) cpu_start: Compile time:     Mar 23 2021 17:07:03
I (478) cpu_start: ELF file SHA256:  d52daae03dc5862d...
I (484) cpu_start: ESP-IDF:          v4.4-dev-479-g1067b2870-dirty
I (491) heap_init: Initializing. RAM available for dynamic allocation:
I (498) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (504) heap_init: At 3FFB7F80 len 00028080 (160 KiB): DRAM
I (510) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (516) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (523) heap_init: At 40095918 len 0000A6E8 (41 KiB): IRAM
I (530) spi_flash: detected chip: generic
I (534) spi_flash: flash io: dio
W (538) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (552) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (611) wifi:wifi driver task: 3ffc195c, prio:23, stack:6656, core=0
I (611) system_api: Base MAC address is not set
I (611) system_api: read default base MAC address from EFUSE
I (621) wifi:wifi firmware version: bb5a818
I (621) wifi:wifi certification version: v7.0
I (621) wifi:config NVS flash: enabled
I (621) wifi:config nano formating: disabled
I (631) wifi:Init data frame dynamic rx buffer num: 32
I (631) wifi:Init management frame dynamic rx buffer num: 32
I (641) wifi:Init management short buffer num: 32
I (641) wifi:Init dynamic tx buffer num: 32
I (651) wifi:Init static rx buffer size: 1600
I (651) wifi:Init static rx buffer num: 10
I (651) wifi:Init dynamic rx buffer num: 32
I (661) wifi_init: rx ba win: 6
I (661) wifi_init: tcpip mbox: 32
I (671) wifi_init: udp mbox: 6
I (671) wifi_init: tcp mbox: 6
I (671) wifi_init: tcp tx win: 5744
I (681) wifi_init: tcp rx win: 5744
I (681) wifi_init: tcp mss: 1440
I (691) wifi_init: WiFi IRAM OP enabled
I (691) wifi_init: WiFi RX IRAM OP enabled
I (701) example: Setting WiFi configuration SSID OvGU-802.1X...
I (701) wpa: WPA2 ENTERPRISE VERSION: [v2.0] enable

I (711) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (821) wifi:mode : sta (24:6f:28:97:48:f8)
I (821) wifi:enable tsf
I (821) wpa: BSS: Add new id 0 BSSID 1c:6a:7a:b9:12:f0 SSID 'OvGU-802.1X' chan 1
I (821) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1551) wifi:state: init -> auth (b0)
I (1551) wifi:state: auth -> assoc (0)
I (1561) wifi:state: assoc -> run (10)
I (1561) wpa: wpa2_task prio:2, stack:6656

I (1591) wpa: SSL: Need 5807 bytes more input data
I (1601) wpa: SSL: Need 4793 bytes more input data
I (1621) wpa: SSL: Need 3779 bytes more input data
I (1631) wpa: SSL: Need 2765 bytes more input data
I (1641) wpa: SSL: Need 1751 bytes more input data
I (1651) wpa: SSL: Need 737 bytes more input data
I (1741) wpa: application data is null, adding one byte for ack
I (2371) wpa: application data is null, adding one byte for ack
I (2521) wpa: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
I (2561) wpa: >>>>>wpa2 FINISH

E (2561) wpa: RSN: PMKSA cache entry found - PMKID - hexdump(len=16):
E (2561) wpa: [hexdump removed since it could be security relevant]
I (2571) wifi:connected with OvGU-802.1X, aid = 2, channel 1, BW20, bssid = 1c:6a:7a:b9:12:f0
I (2571) wifi:security: WPA2-ENT, phy: bgn, rssi: -66
I (2581) wifi:pm start, type: 1

I (2631) wifi:AP's beacon interval = 104448 us, DTIM period = 1
I (4821) example: ~~~~~~~~~~~
I (4821) example: IP:0.0.0.0
I (4821) example: MASK:0.0.0.0
I (4821) example: GW:0.0.0.0
I (4821) example: ~~~~~~~~~~~
W (5611) wifi:<ba-add>idx:0 (ifx:0, 1c:6a:7a:b9:12:f0), tid:0, ssn:3009, winSize:64
I (6601) esp_netif_handlers: sta ip: 141.44.235.??, mask: 255.255.255.0, gw: 141.44.235.1
I (6821) example: ~~~~~~~~~~~
I (6821) example: IP:141.44.235.??
I (6821) example: MASK:255.255.255.0
I (6821) example: GW:141.44.235.1
I (6821) example: ~~~~~~~~~~~
...

Done

Other items if possible

If you need anything else, like some packet sniffing with Wireshark, no problem.

negativekelvin commented 3 years ago

Turn on debug logging for wpa supplicant

sagb2015 commented 3 years ago

@jmgraeffe As @negativekelvin you can turn of wpa debug logs and also the sniffer capture will help!

jmgraeffe commented 3 years ago

Damn, I thought the log above has it enabled already but clearly I saved the wrong thing.

I've an old part of a log which does contain the same error, but the esp-idf version used with that is pretty old: wpa2_failed.txt

Will do fresh logs on Monday and try to capture air traffic as well. But maybe the problem is known or you can find it in the old log already.

kapilkedawat commented 3 years ago

Hi @jmgraeffe

Please enable supplicant logging and mbedtls logging before you try to do fresh logs. We have moved to mbedtls based EAP client which provides better cipher supports in the latest IDF.

jmgraeffe commented 3 years ago

Hey, thanks so far. Here is the fresh log + tcpdump capture:

I'm starting to believe again that this is an infrastructure-related problem when wpa_supplicant is used. Some time ago, I tried the "non-working" credentials on Ubuntu 20.04 (no wpa_supplicant, I suppose) and they worked fine. Tested today again on a Debian system with wpa_supplicant and it didn't work, even though the "always-working" credentials worked fine...

sagb2015 commented 3 years ago

Hi @jmgraeffe, from the logs its clear that the failure is during phase2 challenge-response phase of MSCHAPv2. This typically fails due to wrong credentials but there may be other reasons for it. So yes, this may be very setup specific, but to narrow down we will need more information. I am guessing it will not be possible for you to provide server side logs. In that case it will help to have wpa_supplicant logs in working case with Ubuntu (non-working credentials). Can you clarify what you mean by not having wpa_supplicant on ubuntu? One of the thing we want to check is that if authentication schemes are same in both the cases.

jmgraeffe commented 3 years ago

Can you clarify what you mean by not having wpa_supplicant on ubuntu?

I think I used the GUI on Ubuntu to connect, so maybe NetworkManager did not use wpa_supplicant as the backend. But we will try on Ubuntu again because it seems like the GUI is kind of unreliable/bugged. It might have never worked, because the NetworkManager might not have applied the saved settings and used the working credentials.

Sorry if this is really a login credential thing. The uni data center says it works, we can't get it to work, back and forth... ^^

sagb2015 commented 3 years ago

@jmgraeffe If you are using GUI, please make sure to forget the network and then add the new credential after scanning the network. Also, when the credential is wrong, typically GUI front-end such as nm-applet takes time to reflect the exact status because it just relies on the association events rather than enterprise/4-way authenticated events. The right way to confirm, is to run some data traffic and see if the connection really happened. As mentioned before, mostly this is a credential issue but we can not be 100% sure unless we get the ubuntu logs. Btw, you can run the supplicant on ubuntu manually to see what is happening. Steps to do it -

1) Stop network-manager

2) Kill any background wpa_supplicant daemon running in background.

3) Start wpa_supplicant in foreground (-dd enables logging for supplicant).

wpa_supplicant -Dnl80211 -iwlan0 -c/etc/wpa_supplicant.conf -dd

You may need to refer to wpa_supplicant manual for configuring for enterprise authentication (sample is typically present in default conf under comments). Let us know if you face any issues.

jmgraeffe commented 3 years ago

Not on Ubuntu but on an old Debian machine:

debian_wpa_supplicant_failure.txt

The working login credentials work fine with the exact same configuration file, which looks like this:

network={
  ssid="OvGU-802.1X"
  scan_ssid=1
  key_mgmt=WPA-EAP
  identity="miotr010"
  password="<pass>"
  eap=PEAP
  phase1="peaplabel=0"
  phase2="auth=MSCHAPV2"
}
sagb2015 commented 3 years ago

@jmgraeffe The debian observation matches with ESP32 observation (phase2 failure). I was suggesting to repeat the experiment with ubuntu as well through command line instead of GUI, so we know why there is inconsistency.

EAP-PEAP: received Phase 2: code=1 identifier=14 length=11
EAP-PEAP: Phase 2 Request: type=33
EAP-TLV: Received TLVs - hexdump(len=6): 80 03 00 02 00 02
EAP-TLV: Result TLV - hexdump(len=2): 00 02
EAP-TLV: TLV Result - Failure 
jmgraeffe commented 3 years ago

Okay, after some testing it seems that PEAP+MSCHAPv2 does not work on any computer with the special accounts, while other accounts work. I think it's an infrastructure-related issue, which will be given to our data center and we'll see.


But it's getting more crazy now. The special accounts do work with TTLS+PAP on wpa_supplicant: debian_ttls_pap_success.txt

network={
  ssid="OvGU-802.1X"
  scan_ssid=1
  key_mgmt=WPA-EAP
  identity="miotr006"
  password="<pass>"
  eap=TTLS
  phase2="auth=PAP"
}

They do not work on the ESP32 with TTLS+PAP though: esp32_ttls_pap_failure.txt

jmgraeffe commented 3 years ago

It is confirmed that PEAP+MSCHAPv2 not working with some accounts is infrastructure-related. Apparently there are two Kerberos systems with each one serving a different protocol (PEAP+MSCHAPv2 and TTLS+PAP). The special accounts were only added to one of them by mistake.


However, this does not explain why TTLS+PAP does not work. But I found the following log entries in the esp32_ttls_pap_failure.txt and also logs where I used student accounts which worked from the beginning:

...
I (44134) wpa: TLS: Unsupported Phase2 EAP method 'PAP'
...
D (5040) wpa: EAP-PEAP: Start (server ver=0, own ver=1)
D (5050) wpa: EAP-PEAP: Using PEAP version 0
...

This seems to indicate that PEAP is used instead of TTLS+PAP because PAP is not supported. Thus, the problem that caused PEAP to not work applied with TTLS+PAP chosen in idf.py menuconfig too.

Is this expected behavior? If yes, it may be better to just remove it from the example.

jmgraeffe commented 3 years ago

Since the last problem is not really related to the original issue anymore and this issue seems to be abandoned already, I created a new issue for it: #7011

But thanks for the help! I really appreciated it.