Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wifi: EAP re-authentication does not work (IDFGH-345) #2324

Closed
3 tasks
ghost opened this issue Aug 23, 2018 · 50 comments
Closed
3 tasks

wifi: EAP re-authentication does not work (IDFGH-345) #2324

ghost opened this issue Aug 23, 2018 · 50 comments

Comments

@ghost
Copy link

ghost commented Aug 23, 2018

Environment

  • Development Kit: [none]
  • Kit version (for WroverKit/PicoKit/DevKitC): [-]
  • Core (if using chip or module): [ESP32]
  • IDF version): 30545f4
  • Development Env: [Make]
  • Operating System: [Ubuntu]
  • Power Supply: [external 5V]

Problem Description

EAP re-authentication is non-functional. EAP/enterprise wifi networks may be configured to re-authenticate at certain intervals to regenerate new crypto keys. This function does not work on ESP32 causing wifi disconnects. Also after being disconnected the chip appears stuck in some invalid state causing it to never perform new connect attempts.

Expected Behavior

  1. Successfully connect to EAP/enterprise wifi network
  2. Wait for network to initiate EAP re-authentication
  3. EAP re-authentication completes
  4. Wifi connection is kept

Actual Behavior

  1. Successfully connect to EAP/enterprise wifi network
  2. Wait for network to initiate EAP re-authentication
  3. ESP32 does not respond to network initiated EAP re-authentication
  4. After re-auth timeout ESP32 is disconnected by network (or STA depending on who timed out first)
  5. After being disconnected no more connect attempts are performed.

Steps to repropduce

  1. Configure a test EAP (PEAP-MSCHAPv2) network using hostapd
  2. Set eap_reauth_period in hostapd.conf to a low value (like 60) to have the network perform re-authentication often.
  3. Connect to network using ESP-IDF wpa2_enterprise example code
  4. Wait for EAP re-authentication to occur
  5. Notice the disconnect
  6. Notice that no new connect attempt is done.

Debug Logs

I (144671) example: IP:192.168.5.5
I (144671) example: MASK:255.255.255.240
I (144671) example: GW:192.168.5.1
I (144671) example: ~~~~~~~~~~~
I (145311) wifi: state: run -> init (2c0)
I (145311) wifi: pm stop, total sleep time: 137439245 us / 140408103 us

I (145311) wifi: n:3 0, o:3 0, ap:255 255, sta:3 0, prof:1
D (145321) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Kanstrup, ssid_len:8, bssid:34:13:e8:62:a3:40, reason:204
V (145331) event: enter default callback
V (145331) tcpip_adapter: check: local, if=0 fn=0x400e554c
0x400e554c: tcpip_adapter_down_api at esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1082

Other items if possible

Attached files (logs.tar.gz:

  • trace.pcapng - air sniffer packet log
  • esp32.txt - esp serial log (verbose level)
  • hostapd-filtered.txt - hostapd log (probe req/resp frame log line among others filtered due to security concerns)

To decrypt traffic in air sniffer packet log (eapol packets for EAP re-auth are encrypted) use the following PMK 25638c633b709113ec73401621f08a8ca6a1d01193e9997cd44ed8dd9c49b27e

If wireshark is used the decrypt key can be configured under:
Edit->Preferences->Protocols->IEEE 802.11->Decyption keys->Edit...

Add a WPA-PSK key with the key above.

@FayeY FayeY changed the title wifi: EAP re-authentication does not work [TW#25834] wifi: EAP re-authentication does not work Aug 28, 2018
@XinDeng11
Copy link
Contributor

Hi @mikaelkanstrup this is because our enterprise is a unique task, after you call esp_wifi_sta_wpa2_ent_enable(), the wpa_enterprise task create, after finish the EAP step, the task will delete itself. However, the task would create automatic when you re-authentice, you need enable the task at first then connect.

@XinDeng11
Copy link
Contributor

@mikaelkanstrup Sorry, the task wouldn't create itself when you re-connect. You need enable the task at first by call esp_wifi_sta_wpa2_ent_enable() and then connect

@ghost
Copy link
Author

ghost commented Aug 30, 2018

@XinDeng11 Thanks for the sharing the info! Though I'm not sure how to treat your answer. Do you believe this is an application side error or esp-idf internal error?

For me this is an esp-idf internal error. The steps to make the initial connection already involves calling esp_wifi_sta_wpa2_ent_enable and then wifi_connect. You have the example code so just check the sources if anything is unclear there. After the connection has been established there's no way for application side to know when the network will initiate an EAP re-authentication.

You say the unique task to perform EAP steps is deleted after finishing the initial authentication. This sounds wrong. Some task should still be running and listen for EAP Request Identity data packets from the network that then starts the EAP re-authentication procedure. All of this I would expect is handled internally.

BTW are planning on making any of this open source? I would be happy to help out investigating problems in this area but without source code I can only guess based on the behavior seen.

@XinDeng11
Copy link
Contributor

We need discuss it internal at first

@ghost
Copy link
Author

ghost commented Sep 18, 2018

@XinDeng11 Please have a look at the attached files in computer-reauth-success.tar.gz

These logs (airsniffer logs, wpa_supplicant and hostapd) show my computer successfully keeping its wifi connection through 5 reauthentications. Compare that with the earlier logs from ESP32 where the connection drops when re-authentication times out.

To be able to decrypt all traffic you wil need to configure Wireshark with the following keys:

f8637cd29340f30e875c430ee07acb4616309faaa5de5899a61b759fb998c8c9
4e338339bc1c7d5515aef228aeca4793087b72e9bd7d5caece12e76d6c69625f
8df30c39fe7ccea37dc586aa16b0f622e9308d0d903e6537402f277b3de444dc
acf13f32e2f4fbaefba4a674f6ce3e656c025ddd8e255ca83e83622faf54bfdf
8dbc6b877a441cd479340107529a8f0e7b9b8bf49d29ec79ed6ca893be2619e8
e8b01bef2e376daa51d359a49d179c37949ab98dbbdf14bcc5f0645bace8b9cd

That's six different keys as after initial key negotiation the keys are re-negotiated another 5 times.

computer-reauth-success.tar.gz

@FayeY
Copy link
Collaborator

FayeY commented Sep 25, 2018

I was told that this issue continues through email, so I am going to close it. Please feel free to reopen, if I misunderstood it. Thanks.

@FayeY FayeY closed this as completed Sep 25, 2018
@ghost
Copy link
Author

ghost commented Sep 25, 2018

@FayeY @XinDeng11 I think this issue should be kept open as EAP re-authentication is still not working. We've discussed it via email and we've received information about a possible workaround (i.e. by re-connecting successfully after disconnect). The workaround definitely makes this issue less critical so let's continue the discussion here.

Keeping it open also show other users of ESP-IDF that this is still an issue.

@PaulFreund
Copy link

Hi, implementing reauth would help me a lot (I can stop setting up a parallel infrastructure without WPA2 Enterprise), is this something you are working on?

@projectgus projectgus changed the title [TW#25834] wifi: EAP re-authentication does not work wifi: EAP re-authentication does not work (IDFGH-345) Mar 12, 2019
@ghost
Copy link
Author

ghost commented Aug 28, 2019

This issue is still present on latest master as of today. Are there any plans to support this?

@sagb2015
Copy link
Contributor

sagb2015 commented Aug 28, 2019

This bugfix is internally ready-to be merged and should be available on master soon. We will update once done.

@ghost
Copy link
Author

ghost commented Aug 28, 2019

This bugfix is internally ready-to be merged and should be available on master soon. We will update once done.

@sagb2015 Ok that's really nice to hear! I'd gladly support testing it in our environment if you want some extra verification before merging.

@sagb2015
Copy link
Contributor

@mikaelkanstrup Thanks for offering the help, but it needs both IDF and wifi-lib patches and compatible versions. The changes should be available soon (less than a week time). You can test it then and provide the feedback.

@ghost
Copy link
Author

ghost commented Aug 29, 2019

@sagb2015 Ok sure. I'll try it out once available on master and report back.

@sagb2015
Copy link
Contributor

Apologies for the delay! This has been fixed by 3b606aa. Please help to test.

@sagb2015
Copy link
Contributor

sagb2015 commented Sep 13, 2019

Closing this issue. Feel free to open if you still face it.

@ghost
Copy link
Author

ghost commented Sep 13, 2019

Thanks for implementing this!

Just wanted to confirm that reauth now works. In my test setup I've just completed ~50 successful re-authentications without dropping wifi connection.

@sagb2015
Copy link
Contributor

Thank you for your help in testing!

@PaulFreund
Copy link

Unfortunately it does not seem to fix the problem with the Cisco AP's we have here. I try to make a verbose log as soon as possible. (I had >150 disconnects over the weekend)

@ghost
Copy link
Author

ghost commented Sep 16, 2019

@PaulFreund I have not been able to properly verify towards Cisco APs due to #3956. That issue makes connection attempts fail very often with recent esp-idf master. Most likely it affects both initial authentication as well as re-authentications. Unfortunately there's at the moment no version where EAP re-auth is supported but the commit causing #3956 is not also integrated.

Due to the above issue I've only verified EAP re-auth towards a local test setup running hostapd with an internal radius server. In this setup all works fine.

@PaulFreund
Copy link

PaulFreund commented Sep 16, 2019

I now have a log with wifi set to verbose:

...
I (570) cpu_start: Pro cpu up.
I (570) cpu_start: Application information:
I (585) cpu_start: ESP-IDF:          v4.1-dev-256-g9f145ff16-dirty
...
I (1772) wifi: wifi driver task: 3ffdaa5c, prio:23, stack:3584, core=0
I (1772) wifi: wifi firmware version: df55612
I (1772) wifi: config NVS flash: disabled
I (1772) wifi: config nano formating: disabled
I (1772) wifi: Init dynamic tx buffer num: 32
I (1782) wifi: Init data frame dynamic rx buffer num: 32
I (1782) wifi: Init management frame dynamic rx buffer num: 32
I (1792) wifi: Init management short buffer num: 32
I (1792) wifi: Init static rx buffer size: 1600
I (1802) wifi: Init static rx buffer num: 10
I (1802) wifi: Init dynamic rx buffer num: 32
I (1892) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 0
I (1892) wifi: mode : sta (84:0d:8e:xx:xx:xx)
...
I (3952) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4262) wifi: state: init -> auth (b0)
I (4262) wifi: state: auth -> assoc (0)
I (4292) wifi: state: assoc -> run (10)
I (5582) wifi: connected with CENSORED, channel 1, BW20, bssid = e0:0e:da:xx:xx:xx
I (5582) wifi: pm start, type: 1
...
From here on it is connected until reauth is requested
...
I (1789482) wifi: state: run -> init (fc0)
I (1789482) wifi: pm stop, total sleep time: 1013356158 us / 1783900513 us

I (1789492) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1791552) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1791552) wifi: state: init -> auth (b0)
I (1791562) wifi: state: auth -> assoc (0)
I (1791572) wifi: state: assoc -> run (10)
I (1792782) wifi: connected with CENSORED, channel 1, BW20, bssid = e0:0e:da:xx:xx:xx
I (1792782) wifi: pm start, type: 1

