Opportunistic Key Caching on wpa_supplicant

Matt Causey matt.causey
Wed Sep 21 10:24:07 PDT 2011 

Hello,

I'm running linux 2.38.2, and wpa_supplicant 0.7.3 with the following .config:

CONFIG_IEEE8021X_EAPOL=y
CONFIG_EAP_MD5=y
CONFIG_EAP_TLS=y
CONFIG_EAP_GTC=y
CONFIG_EAP_OTP=y
CONFIG_EAP_PSK=y
CONFIG_EAP_GPSK=y

CONFIG_DRIVER_WEXT=y
CONFIG_DRIVER_RALINK=y
CONFIG_DRIVER_IPW=y

CONFIG_BGSCAN_SIMPLE=y
CONFIG_CTRL_IFACE=y
CONFIG_DRIVER_NL80211=y
CONFIG_DEBUG_FILE=y
CONFIG_CTRL_IFACE_DBUS=y
CONFIG_READLINE=y

and the following wpa_supplicant.conf:

fast_reauth=0
ctrl_interface=/var/run/wpa_supplicant
network={
        proactive_key_caching=1
	ssid="wpa2"
        bgscan="simple:90:-65:300"
        freq_list=4915 4920 4925 4935 4940 4945 4960 4980 5035 5040
5045 5055 5060 5080 5170 5180 5190 5200 5210 5220 5230 5240 5260 5280
5300 5320 5500 5520 5540 5560 5580 5600 5620 5640 5660 5680 5700 5745
5765 5785 5805 5825
	identity="smeagol-prod"
	key_mgmt=WPA-EAP
	proto=WPA2
	pairwise=CCMP
	group=CCMP
	eap=TLS
	ca_cert="/etc/cert/root.pem"
	client_cert="/etc/cert/user_cert.pem"
	private_key="/etc/cert/user_key.pem"
	private_key_passwd="SECRET"
}

I have enabled opportunistic key caching on the infrastructure,
however it would appear that every time we roam, we re-auth against
RADIUS.

Here is what I see on the controller:

*apfMsConnTask_6: Sep 21 17:29:43.333: 1c:65:9d:e5:d3:46 Reassociation
received from mobile on AP 04:fe:7f:48:db:20
*apfMsConnTask_6: Sep 21 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: 1c:65:9d:e5:d3:46 Received RSN
IE with 1 PMKIDs from mobile 1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 17:29:43.333: Received PMKID:  (16)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 85 b6 41 19 53 e4
d9 64 50 06 5a 9d eb 81 46 41
*apfMsConnTask_6: Sep 21 17:29:43.333: 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 17:29:43.333: CCKM: Find PMK in cache: BSSID =  (6)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 04 fe 7f 48 db 20
*apfMsConnTask_6: Sep 21 17:29:43.333: CCKM: Find PMK in cache: realAA =  (6)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 04 fe 7f 48 db 29
*apfMsConnTask_6: Sep 21 17:29:43.333: CCKM: Find PMK in cache: PMKID =  (16)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 85 b6 41 19 53 e4
d9 64 50 06 5a 9d eb 81 46 41
*apfMsConnTask_6: Sep 21 17:29:43.333: 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 17:29:43.333: 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 17:29:43.333: CCKM: AA (6)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 04 fe 7f 48 db 29
*apfMsConnTask_6: Sep 21 17:29:43.333: CCKM: SPA (6)
*apfMsConnTask_6: Sep 21 17:29:43.333:      [0000] 1c 65 9d e5 d3 46
*apfMsConnTask_6: Sep 21 17:29:43.334: 1c:65:9d:e5:d3:46 Unable to
compute a valid PMKID from global PMK cache for mobile
1c:65:9d:e5:d3:46
*apfMsConnTask_6: Sep 21 17:29:43.334: 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 17:29:43.334: 1c:65:9d:e5:d3:46 10.9.9.90
Removed NPU entry.
*apfMsConnTask_6: Sep 21 17:29:43.334: 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 17:29:43.334: 1c:65:9d:e5:d3:46 apfMsRunStateDec
*apfMsConnTask_6: Sep 21 17:29:43.334: 1c:65:9d:e5:d3:46 apfMs1xStateDec
*apfMsConnTask_6: Sep 21 17:29:43.334: 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 17:29:43.334: 1c:65:9d:e5:d3:46 10.9.9.90
START (0) Initializing policy
*apfMsConnTask_6: Sep 21 17:29:43.334: 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 17:29:43.334: 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 17:29:43.334: 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 17:29:43.334: 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 17:29:43.334: 1c:65:9d:e5:d3:46 Stopping
deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_6: Sep 21 17:29:43.334: 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 17:29:43.334: 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 17:29:43.335: 1c:65:9d:e5:d3:46 Disable re-auth,
use PMK lifetime.
*dot1xMsgTask: Sep 21 17:29:43.335: 1c:65:9d:e5:d3:46 dot1x - moving
mobile 1c:65:9d:e5:d3:46 into Connecting state

<next block of messages pertains to the actual authentication with the
RADIUS service>

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.

Thanks for any ideas!

--
Matt

More information about the Hostap mailing list