Bug 1490885

Summary: NetworkManager's mac randomization can lead into MSK mismatch with hostapd and 802.1x
Product: Red Hat Enterprise Linux 7 Reporter: Vladimir Benes <vbenes>
Component: wpa_supplicantAssignee: Beniamino Galvani <bgalvani>
Status: CLOSED ERRATA QA Contact: Ken Benoit <kbenoit>
Severity: high Docs Contact:
Priority: unspecified    
Version: 7.4CC: bgalvani, sukulkar
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1582508 (view as bug list) Environment:
Last Closed: 2018-10-30 09:48:39 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1582508    
Attachments:
Description Flags
wpa_supplicant log
none
hostapd log
none
NetworkManager log none

Description Vladimir Benes 2017-09-12 12:24:18 UTC
Description of problem:
when using mac80211_hwsim wifi devices and hostapd with 8021.x authentication sometimes there is an error:

wlan0: RSN: PMKID mismatch - authentication server may have derived different MSK?!

this is caused by mac randomization in NM. Once this is turned of it works well.

Version-Release number of selected component (if applicable):


How reproducible:
NetworkManager-1.8.0-9.el7.x86_64
wpa_supplicant-2.6-5.el7.x86_64

it's reproducible with any test from simwifi area:
https://github.com/NetworkManager/NetworkManager-ci/blob/devel/vb/hostapd_wireless2/nmcli/features/wifi.feature#L30

Comment 1 Beniamino Galvani 2017-09-12 12:42:33 UTC
Created attachment 1324867 [details]
wpa_supplicant log

Comment 2 Beniamino Galvani 2017-09-12 12:42:57 UTC
Created attachment 1324868 [details]
hostapd log

Comment 3 Beniamino Galvani 2017-09-12 12:43:58 UTC
Created attachment 1324869 [details]
NetworkManager log

Comment 4 Beniamino Galvani 2017-09-12 12:47:48 UTC
Looking at logs, it can be seen that wpa_supplicant still thinks the
interface has the scan random MAC address 66:20:cf:ab:8c:dc, while
hostapd considers 02:00:00:00:00:00 as the STA MAC, leading to a
mismatch of the PMKID:

Sep 12 07:43:41 r5s11 hostapd[5241]: WPA: PMK from EAPOL state machine (MSK len=64 PMK len=32)
Sep 12 07:43:41 r5s11 hostapd[5241]: WPA: 02:00:00:00:00:00 WPA_PTK entering state PTKSTART
Sep 12 07:43:41 r5s11 hostapd[5241]: wlan1: STA 02:00:00:00:00:00 WPA: sending 1/4 msg of 4-Way Handshake
Sep 12 07:43:41 r5s11 hostapd[5241]: #### WPA: aa              - hexdump(len=6): 02 00 00 00 01 00
Sep 12 07:43:41 r5s11 hostapd[5241]: #### WPA: spa             - hexdump(len=6): 02 00 00 00 00 00
Sep 12 07:43:41 r5s11 hostapd[5241]: #### WPA: PMK             - hexdump(len=32): b5 24 76 4f 6f 50 8c f6 a1 2e 24 b8 07 4e 9a 13 1b 94 c4 a8 1f 7e 22 d6 ed fc 7d 43 c7 77 b6 f7
Sep 12 07:43:41 r5s11 hostapd[5241]: #### WPA: computed PMKID  - hexdump(len=16): d8 21 9d a5 73 98 88 26 ef 03 d2 ce f7 04 7d 23
Sep 12 07:43:41 r5s11 hostapd[5241]: WPA: Send EAPOL(version=1 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=22 keyidx=0 encr=0)

Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: wlan0: WPA: RX message 1 of 4-Way Handshake from 02:00:00:00:01:00 (ver=1)
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 d8 21 9d a5 73 98 88 26 ef 03 d2 ce f7 04 7d 23
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 d8 21 9d a5 73 98 88 26 ef 03 d2 ce f7 04 7d 23
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: RSN: PMKID from Authenticator - hexdump(len=16): d8 21 9d a5 73 98 88 26 ef 03 d2 ce f7 04 7d 23
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: wlan0: RSN: no matching PMKID found
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: EAPOL: Successfully fetched key (len=32)
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: WPA: PMK from EAPOL state machines - hexdump(len=32): [REMOVED]
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: #### WPA: aa              - hexdump(len=6): 02 00 00 00 01 00
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: #### WPA: spa             - hexdump(len=6): 66 20 cf ab 8c dc
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: #### WPA: PMK             - hexdump(len=32): b5 24 76 4f 6f 50 8c f6 a1 2e 24 b8 07 4e 9a 13 1b 94 c4 a8 1f 7e 22 d6 ed fc 7d 43 c7 77 b6 f7
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: #### WPA: computed PMKID  - hexdump(len=16): ea 73 67 b1 8e 5f 18 43 58 24 e8 1c 47 23 87 71
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: RSN: Replace PMKSA entry for the current AP and any PMKSA cache entry that was based on the old PMK
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: nl80211: Delete PMKID for 02:00:00:00:01:00
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: wlan0: RSN: PMKSA cache entry free_cb: 02:00:00:00:01:00 reason=1
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: RSN: Added PMKSA cache entry for 02:00:00:00:01:00 network_ctx=0x5630bf85a270
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: nl80211: Add PMKID for 02:00:00:00:01:00
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: wlan0: RSN: PMKID mismatch - authentication server may have derived different MSK?!
Sep 12 07:43:41 r5s11 wpa_supplicant[5214]: wlan0: Request to deauthenticate - bssid=02:00:00:00:01:00 pending_bssid=00:00:00:00:00:00 reason=1 state=4WAY_HANDSHAKE

Comment 5 Beniamino Galvani 2017-09-15 12:39:33 UTC
Posted patch upstream:

http://lists.infradead.org/pipermail/hostap/2017-September/037936.html

Comment 6 Beniamino Galvani 2018-04-03 08:32:46 UTC
Patch applied upstream:

https://w1.fi/cgit/hostap/commit/?id=77a020a118168e05e7cc0d28a7bf661772e531af

Comment 8 Ken Benoit 2018-09-21 12:17:05 UTC
Vladimir has run 300 loops of testing against wpa_supplicant-2.6-12.el7 and not had the issue initially reported. His testing against wpa_supplicant-2.6-9.el7 had failures every 20-50 runs. Given his results I'm going to mark this as verified. Thanks.

Comment 10 errata-xmlrpc 2018-10-30 09:48:39 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:3107