Was more of the code open sourced now? Would it be possible to help debugging now? By now we have 16 separately managed routers in our building just to cope with this.

@sagb2015
Copy link
Contributor

@PaulFreund @mikaelkanstrup : We will prioritise #3956 internally and see if there is any impact on this issue.

@ghost
Copy link
Author

ghost commented Sep 16, 2019

@PaulFreund Yes, there's some more code open sourced now. And most of the EAP handling is in supplicant. With debug logs enabled you get huge amounts of supplicant logs. Note that debug logs include hexdump of encryption keys if you plan to share any logs.

You get a somewhat reasonable level of debug logs for this by leaving the function wpa_hexdump in components/wpa_supplicant/src/utils/wpa_debug.c empty. Like this:

git diff
diff --git a/components/wpa_supplicant/src/utils/wpa_debug.c b/components/wpa_supplicant/src/utils/wpa_debug.c
index aed26664e..b59b6e019 100644
--- a/components/wpa_supplicant/src/utils/wpa_debug.c
+++ b/components/wpa_supplicant/src/utils/wpa_debug.c
@@ -72,24 +72,6 @@ void  wpa_debug_print_timestamp(void)
 
 void  wpa_hexdump(int level, const char *title, const u8 *buf, size_t len)
 {
-#ifdef DEBUG_PRINT 
-       size_t i;
-
-       if (level < MSG_MSGDUMP)
-               return;
-
-       wpa_printf(MSG_DEBUG, "%s - hexdump(len=%lu):\n", title, (unsigned long) len);
-       if (buf == NULL) {
-               wpa_printf(MSG_DEBUG, " [NULL]\n");
-       } else {
-               for (i = 0; i < len; i++) {
-                       wpa_printf(MSG_DEBUG, " %02x", buf[i]);
-            if((i+1) % 16 == 0)
-                wpa_printf(MSG_DEBUG, "\n");
-        }
-       } 
-       wpa_printf(MSG_DEBUG, "\n");
-#endif 
 }
 
 void  wpa_hexdump_key(int level, const char *title, const u8 *buf, size_t len)

And setting Component config>Log output>Default log verbosity>Debug

With this you should see the EAP states, eapol frames, 4 way handshake, key installs etc happening. Hopefully this will tell what's wrong.

@PaulFreund
Copy link

PaulFreund commented Sep 17, 2019

Here is the log of the reauthentication with disconnect:

D (1806623) wpa: IEEE 802.1X RX: version=2 type=0 length=50

I (1806623) wpa: >>>>>wpa2 EAP Re-authentication in progress

D (1806623) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1806623) wpa: WPA2: wpa2 api return, sm->state(1)
D (1806673) wpa: IEEE 802.1X RX: version=2 type=0 length=6

D (1806673) wpa: TLS: using phase1 config options
D (1806673) wpa: SSL: Received packet(len=6) - Flags 0x20
D (1806683) wpa: EAP-PEAP: Start (server ver=0, own ver=1)
D (1806683) wpa: EAP-PEAP: Using PEAP version 0
D (1806693) wpa: TLSv1: Send ClientHello
D (1806693) wpa: SSL: 60 bytes left to be sent out (of total 60 bytes)
D (1806703) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1806703) wpa: WPA2: wpa2 api return, sm->state(1)
D (1806753) wpa: IEEE 802.1X RX: version=2 type=0 length=1296

