Opportunistic Key Caching on wpa_supplicant

Matt Causey matt.causey at gmail.com
Wed Sep 21 21:26:45 EDT 2011 

>> On Wed, Sep 21, 2011 at 05:05:59PM -0400, Matt Causey wrote:
>>> > Which WLAN driver are you using? If the 0.8.x snapshot does not fix
>>> > this, please provide verbose debug log from wpa_supplicant (-ddt on
>>> > command line; or -ddKt if this is a test network and you don't care
>>> > about revealing passwords/keys etc. private information).
>>
>>> We're running with -onl80211, using the vanilla ath9k code in our
>>> kernel version.
>>>
>>> This version seems to roam flawlessly.   How much testing has this
>>> version of code seen?
>>>
>>> Just FYI, I've posted the output from out controller below, in case it
>>> is helpful.
>>
>> Interesting.. It is unclear from those logs what exactly was causing the
>> problem in 0.7.3. The fixes I've done in 0.8.x branch should have
>> addressed somewhat different issues.
>>
>
> Hum.  Well since you said that, I decided to test _again_ with the
> latest stable, and I cannot reproduce the problem.
>
> So, to fill in some detail that I left out initially, I did have this
> work on the latest stable, but something changed and fast roaming
> stopped working.   Restarting the daemon and various other steps would
> not cause it to work again.  And now that I've gone back to test, it's
> working again...on the old code.  It makes me sad that it is
> inconsistent and I don't know what variable is changing.  It's not
> even clear if it is the controller failing or the supplicant.
>
> In the middle of writing this I moved the client around to cause a
> roam and it re-auth'd with RADIUS....so I'm seeing some sort of
> inconsistent failure of fast roaming.  Here is what the supplicant
> says:
>
> Setting authentication timeout: 70 sec 0 usec
> RSN: Authenticator did not accept PMKID, doing full EAP authentication
> EAPOL: Supplicant port status: Unauthorized
>

So this time, I was constantly re-authing successfully until the PMK
expiration timer on the controller fired, and nuked the PMK for my
station.  After that, all of the supplicant's attempts to use its
internal PMK would fail.

Here is the log entry from the controller's side, of the PMK getting
nuked (mostly FYI, just in case it's helpful):

*apfPmkCacheTimer: Sep 22 02:18:04.433: 1c:65:9d:e5:d3:46 Removing
expired PMK cache entry for station 1c:65:9d:e5:d3:46 AKM
was:APF_KEY_MGMT_80211i
*apfReceiveTask: Sep 22 02:18:04.433: 1c:65:9d:e5:d3:46 Initiating
802.1x due to PMK Timeout Event for STA
*dot1xMsgTask: Sep 22 02:18:04.433: 1c:65:9d:e5:d3:46 dot1x - moving
mobile 1c:65:9d:e5:d3:46 into Connecting state
*dot1xMsgTask: Sep 22 02:18:04.433: 1c:65:9d:e5:d3:46 Sending
EAP-Request/Identity to mobile 1c:65:9d:e5:d3:46 (EAP Id 1)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.435: 1c:65:9d:e5:d3:46 Received
EAPOL EAPPKT from mobile 1c:65:9d:e5:d3:46

<snip lots of RADIUS traffic>

*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.679: 1c:65:9d:e5:d3:46 Received
EAP Response from mobile 1c:65:9d:e5:d3:46 (EAP Id 10, EAP Type 13)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.679: 1c:65:9d:e5:d3:46 Entering
Backend Auth Response state for mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Processing
Access-Accept for mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Setting
re-auth timeout to 1800 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Station
1c:65:9d:e5:d3:46 setting dot1x reauth timeout = 1800
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Creating a
PKC PMKID Cache entry for station 1c:65:9d:e5:d3:46 (RSN 2)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Adding
BSSID 04:fe:7f:48:db:29 to PMKID cache for station 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: New PMKID: (16)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683:      [0000] c5 88 3d 3c 34
37 02 35 ba 52 c8 a2 24 9e 97 bf
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.683: 1c:65:9d:e5:d3:46 Disabling
re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 PMK sent
to mobility group
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 Sending
EAP-Success to mobile 1c:65:9d:e5:d3:46 (EAP Id 10)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: Including PMKID in M1  (16)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684:      [0000] c5 88 3d 3c 34
37 02 35 ba 52 c8 a2 24 9e 97 bf
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 Starting
key exchange to mobile 1c:65:9d:e5:d3:46, data packets will be dropped
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 Sending
EAPOL-Key Message to mobile 1c:65:9d:e5:d3:46

                                             state INITPMK (message
1), replay counter 00.00.00.00.00.00.00.02
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 Entering
Backend Auth Success state (id=10) for mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 Received
Auth Success while in Authenticating state for mobile
1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.684: 1c:65:9d:e5:d3:46 dot1x -
moving mobile 1c:65:9d:e5:d3:46 into Authenticated state
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.689: 1c:65:9d:e5:d3:46 Received
EAPOL-Key from mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.689: 1c:65:9d:e5:d3:46 Ignoring
invalid EAPOL version (1) in EAPOL-key message from mobile
1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.689: 1c:65:9d:e5:d3:46 Received
EAPOL-key in PTK_START state (message 2) from mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.689: 1c:65:9d:e5:d3:46 Stopping
retransmission timer for mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.690: 1c:65:9d:e5:d3:46 Sending
EAPOL-Key Message to mobile 1c:65:9d:e5:d3:46

                                             state PTKINITNEGOTIATING
(message 3), replay counter 00.00.00.00.00.00.00.03
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 Received
EAPOL-Key from mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 Ignoring
invalid EAPOL version (1) in EAPOL-key message from mobile
1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 Received
EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile
1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 STA
[1c:65:9d:e5:d3:46, 10.9.9.90] Deleting Fast Path Rule (8021X_AUTH)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 apfMsRunStateDec
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 apfMs1xStateDec
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Change state to 8021X_REQD (3) last state RUN (20)
*pemReceiveTask: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
Removed NPU entry.
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 apfMs1xStateInc
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 04:fe:7f:48:db:20
vapId 7 apVapId 7
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 apfMsRunStateInc
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Reached PLUMBFASTPATH: from line 4604
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Adding Fast Path rule
  type = Airespace AP Client
  on AP 04:fe:7f:48:db:20, slot 1, interface = 13, QOS = 0
  ACL Id = 255, Jumbo Frames = NO
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID =
7006  IPv6 Vlan = 9, IPv6 intf id = 13
*Dot1x_NW_MsgTask_6: Sep 22 02:18:04.693: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Successfully plumbed mobile rule (ACL ID 255)


I would expect though, that after the station successfully re-auths,
it should update its PMK so that future attempts to re-auth with it
succeed.  But it doesn't look like it is doing that.  Do you have any
ideas?

Thanks!

--
Matt

More information about the HostAP mailing list