Opportunistic Key Caching on wpa_supplicant

[Matt Causey]

So, I know that all of you are super busy with, well probably your
real life.  :-)  But I was wondering if you have any ideas for how to
diagnose this issue further?  I'm at a place where the data points to
a bug in the supplicant somewhere, but I am not sure...

--
Matt


On Wed, Sep 21, 2011 at 9:26 PM, Matt Causey <matt.causey at gmail.com> wrote:
>>> 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
>