D (1806753) wpa: SSL: Received packet(len=1296) - Flags 0xc0
D (1806753) wpa: SSL: TLS Message Length: 3633
I (1806753) wpa: SSL: Need 2347 bytes more input data
D (1806763) wpa: SSL: Building ACK (type=25 id=3 ver=0) 

D (1806763) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1806773) wpa: WPA2: wpa2 api return, sm->state(1)
D (1806823) wpa: IEEE 802.1X RX: version=2 type=0 length=1296

D (1806823) wpa: SSL: Received packet(len=1296) - Flags 0x40
I (1806823) wpa: SSL: Need 1057 bytes more input data
D (1806823) wpa: SSL: Building ACK (type=25 id=4 ver=0) 

D (1806833) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1806833) wpa: WPA2: wpa2 api return, sm->state(1)
D (1806903) wpa: IEEE 802.1X RX: version=2 type=0 length=1063

D (1806903) wpa: SSL: Received packet(len=1063) - Flags 0x00
D (1806903) wpa: TLSv1: Received content type 22 version 3.1 length 3628
D (1806913) wpa: TLSv1: Received ServerHello
D (1806913) wpa: TLSv1: Using TLS v1.0
D (1806923) wpa: TLSv1: Selected cipher suite: 0x0035
D (1806923) wpa: TLSv1: Received Certificate (certificate_list len 3536)
D (1806933) wpa: TLSv1: Certificate 0 (len 1908)
D (1806933) wpa: X509: Version X.509v3
D (1806943) wpa: X509: serialNumber 53251
D (1806943) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1806953) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1806953) wpa: X509: subject C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=DISIP, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1806973) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1806973) wpa: ASN.1: Extended tag data: 0x04
D (1806983) wpa: X509: Extension: extnID=2.5.29.15 critical=255
D (1806983) wpa: X509: KeyUsage 0x5
D (1806993) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1806993) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1807003) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1807003) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.7 critical=0
D (1807013) wpa: X509: Extension: extnID=2.5.29.37 critical=0
D (1807013) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1807023) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.10 critical=0
D (1807033) wpa: X509: Version X.509v3
D (1807033) wpa: X509: serialNumber 53251
D (1807033) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1807043) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1807053) wpa: X509: subject C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1807063) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1807063) wpa: ASN.1: Extended tag data: 0x04
D (1807073) wpa: X509: Extension: extnID=2.5.29.15 critical=255
D (1807073) wpa: X509: KeyUsage 0x5
D (1807083) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1807083) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1807093) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1807103) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.7 critical=0
D (1807103) wpa: X509: Extension: extnID=2.5.29.37 critical=0
D (1807113) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1807113) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.10 critical=0
D (1807123) wpa: TLSv1: Certificate 1 (len 1619)
D (1807123) wpa: X509: Version X.509v3
D (1807133) wpa: X509: serialNumber 2
D (1807133) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Root CA
D (1807143) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1807143) wpa: X509: subject C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1807153) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.1 critical=0
D (1807163) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1807163) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1807173) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.20.2 critical=0
D (1807173) wpa: X509: Extension: extnID=2.5.29.15 critical=0
D (1807183) wpa: X509: KeyUsage 0x61
D (1807183) wpa: ASN.1: Extended tag data: 0x04
D (1807193) wpa: X509: Extension: extnID=2.5.29.19 critical=255
D (1807193) wpa: X509: BasicConstraints - cA=255
D (1807203) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1807203) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1807213) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1807213) wpa: X509: Validate certificate chain
D (1807223) wpa: X509: 0: C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=DISIP, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1807433) wpa: X509: Certificate Digest matches with calculated tbsCertificate hash
D (1807433) wpa: X509: 1: C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1807433) wpa: X509: Did not find any of the issuers from the list of trusted certificates
D (1807443) wpa: X509: Certificate chain validation disabled - ignore unknown CA issue
D (1807453) wpa: X509: Certificate chain valid
D (1807463) wpa: TLSv1: Received CertificateRequest
D (1807463) wpa: TLSv1: Received ServerHelloDone
D (1807463) wpa: TLSv1: Send Certificate
D (1807473) wpa: TLSv1: Full client certificate chain not configured - validation may fail
D (1807473) wpa: TLSv1: Send ClientKeyExchange
D (1807663) wpa: TLSv1: Send ChangeCipherSpec
D (1807663) wpa: TLSv1: Record Layer - New write cipher suite 0x0035
D (1807663) wpa: TLSv1: Send Finished
D (1807673) wpa: SSL: 338 bytes left to be sent out (of total 338 bytes)
D (1807673) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1807673) wpa: WPA2: wpa2 api return, sm->state(1)
D (1807743) wpa: IEEE 802.1X RX: version=2 type=0 length=69

D (1807743) wpa: SSL: Received packet(len=69) - Flags 0x80
D (1807743) wpa: SSL: TLS Message Length: 59
D (1807743) wpa: TLSv1: Received content type 20 version 3.1 length 1
D (1807753) wpa: TLSv1: Received ChangeCipherSpec
D (1807753) wpa: TLSv1: Record Layer - New read cipher suite 0x0035 

D (1807763) wpa: TLSv1: Received content type 22 version 3.1 length 48
D (1807763) wpa: TLSv1: Received Finished
D (1807773) wpa: TLSv1: Handshake completed successfully
D (1807773) wpa: SSL: No data to be sent out
D (1807773) wpa: EAP-PEAP: TLS done, proceed to Phase 2
D (1807783) wpa: EAP-PEAP: using label 'client EAP encryption' in key derivation
D (1807793) wpa: SSL: Building ACK (type=25 id=6 ver=0) 

D (1807793) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1807803) wpa: WPA2: wpa2 api return, sm->state(1)
D (1807853) wpa: IEEE 802.1X RX: version=2 type=0 length=43

D (1807853) wpa: SSL: Received packet(len=43) - Flags 0x00
D (1807853) wpa: EAP-PEAP: received 37 bytes encrypted data for Phase 2

D (1807853) wpa: TLSv1: Received content type 23 version 3.1 length 32
D (1807863) wpa: EAP-PEAP: received Phase 2: code=1 identifier=7 length=5

D (1807863) wpa: EAP-PEAP: Phase 2 Request: type=1

D (1807873) wpa: SSL: 53 bytes left to be sent out (of total 53 bytes)
D (1807883) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1807883) wpa: WPA2: wpa2 api return, sm->state(1)
D (1807923) wpa: IEEE 802.1X RX: version=2 type=0 length=59

D (1807923) wpa: SSL: Received packet(len=59) - Flags 0x00
D (1807923) wpa: EAP-PEAP: received 53 bytes encrypted data for Phase 2

D (1807923) wpa: TLSv1: Received content type 23 version 3.1 length 48
D (1807933) wpa: EAP-PEAP: received Phase 2: code=1 identifier=8 length=20

D (1807943) wpa: EAP-PEAP: Phase 2 Request: type=1

