wpa-supplicant 2.4 and "RSN: no PMKSA entry found"

Tue Jun 30 12:05:20 PDT 2015

Hello,

I'm having trouble with WPA-EAP and wpa_supplicant 2.4; I get deauth for local reason during EAPOL, probably due to PMKSA cache problem.
Using identical config with 2.1 and 2.3 successfully connects, while 2.4 fails.

I've compared wpa_supplicant -ddd output to find the following change:

(both)RSN: Added PMKSA cache entry for 00:04:96:68:71:31 network_ctx=(...)
(both)nl80211: Add PMKID for 00:04:96:68:71:31

(bad) wlp4s0: RSN: no PMKSA entry found - trigger full EAP authentication
(good)wlp4s0: RSN: the new PMK matches with the PMKID

Next: 2.3 and 2.1 succeed EAPOL, 2.4 prints out several lines, waits for 0.5s and deauths.

I inserted larger context of logs below.

Initially I've been looking for the source of the problem around card drivers, network manager etc., but a colleague of mine encountered today the same problem on Fedora 22 after wpa_supplicant 2.3->2.4 update. I checked against an 2.1 version, and bingo, connection established.

I observed the problem using Intel Dual Band Wireless-AC 7265 (iwlwifi iwlmvm, iwlwifi-7265D-12.ucode), with linux-4.1.0, gentoo.

Do I correctly blame wpa_supplicant for regression? If no, where else should I report the problem?

Regards,
Jan

================ wpa_supplicant v2.4 ================
wlp4s0: State: ASSOCIATED -> 4WAY_HANDSHAKE
wlp4s0: WPA: RX message 1 of 4-Way Handshake from 00:04:96:68:71:31 (ver=2)
RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
RSN: PMKID from Authenticator - hexdump(len=16): 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
wlp4s0: RSN: no matching PMKID found
EAPOL: Successfully fetched key (len=32)
EAPOL: Successfully fetched key (len=64)
WPA: PMK from EAPOL state machines - hexdump(len=32): [REMOVED]
RSN: Added PMKSA cache entry for 00:04:96:68:71:31 network_ctx=0x259daf0
nl80211: Add PMKID for 00:04:96:68:71:31
wlp4s0: RSN: no PMKSA entry found - trigger full EAP authentication
wlp4s0: RSN: Do not reply to msg 1/4 - requesting full EAP authentication
l2_packet_receive: src=00:04:96:68:71:31 len=121
wlp4s0: RX EAPOL from 00:04:96:68:71:31
RX EAPOL - hexdump(len=121): 01 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 02 ae 09 7c e1 c1 0f f2 93 6c 68 8a 16 c7 20 0c c2 73 11 32 52 80 09 09 f8 ff 34 a1 1d ab 49 71 f8 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines
wlp4s0: IEEE 802.1X RX: version=1 type=3 length=117
WPA: RX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 00 8a 00 10 00 00 00 00 00 00 00 02 ae 09 7c e1 c1 0f f2 93 6c 68 8a 16 c7 20 0c c2 73 11 32 52 80 09 09 f8 ff 34 a1 1d ab 49 71 f8 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 16 dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
wlp4s0:   EAPOL-Key type=2
wlp4s0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
wlp4s0:   key_length=16 key_data_length=22
  replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
  key_nonce - hexdump(len=32): ae 09 7c e1 c1 0f f2 93 6c 68 8a 16 c7 20 0c c2 73 11 32 52 80 09 09 f8 ff 34 a1 1d ab 49 71 f8
  key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
  key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
  key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
