Opportunistic Key Caching on wpa_supplicant
Matt Causey
matt.causey
Wed Sep 21 14:05:59 PDT 2011
Cheers for you response!
On Wed, Sep 21, 2011 at 3:24 PM, Jouni Malinen <j at w1.fi> wrote:
> On Wed, Sep 21, 2011 at 01:24:07PM -0400, Matt Causey wrote:
>> I'm running linux 2.38.2, and wpa_supplicant 0.7.3 with the following .config:
>
> I would suggest running a quick test with the current development
> snapshot from hostap.git (0.8.x). There has been some fixes in PMKSA
> caching and OKC recently and I'm not sure whether they would affect
> 0.7.3.
>
>> What it looks like is that the supplicant is providing a key that does
>> not match what the controller is expecting, and so it fails and causes
>> re-auth. ?What data do I need to collect to understand what this is
>> happening? ?It is predictable, as I have a small test network with a
>> single controller with 2 access points. ?Anytime I roam between them,
>> it re-auths.....and I'm not sure how to diagnose from here.
>
> 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.
Cheers
(Cisco Controller) >*pemReceiveTask: Sep 21 21:58:43.393:
1c:65:9d:e5:d3:46 10.9.9.90 Added NPU entry of type 1, dtlFlags 0x0
*apfMsConnTask_6: Sep 21 22:00:59.966: 1c:65:9d:e5:d3:46 Reassociation
received from mobile on AP 04:fe:7f:48:db:20
*apfMsConnTask_6: Sep 21 22:00:59.966: 1c:65:9d:e5:d3:46 10.9.9.90 RUN
(20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) ---
(caller apf_policy.c:1393)
*apfMsConnTask_6: Sep 21 22:00:59.966: 1c:65:9d:e5:d3:46 Applying
site-specific IPv6 override for station 1c:65:9d:e5:d3:46 - vapId 7,
site 'default-group', interface 'vlan9'
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 10.9.9.90 RUN
(20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) ---
(caller apf_policy.c:1393)
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Applying IPv6
Interface Policy for station 1c:65:9d:e5:d3:46 - vlan 9, interface id
13, interface 'vlan9'
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 STA - rates
(8): 12 18 24 36 48 72 96 108 0 0 0 0 0 0 0 0
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Processing
RSN IE type 48, length 38 for mobile 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Received RSN
IE with 1 PMKIDs from mobile 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: Received PMKID: (16)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 27 32 98 c7 f9 cb
c8 87 d2 05 ed 9d 66 ff 9e 21
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 No valid
PMKID found in the cache for mobile 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: CCKM: Find PMK in cache: BSSID = (6)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 04 fe 7f 48 db 20
*apfMsConnTask_6: Sep 21 22:00:59.967: CCKM: Find PMK in cache: realAA = (6)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 04 fe 7f 48 db 29
*apfMsConnTask_6: Sep 21 22:00:59.967: CCKM: Find PMK in cache: PMKID = (16)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 27 32 98 c7 f9 cb
c8 87 d2 05 ed 9d 66 ff 9e 21
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Unable to
compute a valid PMKID from dot1x PMK cache for mobile
1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Found an
entry in the global PMK cache for station 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: CCKM: AA (6)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 04 fe 7f 48 db 29
*apfMsConnTask_6: Sep 21 22:00:59.967: CCKM: SPA (6)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 1c 65 9d e5 d3 46
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 computed a
valid PMKID from global PMK cache for mobile 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Creating a
PKC PMKID Cache entry for station 1c:65:9d:e5:d3:46 (RSN 0) on BSSID
04:fe:7f:48:db:29
*apfMsConnTask_6: Sep 21 22:00:59.967: 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
*apfMsConnTask_6: Sep 21 22:00:59.967: New PMKID: (16)
*apfMsConnTask_6: Sep 21 22:00:59.967: [0000] 27 32 98 c7 f9 cb
c8 87 d2 05 ed 9d 66 ff 9e 21
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 10.9.9.90 RUN
(20) Deleted mobile LWAPP rule on AP [00:24:14:ff:0c:10]
*pemReceiveTask: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 10.9.9.90
Removed NPU entry.
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 Updated
location for station old AP 00:24:14:ff:0c:10-1, new AP
04:fe:7f:48:db:20-1
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 apfMsRunStateDec
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 apfMs1xStateDec
*apfMsConnTask_6: Sep 21 22:00:59.967: 1c:65:9d:e5:d3:46 10.9.9.90 RUN
(20) Change state to START (0) last state RUN (20)
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 10.9.9.90
START (0) Initializing policy
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 10.9.9.90
START (0) Change state to AUTHCHECK (2) last state RUN (20)
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 10.9.9.90
AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 10.9.9.90
8021X_REQD (3) Plumbed mobile LWAPP rule on AP 04:fe:7f:48:db:20 vapId
7 apVapId 7
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46
apfPemAddUser2 (apf_policy.c:222) Changing state for mobile
1c:65:9d:e5:d3:46 on AP 04:fe:7f:48:db:20 from Associated to
Associated
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 Stopping
deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46 Sending Assoc
Response to station on BSSID 04:fe:7f:48:db:20 (status 0)
*apfMsConnTask_6: Sep 21 22:00:59.968: 1c:65:9d:e5:d3:46
apfProcessAssocReq (apf_80211.c:4587) Changing state for mobile
1c:65:9d:e5:d3:46 on AP 04:fe:7f:48:db:20 from Associated to
Associated
*dot1xMsgTask: Sep 21 22:00:59.969: 1c:65:9d:e5:d3:46 Initiating RSN
with existing PMK to mobile 1c:65:9d:e5:d3:46
*dot1xMsgTask: Sep 21 22:00:59.969: 1c:65:9d:e5:d3:46 Disable re-auth,
use PMK lifetime.
*dot1xMsgTask: Sep 21 22:00:59.969: 1c:65:9d:e5:d3:46 dot1x - moving
mobile 1c:65:9d:e5:d3:46 into Force Auth state
*dot1xMsgTask: Sep 21 22:00:59.969: 1c:65:9d:e5:d3:46 Skipping
EAP-Success to mobile 1c:65:9d:e5:d3:46
*dot1xMsgTask: Sep 21 22:00:59.969: Including PMKID in M1 (16)
*dot1xMsgTask: Sep 21 22:00:59.969: [0000] 27 32 98 c7 f9 cb c8
87 d2 05 ed 9d 66 ff 9e 21
*dot1xMsgTask: Sep 21 22:00:59.969: 1c:65:9d:e5:d3:46 Starting key
exchange to mobile 1c:65:9d:e5:d3:46, data packets will be dropped
*dot1xMsgTask: Sep 21 22:00:59.969: 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.00
*Dot1x_NW_MsgTask_6: Sep 21 22:00:59.997: 1c:65:9d:e5:d3:46 Received
EAPOL-Key from mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 21 22:00:59.997: 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 21 22:00:59.997: 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 21 22:00:59.997: 1c:65:9d:e5:d3:46 Stopping
retransmission timer for mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 21 22:00:59.997: 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.01
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.003: 1c:65:9d:e5:d3:46 Received
EAPOL-Key from mobile 1c:65:9d:e5:d3:46
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.003: 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 21 22:01:00.003: 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 21 22:01:00.003: 1c:65:9d:e5:d3:46 apfMs1xStateInc
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.003: 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 21 22:01:00.003: 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 21 22:01:00.003: 1c:65:9d:e5:d3:46 apfMsRunStateInc
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.003: 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 21 22:01:00.003: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Reached PLUMBFASTPATH: from line 4604
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.003: 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 21 22:01:00.003: 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 21 22:01:00.004: 1c:65:9d:e5:d3:46 10.9.9.90
RUN (20) Successfully plumbed mobile rule (ACL ID 255)
*Dot1x_NW_MsgTask_6: Sep 21 22:01:00.004: 1c:65:9d:e5:d3:46 Stopping
retransmission timer for mobile 1c:65:9d:e5:d3:46
*pemReceiveTask: Sep 21 22:01:00.004: 1c:65:9d:e5:d3:46 10.9.9.90
Added NPU entry of type 1, dtlFlags 0x0
Cheers again,
--
Matt
More information about the Hostap
mailing list