D (1807943) wpa: SSL: 53 bytes left to be sent out (of total 53 bytes)
D (1807953) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1807953) wpa: WPA2: wpa2 api return, sm->state(1)
D (1807993) wpa: IEEE 802.1X RX: version=2 type=0 length=75

D (1807993) wpa: SSL: Received packet(len=75) - Flags 0x00
D (1807993) wpa: EAP-PEAP: received 69 bytes encrypted data for Phase 2

D (1807993) wpa: TLSv1: Received content type 23 version 3.1 length 64
D (1808003) wpa: EAP-PEAP: received Phase 2: code=1 identifier=9 length=34

D (1808013) wpa: EAP-PEAP: Phase 2 Request: type=26

D (1808013) wpa: EAP-PEAP: Selected Phase 2 EAP vendor 0 method 26

D (1808023) wpa: EAP-MSCHAPV2: RX identifier 9 mschapv2_id 9

D (1808023) wpa: EAP-MSCHAPV2: Generate Challenge Response

D (1808033) wpa: SSL: 101 bytes left to be sent out (of total 101 bytes)
D (1808043) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1808043) wpa: WPA2: wpa2 api return, sm->state(1)
D (1808083) wpa: IEEE 802.1X RX: version=2 type=0 length=91

D (1808083) wpa: SSL: Received packet(len=91) - Flags 0x00
D (1808093) wpa: EAP-PEAP: received 85 bytes encrypted data for Phase 2

D (1808093) wpa: TLSv1: Received content type 23 version 3.1 length 80
D (1808103) wpa: EAP-PEAP: received Phase 2: code=1 identifier=10 length=51

D (1808103) wpa: EAP-PEAP: Phase 2 Request: type=26

D (1808113) wpa: EAP-MSCHAPV2: RX identifier 10 mschapv2_id 9

D (1808113) wpa: SSL: 37 bytes left to be sent out (of total 37 bytes)
D (1808123) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1808133) wpa: WPA2: wpa2 api return, sm->state(1)
D (1838173) wpa: IEEE 802.1X RX: version=2 type=0 length=91

D (1838173) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1838173) wpa: WPA2: wpa2 api return, sm->state(1)
D (1838203) wpa: IEEE 802.1X RX: version=2 type=0 length=107

D (1838203) wpa: SSL: Received packet(len=107) - Flags 0x00
D (1838203) wpa: EAP-PEAP: received 101 bytes encrypted data for Phase 2

D (1838213) wpa: TLSv1: Received content type 23 version 3.1 length 96
D (1838223) wpa: EAP-PEAP: received Phase 2: code=1 identifier=12 length=71

D (1838223) wpa: EAP-PEAP: Phase 2 Request: type=33

D (1838233) wpa: EAP-PEAP: Valid cryptobinding TLV received
I (1838233) wpa: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
D (1838243) wpa: SSL: 101 bytes left to be sent out (of total 101 bytes)
D (1838253) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1838253) wpa: WPA2: wpa2 api return, sm->state(1)
D (1838293) wpa: IEEE 802.1X RX: version=2 type=0 length=4

I (1838293) wpa: >>>>>wpa2 FINISH

D (1838293) wpa: TLSv1: Selected cipher suite: 0x0000
D (1838293) wpa: TLSv1: Record Layer - New write cipher suite 0x0000
D (1838303) wpa: TLSv1: Record Layer - New read cipher suite 0x0000 

D (1838313) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1838313) wpa: WPA2: wpa2 api return, sm->state(2)
D (1838323) wpa: IEEE 802.1X RX: version=2 type=3 length=117

D (1838323) wpa:   EAPOL-Key type=2

D (1838323) wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

D (1838333) wpa:   key_length=16 key_data_length=22

D (1838343) wpa: WPA 1/4-Way Handshake

D (1838343) wpa: WPA: PTK derivation - A1=84:0d:8e:1b:e8:a0 A2=XX:XX:XX:XX:XX:XX

D (1838353) wpa: WPA Send EAPOL-Key 2/4

D (1839533) wpa: IEEE 802.1X RX: version=2 type=3 length=117

D (1839533) wpa:   EAPOL-Key type=2

D (1839533) wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

D (1839533) wpa:   key_length=16 key_data_length=22

D (1839543) wpa: WPA 1/4-Way Handshake

D (1839543) wpa: WPA: PTK derivation - A1=84:0d:8e:1b:e8:a0 A2=XX:XX:XX:XX:XX:XX

D (1839553) wpa: WPA Send EAPOL-Key 2/4

D (1840463) wpa: IEEE 802.1X RX: version=2 type=3 length=117

D (1840463) wpa:   EAPOL-Key type=2

D (1840463) wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

D (1840463) wpa:   key_length=16 key_data_length=22

D (1840473) wpa: WPA 1/4-Way Handshake

D (1840473) wpa: WPA: PTK derivation - A1=84:0d:8e:1b:e8:a0 A2=XX:XX:XX:XX:XX:XX

D (1840483) wpa: WPA Send EAPOL-Key 2/4

I (1841823) wifi: state: run -> init (fc0)
I (1841823) wifi: pm stop, total sleep time: 1079244990 us / 1835077976 us

D (1841823) wpa: WPA2: queue deleted
D (1841823) wpa: WPA2: task deleted
D (1841833) wpa: WPA2: wifi->wpa2 api completed sig(2)
D (1841833) wpa: WPA2: wpa2 api return, sm->state(2)
D (1841843) wpa: wpa2 eap_peer_sm_deinit: free data lock
I (1841843) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1841853) wpa: WPA2: already enabled
I (1843913) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (1843913) wifi: state: init -> auth (b0)
I (1843923) wifi: state: auth -> assoc (0)
I (1843933) wifi: state: assoc -> run (10)
I (1843933) wpa: wpa2_task prio:2, stack:6656

D (1843933) wpa: WPA2: wifi->wpa2 api completed sig(0)
D (1843933) wpa: WPA2: wpa2 api return, sm->state(1)
D (1843943) wpa: IEEE 802.1X RX: version=2 type=0 length=50

D (1843943) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1843953) wpa: WPA2: wpa2 api return, sm->state(1)
D (1843953) wpa: IEEE 802.1X RX: version=2 type=0 length=50

D (1843963) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1843963) wpa: WPA2: wpa2 api return, sm->state(1)
D (1844013) wpa: IEEE 802.1X RX: version=2 type=0 length=6

D (1844013) wpa: TLS: using phase1 config options
D (1844013) wpa: SSL: Received packet(len=6) - Flags 0x20
D (1844013) wpa: EAP-PEAP: Start (server ver=0, own ver=1)
D (1844023) wpa: EAP-PEAP: Using PEAP version 0
D (1844023) wpa: TLSv1: Send ClientHello
D (1844023) wpa: SSL: 60 bytes left to be sent out (of total 60 bytes)
D (1844033) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1844043) wpa: WPA2: wpa2 api return, sm->state(1)
D (1844083) wpa: IEEE 802.1X RX: version=2 type=0 length=1296

D (1844083) wpa: SSL: Received packet(len=1296) - Flags 0xc0
D (1844083) wpa: SSL: TLS Message Length: 3633
I (1844093) wpa: SSL: Need 2347 bytes more input data
D (1844093) wpa: SSL: Building ACK (type=25 id=4 ver=0) 