wlp4s0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
wlp4s0: WPA: RX message 1 of 4-Way Handshake from 00:04:96:68:71:31 (ver=2)
RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
RSN: PMKID from Authenticator - hexdump(len=16): 5b 61 2f 34 dd c5 23 d0 57 fa 57 be 9d 95 e8 f3
EAPOL: Successfully fetched key (len=32)
EAPOL: Successfully fetched key (len=64)
WPA: PMK from EAPOL state machines - hexdump(len=32): [REMOVED]
WPA: reusing previous PMKSA entry
Get randomness: len=32 entropy=11
random from os_get_random - hexdump(len=32): [REMOVED]
random_mix_pool - hexdump(len=20): [REMOVED]
random from internal pool - hexdump(len=16): [REMOVED]
random_mix_pool - hexdump(len=20): [REMOVED]
random from internal pool - hexdump(len=16): [REMOVED]
mixed random - hexdump(len=32): [REMOVED]
WPA: Renewed SNonce - hexdump(len=32): f0 b9 6c 0e 44 7c a5 f8 0e e5 b4 e9 26 c3 b4 a1 27 5e e5 39 e6 7b c7 0d 43 ff fc 47 25 0c 9d 02
WPA: PTK derivation - A1=60:57:18:7a:43:ba A2=00:04:96:68:71:31
WPA: Nonce1 - hexdump(len=32): f0 b9 6c 0e 44 7c a5 f8 0e e5 b4 e9 26 c3 b4 a1 27 5e e5 39 e6 7b c7 0d 43 ff fc 47 25 0c 9d 02
WPA: Nonce2 - hexdump(len=32): ae 09 7c e1 c1 0f f2 93 6c 68 8a 16 c7 20 0c c2 73 11 32 52 80 09 09 f8 ff 34 a1 1d ab 49 71 f8
WPA: PMK - hexdump(len=32): [REMOVED]
WPA: PTK - hexdump(len=48): [REMOVED]
WPA: KCK - hexdump(len=16): [REMOVED]
WPA: KEK - hexdump(len=16): [REMOVED]
WPA: TK - hexdump(len=16): [REMOVED]
WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
wlp4s0: WPA: Sending EAPOL-Key 2/4
WPA: KCK - hexdump(len=16): [REMOVED]
WPA: Derived Key MIC - hexdump(len=16): 17 72 0f b6 2b d3 6b 88 39 a0 c4 62 62 08 1a 14
WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 02 f0 b9 6c 0e 44 7c a5 f8 0e e5 b4 e9 26 c3 b4 a1 27 5e e5 39 e6 7b c7 0d 43 ff fc 47 25 0c 9d 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 17 72 0f b6 2b d3 6b 88 39 a0 c4 62 62 08 1a 14 00 16 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
RTM_NEWLINK: ifi_index=4 ifname=wlp4s0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003 ([UP])
nl80211: Event message available
nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlp4s0
nl80211: Delete station 00:04:96:68:71:31
nl80211: Event message available
nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlp4s0
nl80211: MLME event 39 (NL80211_CMD_DEAUTHENTICATE) on wlp4s0(60:57:18:7a:43:ba) A1=60:57:18:7a:43:ba A2=00:04:96:68:71:31
nl80211: MLME event frame - hexdump(len=26): c0 00 3a 01 60 57 18 7a 43 ba 00 04 96 68 71 31 00 04 96 68 71 31 60 8c 0f 00
nl80211: Deauthenticate event
wlp4s0: Event DEAUTH (12) received
wlp4s0: Deauthentication notification
wlp4s0:  * reason 15
wlp4s0:  * address 00:04:96:68:71:31
Deauthentication frame IE(s) - hexdump(len=0): [NULL]
wlp4s0: CTRL-EVENT-DISCONNECTED bssid=00:04:96:68:71:31 reason=15
=====================================================

================ wpa_supplicant v2.1 ================
wlp4s0: State: ASSOCIATED -> 4WAY_HANDSHAKE
wlp4s0: WPA: RX message 1 of 4-Way Handshake from 00:04:96:68:71:31 (ver=2)
RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 48 8e 54 f0 86 4a 7e ef 0e 07 f7 8c cf de 66 69
WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 48 8e 54 f0 86 4a 7e ef 0e 07 f7 8c cf de 66 69
RSN: PMKID from Authenticator - hexdump(len=16): 48 8e 54 f0 86 4a 7e ef 0e 07 f7 8c cf de 66 69
wlp4s0: RSN: no matching PMKID found
EAPOL: Successfully fetched key (len=32)
EAPOL: Successfully fetched key (len=64)
WPA: PMK from EAPOL state machines - hexdump(len=32): [REMOVED]
RSN: Added PMKSA cache entry for 00:04:96:68:71:31 network_ctx=0x200cf30
nl80211: Add PMKID for 00:04:96:68:71:31
wlp4s0: RSN: the new PMK matches with the PMKID
Get randomness: len=32 entropy=11
random from os_get_random - hexdump(len=32): [REMOVED]
random_mix_pool - hexdump(len=20): [REMOVED]
random from internal pool - hexdump(len=16): [REMOVED]
random_mix_pool - hexdump(len=20): [REMOVED]
random from internal pool - hexdump(len=16): [REMOVED]
mixed random - hexdump(len=32): [REMOVED]
WPA: Renewed SNonce - hexdump(len=32): e5 da c9 ce d0 d5 d5 f1 e2 8d 83 ee 7f 06 39 48 00 5c 39 91 bf 07 44 a9 86 e2 cf ba ac db 6f f8
WPA: PTK derivation - A1=60:57:18:7a:43:ba A2=00:04:96:68:71:31
WPA: Nonce1 - hexdump(len=32): e5 da c9 ce d0 d5 d5 f1 e2 8d 83 ee 7f 06 39 48 00 5c 39 91 bf 07 44 a9 86 e2 cf ba ac db 6f f8
WPA: Nonce2 - hexdump(len=32): d1 36 fe a1 60 ea 11 c6 08 60 e6 05 06 cb 5a 34 cc 08 96 bc 89 1a 6f a4 82 bd a8 2c 51 57 3f 44
WPA: PMK - hexdump(len=32): [REMOVED]
WPA: PTK - hexdump(len=48): [REMOVED]
WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 01 00 00
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
wlp4s0: WPA: Sending EAPOL-Key 2/4
=====================================================