D (1844103) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1844103) wpa: WPA2: wpa2 api return, sm->state(1)
D (1844153) wpa: IEEE 802.1X RX: version=2 type=0 length=1296

D (1844153) wpa: SSL: Received packet(len=1296) - Flags 0x40
I (1844153) wpa: SSL: Need 1057 bytes more input data
D (1844153) wpa: SSL: Building ACK (type=25 id=5 ver=0) 

D (1844163) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1844163) wpa: WPA2: wpa2 api return, sm->state(1)
D (1844223) wpa: IEEE 802.1X RX: version=2 type=0 length=1063

D (1844223) wpa: SSL: Received packet(len=1063) - Flags 0x00
D (1844223) wpa: TLSv1: Received content type 22 version 3.1 length 3628
D (1844233) wpa: TLSv1: Received ServerHello
D (1844233) wpa: TLSv1: Using TLS v1.0
D (1844233) wpa: TLSv1: Selected cipher suite: 0x0035
D (1844243) wpa: TLSv1: Received Certificate (certificate_list len 3536)
D (1844253) wpa: TLSv1: Certificate 0 (len 1908)
D (1844253) wpa: X509: Version X.509v3
D (1844253) wpa: X509: serialNumber 53251
D (1844263) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1844263) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1844273) wpa: X509: subject C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=DISIP, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1844283) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1844293) wpa: ASN.1: Extended tag data: 0x04
D (1844293) wpa: X509: Extension: extnID=2.5.29.15 critical=255
D (1844303) wpa: X509: KeyUsage 0x5
D (1844303) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1844313) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1844313) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1844323) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.7 critical=0
D (1844333) wpa: X509: Extension: extnID=2.5.29.37 critical=0
D (1844333) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1844343) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.10 critical=0
D (1844343) wpa: X509: Version X.509v3
D (1844353) wpa: X509: serialNumber 53251
D (1844353) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1844363) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1844363) wpa: X509: subject C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1844383) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1844383) wpa: ASN.1: Extended tag data: 0x04
D (1844393) wpa: X509: Extension: extnID=2.5.29.15 critical=255
D (1844393) wpa: X509: KeyUsage 0x5
D (1844393) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1844403) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1844413) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1844413) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.7 critical=0
D (1844423) wpa: X509: Extension: extnID=2.5.29.37 critical=0
D (1844423) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1844433) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.10 critical=0
D (1844443) wpa: TLSv1: Certificate 1 (len 1619)
D (1844443) wpa: X509: Version X.509v3
D (1844443) wpa: X509: serialNumber 2
D (1844453) wpa: X509: issuer C=SE, O=CENSORED, OU=PKI, CN=CENSORED Root CA
D (1844453) wpa: X509: Validity: notBefore: 0 notAfter: 0
D (1844463) wpa: X509: subject C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1844473) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.21.1 critical=0
D (1844473) wpa: X509: Extension: extnID=2.5.29.14 critical=0
D (1844483) wpa: X509: Extension: extnID=2.5.29.32 critical=0
D (1844483) wpa: X509: Extension: extnID=1.3.6.1.4.1.311.20.2 critical=0
D (1844493) wpa: X509: Extension: extnID=2.5.29.15 critical=0
D (1844503) wpa: X509: KeyUsage 0x61
D (1844503) wpa: ASN.1: Extended tag data: 0x04
D (1844503) wpa: X509: Extension: extnID=2.5.29.19 critical=255
D (1844513) wpa: X509: BasicConstraints - cA=255
D (1844513) wpa: X509: Extension: extnID=2.5.29.35 critical=0
D (1844523) wpa: X509: Extension: extnID=2.5.29.31 critical=0
D (1844523) wpa: X509: Extension: extnID=1.3.6.1.5.5.7.1.1 critical=0
D (1844533) wpa: X509: Validate certificate chain
D (1844543) wpa: X509: 0: C=CENSORED, ST=CENSORED, L=CENSORED, O=AB CENSORED, OU=DISIP, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=CENSORED, OU=I
D (1844753) wpa: X509: Certificate Digest matches with calculated tbsCertificate hash
D (1844753) wpa: X509: 1: C=SE, O=CENSORED, OU=PKI, CN=CENSORED Central CA
D (1844753) wpa: X509: Did not find any of the issuers from the list of trusted certificates
D (1844763) wpa: X509: Certificate chain validation disabled - ignore unknown CA issue
D (1844773) wpa: X509: Certificate chain valid
D (1844773) wpa: TLSv1: Received CertificateRequest
D (1844773) wpa: TLSv1: Received ServerHelloDone
D (1844783) wpa: TLSv1: Send Certificate
D (1844783) wpa: TLSv1: Full client certificate chain not configured - validation may fail
D (1844793) wpa: TLSv1: Send ClientKeyExchange
D (1844993) wpa: TLSv1: Send ChangeCipherSpec
D (1844993) wpa: TLSv1: Record Layer - New write cipher suite 0x0035
D (1844993) wpa: TLSv1: Send Finished
D (1845003) wpa: SSL: 338 bytes left to be sent out (of total 338 bytes)
D (1845003) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845013) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845063) wpa: IEEE 802.1X RX: version=2 type=0 length=69

D (1845063) wpa: SSL: Received packet(len=69) - Flags 0x80
D (1845063) wpa: SSL: TLS Message Length: 59
D (1845063) wpa: TLSv1: Received content type 20 version 3.1 length 1
D (1845073) wpa: TLSv1: Received ChangeCipherSpec
D (1845073) wpa: TLSv1: Record Layer - New read cipher suite 0x0035 

D (1845083) wpa: TLSv1: Received content type 22 version 3.1 length 48
D (1845093) wpa: TLSv1: Received Finished
D (1845093) wpa: TLSv1: Handshake completed successfully
D (1845093) wpa: SSL: No data to be sent out
D (1845103) wpa: EAP-PEAP: TLS done, proceed to Phase 2
D (1845103) wpa: EAP-PEAP: using label 'client EAP encryption' in key derivation
D (1845113) wpa: SSL: Building ACK (type=25 id=7 ver=0) 

D (1845123) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845123) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845163) wpa: IEEE 802.1X RX: version=2 type=0 length=43

D (1845163) wpa: SSL: Received packet(len=43) - Flags 0x00
D (1845163) wpa: EAP-PEAP: received 37 bytes encrypted data for Phase 2

D (1845173) wpa: TLSv1: Received content type 23 version 3.1 length 32
D (1845173) wpa: EAP-PEAP: received Phase 2: code=1 identifier=8 length=5

D (1845183) wpa: EAP-PEAP: Phase 2 Request: type=1

D (1845183) wpa: SSL: 53 bytes left to be sent out (of total 53 bytes)
D (1845193) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845203) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845243) wpa: IEEE 802.1X RX: version=2 type=0 length=59

D (1845243) wpa: SSL: Received packet(len=59) - Flags 0x00
D (1845243) wpa: EAP-PEAP: received 53 bytes encrypted data for Phase 2

D (1845243) wpa: TLSv1: Received content type 23 version 3.1 length 48
D (1845253) wpa: EAP-PEAP: received Phase 2: code=1 identifier=9 length=20

D (1845263) wpa: EAP-PEAP: Phase 2 Request: type=1

D (1845263) wpa: SSL: 53 bytes left to be sent out (of total 53 bytes)
D (1845273) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845273) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845323) wpa: IEEE 802.1X RX: version=2 type=0 length=75

D (1845323) wpa: SSL: Received packet(len=75) - Flags 0x00
D (1845323) wpa: EAP-PEAP: received 69 bytes encrypted data for Phase 2

D (1845333) wpa: TLSv1: Received content type 23 version 3.1 length 64
D (1845333) wpa: EAP-PEAP: received Phase 2: code=1 identifier=10 length=34

D (1845343) wpa: EAP-PEAP: Phase 2 Request: type=26

D (1845343) wpa: EAP-PEAP: Selected Phase 2 EAP vendor 0 method 26

D (1845353) wpa: EAP-MSCHAPV2: RX identifier 10 mschapv2_id 10

D (1845363) wpa: EAP-MSCHAPV2: Generate Challenge Response

D (1845363) wpa: SSL: 101 bytes left to be sent out (of total 101 bytes)
D (1845373) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845373) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845423) wpa: IEEE 802.1X RX: version=2 type=0 length=91

D (1845423) wpa: SSL: Received packet(len=91) - Flags 0x00
D (1845423) wpa: EAP-PEAP: received 85 bytes encrypted data for Phase 2

D (1845433) wpa: TLSv1: Received content type 23 version 3.1 length 80
D (1845433) wpa: EAP-PEAP: received Phase 2: code=1 identifier=11 length=51

D (1845443) wpa: EAP-PEAP: Phase 2 Request: type=26

D (1845443) wpa: EAP-MSCHAPV2: RX identifier 11 mschapv2_id 10

D (1845453) wpa: SSL: 37 bytes left to be sent out (of total 37 bytes)
D (1845463) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845463) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845503) wpa: IEEE 802.1X RX: version=2 type=0 length=107

D (1845503) wpa: SSL: Received packet(len=107) - Flags 0x00
D (1845503) wpa: EAP-PEAP: received 101 bytes encrypted data for Phase 2

D (1845503) wpa: TLSv1: Received content type 23 version 3.1 length 96
D (1845513) wpa: EAP-PEAP: received Phase 2: code=1 identifier=13 length=71

D (1845523) wpa: EAP-PEAP: Phase 2 Request: type=33

D (1845523) wpa: EAP-PEAP: Valid cryptobinding TLV received
I (1845533) wpa: EAP-TLV: TLV Result - Success - EAP-TLV/Phase2 Completed
D (1845533) wpa: SSL: 101 bytes left to be sent out (of total 101 bytes)
D (1845543) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845553) wpa: WPA2: wpa2 api return, sm->state(1)
D (1845593) wpa: IEEE 802.1X RX: version=2 type=0 length=4

I (1845593) wpa: >>>>>wpa2 FINISH

D (1845593) wpa: TLSv1: Selected cipher suite: 0x0000
D (1845603) wpa: TLSv1: Record Layer - New write cipher suite 0x0000
D (1845603) wpa: TLSv1: Record Layer - New read cipher suite 0x0000 

D (1845613) wpa: WPA2: wifi->wpa2 api completed sig(1)
D (1845613) wpa: WPA2: wpa2 api return, sm->state(2)
D (1845623) wpa: IEEE 802.1X RX: version=2 type=3 length=117

D (1845623) wpa:   EAPOL-Key type=2

D (1845633) wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

D (1845633) wpa:   key_length=16 key_data_length=22

D (1845643) wpa: WPA 1/4-Way Handshake

D (1845643) wpa: WPA: PTK derivation - A1=84:0d:8e:1b:e8:a0 A2=XX:XX:XX:XX:XX:XX

D (1845653) wpa: WPA Send EAPOL-Key 2/4

D (1845663) wpa: IEEE 802.1X RX: version=2 type=3 length=151

D (1845663) wpa:   EAPOL-Key type=2

D (1845663) wpa:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)

D (1845673) wpa:   key_length=16 key_data_length=56

D (1845683) wpa: WPA 3/4-Way Handshake

D (1845683) wpa: WPA: No WPA/RSN IE for this AP known. Trying to get from scan results

D (1845693) wpa: WPA: Found the current AP from updated scan results

D (1845693) wpa: tx 4/4 txcb_flags=8192

D (1845703) wpa: WPA Send EAPOL-Key 4/4

D (1845703) wpa: WPA: Installing PTK to the driver.

D (1845703) wpa: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=16).

D (1845713) wpa: WPA: Key negotiation completed with XX:XX:XX:XX:XX:XX [PTK=CCMP GTK=CCMP]

I (1845723) wifi: connected with CENSORED, channel 1, BW20, bssid = XX:XX:XX:XX:XX:XX
I (1845733) wifi: pm start, type: 1

I think

D (1840483) wpa: WPA Send EAPOL-Key 2/4

Is the last event before it goes haywire

@sagb2015
Copy link
Contributor

It appears 2/4 message of 4-way hanshake sent by ESP32 is not received by Cisco AP since it is retrying message 1/4. Is it possible for you to provide a sniffer capture for re-authentication failure case?

@PaulFreund
Copy link

PaulFreund commented Sep 17, 2019

At the moment not unfortunately but to me it looks like the AP is actually replying to the 2/4 but with a different payload:

Working:

wpa: WPA Send EAPOL-Key 2/4
wpa: IEEE 802.1X RX: version=2 type=3 length=151
wpa:   EAPOL-Key type=2
wpa:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
wpa:   key_length=16 key_data_length=56

Not working:

wpa: WPA Send EAPOL-Key 2/4
wpa: IEEE 802.1X RX: version=2 type=3 length=117
wpa:   EAPOL-Key type=2
wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
wpa:   key_length=16 key_data_length=22

There is a difference of 34 bytes in the key data length coming from the AP and the key info in working case is "Pairwise Install Ack MIC Secure Encr" instead of the non working "Pairwise Ack", which means in key_info

WPA_KEY_INFO_INSTALL
WPA_KEY_INFO_MIC
WPA_KEY_INFO_SECURE
WPA_KEY_INFO_ENCR_KEY_DATA

are not set. I would still need to read the specification about that points but it seems to me that in one case (the first one) the router wants to install and therefore includes more information in the key data and in the second case it expects the information to be already present.

@PaulFreund
Copy link

If I am not mistaken we are in the wpa_sm_rx_eapol function of wpa.c (line 1495) where the output of the log information is wpa_eapol_key_dump (line 1558) and later there is the check starting at line 1658:

        if (key_info & WPA_KEY_INFO_MIC) {
            /* 3/4 4-Way Handshake */
            wpa_supplicant_process_3_of_4(sm, key, ver);
        } else {
            /* 1/4 4-Way Handshake */
            wpa_supplicant_process_1_of_4(sm, src_addr, key,
                              ver);
        }

as WPA_KEY_INFO_KEY_TYPE is set (Pairwise is in the log) and MIC not this should be the reason why wpa jumps back to step 1.

@sagb2015
Copy link
Contributor

@PaulFreund - In the failure case, the router did not get message 2/4 from ESP32. So it is retrying by sending 1/4 to ESP32 again. "Pairwise Ack" case is actually msg 1 out of 4. To check why 2/4 was not received by router a sniffer capture would have helped a lot. For 4-way handhshake, you can refer to this article.

@PaulFreund
Copy link

I want to make sure we are really on the same page, here is a diff of the working case vs the non working case: http://www.mergely.com/i6XsuLvv/ with exactly the same starting point in the sequence but different outcome:

Small breakdown of the logs:

D () wpa: IEEE 802.1X RX: version=2 type=3 length=117
D () wpa:   EAPOL-Key type=2
D () wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
D () wpa:   key_length=16 key_data_length=22

This should be the AP sending the ANonce, initiating the handshake. "IEEE 802.1X RX" indicates that this comes from the wpa_supplicant receive function which means the data comes from the AP

D () wpa: WPA 1/4-Way Handshake
D () wpa: WPA: PTK derivation - A1=84:0d:8e:XX:XX:XX A2=XX:XX:XX:XX:XX:XX
D () wpa: WPA Send EAPOL-Key 2/4

Here the client uses the information to derive the PTK and sends the MIC to the AP (wpa_supplicant_send_2_of_4 function).

Until here both logs are 100% identical, AP sent ANonce, STA sent MIC and then in both logs the STA receives an answer (indicated by "IEEE 802.1X RX"). In the working log this is:

D () wpa: IEEE 802.1X RX: version=2 type=3 length=151
D () wpa:   EAPOL-Key type=2
D () wpa:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
D () wpa:   key_length=16 key_data_length=56

Which means that the EAPOL message includes the MIC and the status changed for installed key, secure and encrypted connection.

In the re-authentication log the next message we get from the AP is again identical to the start of the handshake and does not include the flags we expect.

D () wpa: IEEE 802.1X RX: version=2 type=3 length=117
D () wpa:   EAPOL-Key type=2
D () wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
D () wpa:   key_length=16 key_data_length=22

As this behaviour is 100% consistent for all re-authentication tries (I logged in the hundereds) I am pretty sure the AP actually receives the message but is not happy with the message flow and therefore restarts. Maybe there is some alternative flow for the handshake in case of a re-authentication. For actual sniffing I need more time.

@PaulFreund
Copy link

PaulFreund commented Sep 18, 2019

I did not find free access to the full spec yet but I found this:

NOTE: The EAPOL frame is silently discarded by the 802.11 Station/AP if the Key Sequence counter value in a particular EAPOL frame received was already sent in a previous EAPOL frame or the MIC received by either party is not properly decoded. No indication of failure is reported to the sender of the EAPOL frame

Just as an idea, are we starting/continue with a new sequence counter for this transaction or are we incrementing the one from the last transaction? Maybe the CISCO AP expects we continue with an increment of the last counter value from the previous transaction or the other way around and other AP's don't check this.

@ghost
Copy link
Author

ghost commented Oct 14, 2019

After seeing that @PaulFreund still had issues with the fix for this issue I looked more closely at some sniffer logs from the tests I did to confirm this issue was solved. Then found that I was wrong. The fix (3b606aa) does handle re-authentication but not the way it should be done. The re-authentication shall be done with frame exchange encrypted with currrent keys. esp-idf do all 4-way handshakes unencrypted. Only the initial one can be.

Please see the attached logs and sniffer logs. Sniffer logs for both a test with wpa_supplicant under linux and with esp_supplicant attached.

For decryption with Wireshark the following PMKs can be used:

wpa_supplicant:
18b069d3a262256e2bd2aa1eb64518f894edc59b64f15774efa26cf66a67e97b
6f0ee8d2a59d3a7e27c282dab58c163d58bdba70eb7bcd78a7a0f9f6c7a25632

esp_supplicant:
4f30904463755fcf4a17d8fb56923c80ec782887852c6fc0ef52ced6cdd03107
7b3e4601eb7cff34c1f714adc9d9f622770c08a817b6619af24b630ca6f11a76
44902000134fcab831cf14f7c280aeae229034f5d9487974a77b5d213a49a349

Compare unencrypted 4-way handshake messages 2/4 and 4/4 from ESP in esp_supplicant.pcapng: 102, 103, 104, 127, 129, 131, 132

With same frames encrypted with wpa_supplicant.pcapng frames: 268, 270

logs.tar.gz

@sagb2015
Copy link
Contributor

@mikaelkanstrup Thanks for testing this. I am reopening the issue. The spec is not very explicit about encryption of re-authentication EAP frames. I found the following statement in the spec which is consistent with your expectation. "This standard assumes that IEEE Std 802.1X-2010 does not block the Controlled Port when authentication is triggered through reauthentication. During IEEE 802.1X reauthentication, an existing RSNA can protect all MSDUs exchanged between the STAs. Blocking MSDUs is not required during reauthentication over an RSNA." Theoretically, the security o f re-authentication without encryption should be as good as during first authentication as 802.1x does not distinguish between the two during the handshake.

@sagb2015 sagb2015 reopened this Oct 14, 2019
@ghost
Copy link
Author

ghost commented Oct 14, 2019

@sagb2015 Thanks, agree that "the security of re-authentication without encryption should be as good as during first authentication". However as EAPOL Key frames are transferred as data frames I think IEEE 802.11-2016 Chapter 12.9 Per-frame (and sub-chapters) rules should apply here.

Check:
12.9.2.4 Per-MPDU Tx pseudocode
12.9.2.6 Per-MPDU Rx pseudocode

These I interpret as when dot11RSNAActivated=true:

  • TX frames shall be encrypted with TK
  • RX plain text frames shall be discarded.

@PaulFreund
Copy link

@sagb2015 Can you create a test branch with this suggestion? I would like to test it as soon as possible.

@PaulFreund
Copy link

PaulFreund commented Nov 13, 2019

Sorry for bumping, I might have the chance for integration in a broader infrastructure soon which will most likely require this to work and it seems that the solution is near. Can we follow up on this please?

@sagb2015
Copy link
Contributor

We have fixed this internally. Unfortunately, it may take some time to be available on github. Hoping to get it done by early next week.

@PaulFreund
Copy link

I'm really, really sorry to bump this again but are there any updates?

@sagb2015
Copy link
Contributor

sagb2015 commented Dec 2, 2019

And I am sorry that we could not make the fix available sooner. We have quite a CI backlog internally, We will prioritise this and get it merged this week.

@sagb2015
Copy link
Contributor

sagb2015 commented Dec 5, 2019

Hi @PaulFreund, We still have a lot of CI backlog, so this may take some more time. Can you use this lib for testing at commit 93a8603? This way you can get unblocked.

@PaulFreund
Copy link

@sagb2015 Thank you very much! Unfortunately it seems (at least with the old make system) librtc.a is missing
make: *** No rule to make target '/CENSORED/esp-idf/components/esp_wifi/lib/esp32/librtc.a', needed by '/CENSORED/build/CENSORED.elf'. Stop.

git rev-parse HEAD shows
93a8603

only the lib content has been modified

@sagb2015
Copy link
Contributor

sagb2015 commented Dec 5, 2019

Please keep the librtc.a same. Just replace the files, do not delete existing ones.

@PaulFreund
Copy link

Perfect, so far we are a little bit over 30 minutes and I did not have a disconnect, I'm hopeful :)

@PaulFreund
Copy link

Okay I have to investigate a little more, after one hour the device is no longer online at all. I will get back to you.

@PaulFreund
Copy link

Okay maybe it was really a connection issue, now I'm running three hours without problems, I'll keep you updated :) I will roll out the test firmware on more devices tomorrow

@PaulFreund
Copy link

:) Looks good! I had 5 devices running over the weekend and three didn't have any reconnect at all. The other two had a few but without any relation to the half hour seen before. I think they just have worse reception (office complex). Thank you so much! Please keep me updated on merging to master/release

@sagb2015
Copy link
Contributor

sagb2015 commented Dec 9, 2019

Thanks for the update! We will keep you posted.

@sagb2015
Copy link
Contributor

This is now available on master 04e024b

@sagb2015
Copy link
Contributor

Feel free to re-open in case of issues.

@PaulFreund
Copy link

With your linked master commit 04e024b I was able to observe both, working and non-working re-authentication. this is shortly before the logs differ:

Working

wpa: WPA 1/4-Way Handshake
wpa: RSN: msg 1/4 key data - hexdump(len=22):
wpa: RSN: Replace PMKSA entry for the current AP and any PMKSA cache entry that was based on the old PMK
wpa: RSN: PMKSA cache entry free_cb: CE:NS:OR:ED:00:02 reason=1
wpa: RSN: replaced current PMKSA entry
wpa: RSN: Added PMKSA cache entry for CE:NS:OR:ED:00:02 network_ctx=0x0
wpa: RSN: the new PMK matches with the PMKID
wpa: RSN: PMKSA cache search - network_ctx=0x0 try_opportunistic=0
wpa: RSN: Search for BSSID CE:NS:OR:ED:00:02
wpa: WPA: PTK derivation - A1=CE:NS:OR:ED:00:01 A2=CE:NS:OR:ED:00:02
wpa: WPA: PMK - hexdump(len=32):
wpa: WPA: PTK - hexdump(len=48):
wpa: WPA: WPA IE for msg 2/4
 - hexdump(len=22):
wpa: WPA Send EAPOL-Key 2/4
wpa: WPA: TX EAPOL-Key - hexdump(len=121):
wpa: IEEE 802.1X RX: version=2 type=3 length=151
wpa:   EAPOL-Key type=2
wpa:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
wpa:   key_length=16 key_data_length=56
wpa: WPA: RX EAPOL-Key - hexdump(len=155):
wpa: WPA 3/4-Way Handshake
wpa: WPA: No WPA/RSN IE for this AP known. Trying to get from scan results
wpa: WPA: Found the current AP from updated scan results
wpa: tx 4/4 txcb_flags=8192
wpa: WPA Send EAPOL-Key 4/4
wpa: WPA: TX EAPOL-Key - hexdump(len=99):
wpa: WPA: Installing PTK to the driver.
wpa: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=16).
wpa: WPA: Key negotiation completed with CE:NS:OR:ED:00:02 [PTK=CCMP GTK=CCMP]
esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffdfde4
esp_netif_lwip: if0x3ffdfd4c ip unchanged

Not working

wpa: WPA 1/4-Way Handshake
wpa: RSN: msg 1/4 key data - hexdump(len=22):
wpa: RSN: Replace PMKSA entry for the current AP and any PMKSA cache entry that was based on the old PMK
wpa: RSN: PMKSA cache entry free_cb: CE:NS:OR:ED:00:02 reason=1
wpa: RSN: replaced current PMKSA entry
wpa: RSN: Added PMKSA cache entry for CE:NS:OR:ED:00:02 network_ctx=0x0
wpa: RSN: the new PMK matches with the PMKID
wpa: RSN: PMKSA cache search - network_ctx=0x0 try_opportunistic=0
wpa: RSN: Search for BSSID CE:NS:OR:ED:00:02
wpa: WPA: PTK derivation - A1=CE:NS:OR:ED:00:01 A2=CE:NS:OR:ED:00:02
wpa: WPA: PMK - hexdump(len=32):
wpa: WPA: PTK - hexdump(len=48):
wpa: WPA: WPA IE for msg 2/4
 - hexdump(len=22):
wpa: WPA Send EAPOL-Key 2/4
wpa: WPA: TX EAPOL-Key - hexdump(len=121):
wpa: IEEE 802.1X RX: version=2 type=3 length=151
wpa:   EAPOL-Key type=2
wpa:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
wpa:   key_length=16 key_data_length=56
wpa: WPA: RX EAPOL-Key - hexdump(len=155):
wpa: WPA 3/4-Way Handshake
wpa: WPA: No WPA/RSN IE for this AP known. Trying to get from scan results
wpa: WPA: Found the current AP from updated scan results
wpa: tx 4/4 txcb_flags=8192
wpa: WPA Send EAPOL-Key 4/4
wpa: WPA: TX EAPOL-Key - hexdump(len=99):
wpa: WPA: Installing PTK to the driver.
wpa: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=16).
wpa: WPA: Key negotiation completed with CE:NS:OR:ED:00:02 [PTK=CCMP GTK=CCMP]
wifi: state: run -> init (fc0)
wifi: pm stop, total sleep time: 3091882043 us / 5440416651 us
wpa: WPA2: queue deleted
wpa: WPA2: task deleted
wpa: WPA2: wifi->wpa2 api completed sig(2)
wpa: WPA2: wpa2 api return, sm->state(2)
wpa: wpa2 eap_peer_sm_deinit: free data lock
wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
event: running post WIFI_EVENT:5 with handler 0x40118df8 on loop 0x3ffd7430
esp_netif_handlers: esp_netif action disconnected with netif0x3ffdfd4c from event_id=5
esp_netif_lwip: check: remote, if=0x3ffdfd4c fn=0x40118940
esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffdfd4c
esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffdfde4
esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffdfd4c
esp_netif_lwip: if0x3ffdfd4c start ip lost tmr: interval=120
esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffdfd4c
esp_netif_lwip: if0x3ffdfd4c start ip lost tmr: already started
esp_netif_lwip: call api in lwip: ret=0x0, give sem
event: running post SYSTEM_EVENT:5 with handler 0x40115cb4 on loop 0x3ffd7430
DriverESP32Wifi: STA disconnected (15)
event: handler already registered, overwriting
event: handler already registered, overwriting
wpa: WPA2: already enabled
esp_netif_lwip: check: remote, if=0x3ffdfd4c fn=0x40118228
esp_netif_lwip: esp_netif_set_hostname_api esp_netif:0x3ffdfd4c hostname CENSORED
esp_netif_lwip: call api in lwip: ret=0x0, give sem

I just see a sudden change in state but nothing else with debug level. Once I am able to use the most recent master I will try to get some more data.

@sagb2015
Copy link
Contributor

Seems like connection station lost AP connection in the failure case. I do not think it is related to EAP (re)authentication.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants