Understanding and Troubleshooting OKC Roaming on AireOS WLCs

By /
AireOS · OKC Troubleshooting Deep Dive

Understanding and Troubleshooting OKC Roaming on AireOS WLCs

This article explains Opportunistic Key Caching on an AireOS controller, correlates controller and access-point debugs with an over-the-air capture, and provides a practical workflow for troubleshooting PMKID validation and fast roaming.

Background and Components

  • Cisco 5520 Wireless Controller
  • AireOS 8.10.196
  • Cisco Catalyst 9130AXI AP
  • Cisco Aironet 2802I AP

OKC, often called Proactive Key Caching (PKC) in Cisco documentation, is a non-IEEE extension to WPA2-Enterprise PMKID caching. After the initial 802.1X/EAP authentication, the client and centralized WLAN infrastructure retain the PMK. For each target BSSID, both sides calculate the applicable PMKID and, when it validates, skip the full EAP exchange. A fresh WPA2 4-Way Handshake still derives a new PTK for the target AP association.

Initial Enterprise join:
802.11 association -> full EAP/802.1X -> PMK established -> 4-Way Handshake

Successful OKC roam:
802.11 reassociation + target PMKID -> PMKID validation -> 4-Way Handshake
(no full EAP method exchange)

Collect the Right Evidence

AireOS WLC CLI

debug client <client-mac>
debug mac addr <client-mac>
debug aaa detail enable

AP CLI

exec-timeout 0
debug client <client-mac>
terminal monitor

Enable the debugs before the test, synchronize clocks, record the client MAC, source and target BSSIDs, AP names, channels, WLAN ID, and test direction. Disable debugs afterward to avoid unnecessary controller and console load.

Initial Association: WLC Perspective

The controller sees the central association, EAP/RADIUS flow, PMK-cache creation, 4-Way Handshake, and policy state transitions. The AP must be joined to this controller for the controller to receive the relevant client events.

AireOS WLC: first association, full outputFull debug output
*apfOpenDtlSocket: Feb 17 06:43:40.752: [PA] 9e:e7:45:a3:b7:b7 Received management frame ASSOCIATION REQUEST on BSSID f8:c6:50:9e:80:ad destination addr f8:c6:50:9e:80:ad slotid 1
*apfMsConnTask_0: Feb 17 06:43:40.753: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_ASSOC_START (1), reasonCode (1), Result (0), Ssid (DOT1X OKC), ApMac (f8:c6:50:9e:80:a0), RSSI (-39), SNR (59)
*apfMsConnTask_0: Feb 17 06:43:40.753: [PA] 9e:e7:45:a3:b7:b7 Association received from mobile on BSSID f8:c6:50:9e:80:ad AP 9130AXI-4CA0
*apfMsConnTask_0: Feb 17 06:43:40.753: [PA] 9e:e7:45:a3:b7:b7 Assoc Req BSSID f8:c6:50:9e:80:ad AP(9130AXI-4CA0) slot 1 ssid (DOT1X OKC) Tmstmp 1084100 AID 1 stCode 0/0 apChngd 0 oldAp 00:00:00:00:00:00
*apfMsConnTask_0: Feb 17 06:43:40.753: [PA] 9e:e7:45:a3:b7:b7 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_0: Feb 17 06:43:40.753: [PA] 9e:e7:45:a3:b7:b7 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)
*apfMsConnTask_0: Feb 17 06:43:40.754: [PA] 9e:e7:45:a3:b7:b7 Sending Assoc Response (status: '0') to station on AP 9130AXI-4CA0 on BSSID f8:c6:50:9e:80:ad ApVapId 3 Slot 1, mobility role 0
*apfMsConnTask_0: Feb 17 06:43:40.754: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_ASSOC_DONE (2), reasonCode (0), Result (0), Ssid (DOT1X OKC), ServerIp ()

//// Starting Dot1x (Layer 2) Authentication \
*spamApTask1: Feb 17 06:43:40.772: [PA] 9e:e7:45:a3:b7:b7 Received ADD_MOBILE ack - Initiating 1x to STA 9e:e7:45:a3:b7:b7 (idx 146)
*spamApTask1: Feb 17 06:43:40.772: [PA] 9e:e7:45:a3:b7:b7 APF Initiating 1x to STA 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.772: [PA] 9e:e7:45:a3:b7:b7 Sending EAP-Request/Identity to mobile 9e:e7:45:a3:b7:b7 (EAP Id 1)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.772: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_AUTH_START (3), reasonCode (0), Result (0)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.805: [PA] 9e:e7:45:a3:b7:b7 Received Identity Response (count=1) from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.805: [PA] 9e:e7:45:a3:b7:b7 Created Cisco-Audit-Session-ID for the mobile: 1667ee0a000000111c4bb367 type: local
*aaaQueueReader: Feb 17 06:43:40.805: [PA] AuthenticationRequest: 0x7f790fb3e1e8
*aaaQueueReader: Feb 17 06:43:40.814: [PA]          AVP[01] User-Name................................dyanev (6 bytes)
*aaaQueueReader: Feb 17 06:43:40.805: [PA]          AVP[07] Cisco / Audit-Session-Id.................1667ee0a000000111c4bb367 (24 bytes)
***
*aaaQueueReader: Feb 17 06:43:40.805: [PA] 9e:e7:45:a3:b7:b7 Send Radius Auth Request with pktId:90 into qid:7 of server at index:1
*aaaQueueReader: Feb 17 06:43:40.805: [PA] 9e:e7:45:a3:b7:b7 Sending the packet to v4 host 10.238.103.94:1812 of length 277
*aaaQueueReader: Feb 17 06:43:40.805: [PA] 9e:e7:45:a3:b7:b7 Successful transmission of Authentication Packet (pktId 90) to 10.238.103.94:1812 from server queue 7, proxy state 9e:e7:45:a3:b7:b7-02:00
*radiusTransportThread: Feb 17 06:43:40.809: [PA] 9e:e7:45:a3:b7:b7 Counted 3 AVPs (processed 125 bytes, left 0)
*radiusTransportThread: Feb 17 06:43:40.809: [PA] 9e:e7:45:a3:b7:b7 Access-Challenge received from RADIUS server 10.238.103.94 (qid:7) with port:1812, pktId:90
*radiusTransportThread: Feb 17 06:43:40.809: [PA] AuthorizationResponse: 0x5f73752b00
*radiusTransportThread: Feb 17 06:43:40.809: [PA] AVP[01] State....................................37CPMSessionID=1667ee0a000000111c4bb367;34SessionID=SofIse23/523999143/62235; (77 bytes)

/// / The remaining 802.1X exchanges continue until authentication is complete. For a detailed breakdown of the full 802.1X flow, refer to my related articles \
***
*radiusTransportThread: Feb 17 06:43:40.900: [PA] 9e:e7:45:a3:b7:b7 Access-Accept received from RADIUS server 10.238.103.94 (qid:7) with port:1812, pktId:99
***
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.900: [PA] 9e:e7:45:a3:b7:b7 Processing Access-Accept for mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 1x: Updated the audit-session-id of PMK-Cache from client mscb: 1667ee0a000000111c4bb367
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Building Audit session ID (1667ee0a000000111c4bb367) payload in Mobility handoff
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 1 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 PMK sent to mobility group
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_AUTH_DONE (4), reasonCode (89), Result (0), ServerIp (10.238.103.94), UserName (dyanev) DUID ()
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Sending EAP-Success to mobile 9e:e7:45:a3:b7:b7 (EAP Id 66)

//// Layer 2 Authentication (Dot1x) completed \
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.900: [PA] 9e:e7:45:a3:b7:b7 Created PMKID PMK Cache for BSSID f8:c6:50:9e:80:ad at index 0 for station 9e:e7:45:a3:b7:b7
                                                                                  (sticky key cache disabled)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] New PMKID: (16)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] [0000] 4e 4c 0e 6d 27 b3 d8 5c 2e 23 a5 2c bc 8d f6 5e
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 apfCreatePmkCacheEntry: added a new pmk cache entry for 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] Including PMKID in M1 (16)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] [0000] 4e 4c 0e 6d 27 b3 d8 5c 2e 23 a5 2c bc 8d f6 5e
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] M1 - Key Data: (22)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] [0000] dd 14 00 0f ac 04 4e 4c 0e 6d 27 b3 d8 5c 2e 23
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] [0016] a5 2c bc 8d f6 5e

//// 4-Way Handshake process has begun \
Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Starting key exchange to mobile 9e:e7:45:a3:b7:b7, data packets will be dropped
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Sending EAPOL-Key Message to mobile 9e:e7:45:a3:b7:b7 state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Reusing allocated memory for EAP Pkt for retransmission to mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Entering Backend Auth Success state (id=66) for mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 Received Auth Success while in Authenticating state for mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.901: [PA] 9e:e7:45:a3:b7:b7 dot1x - moving mobile 9e:e7:45:a3:b7:b7 into Authenticated state
*dot1xSocketTask: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-key in PTK_START state (message 2) from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Compare RSN IE in association and EAPOL-M2 frame(rsnie_len :20, and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 rsnieCapabilty = 0 rsnie_len =20
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Dumping RSNIE received in Association request(len = 40):
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 00000000: 30 26 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0&..............
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 00000010: 00 0f ac 01 00 00 01 00 29 3c a6 ae c8 b1 a2 24 ........)<.....$
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 00000010: ac 01 00 00 01 00 29 3c a6 ae c8 b1 a2 24 73 87 ......)<.....$s.
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 distribute to flexgroup only when the PSK request is not in progress with RADIUS
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Not Flex client. Do not distribute PMK Key cache.
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Stopping retransmission timer for mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 key Desc Version FT - 0
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 key Desc Version FT - 0
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.912: [PA] 9e:e7:45:a3:b7:b7 Sending EAPOL-Key Message to mobile 9e:e7:45:a3:b7:b7 state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*dot1xSocketTask: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-Key from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 key Desc Version FT - 0
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_L2KEY_DONE (5), reasonCode (0), Result (0)
//// 4-Way Handshake completed \
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)
*Dot1x_NW_MsgTask_7: Feb 17 06:43:40.924: [PA] 9e:e7:45:a3:b7:b7 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)
//// DHCP (DORA) process would typically occur here; however, in this case, the client used a static IP address.\
*apfReceiveTask: Feb 17 06:43:43.784: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7)
*apfReceiveTask: Feb 17 06:43:43.784: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 RUN (20) No 11v BTM
How to read this sequence
  1. The client associates to BSSID f8:c6:50:9e:80:ad on slot 1.
  2. The controller selects 802.1X and sends EAP-Request/Identity.
  3. RADIUS returns Access-Challenge exchanges and eventually Access-Accept.
  4. The PMK cache and a BSSID-specific PMKID are created.
  5. EAPOL-Key M1 through M4 derive and install the pairwise keys.
  6. The client moves through L2AUTHCOMPLETE, DHCP_REQD, and RUN.

PMKID detail: the standard PMKID calculation is the first 128 bits of HMAC-SHA1-128(PMK, "PMK Name" || AA || SPA). In this context, AA is the authenticator address used for the secure association, normally the target BSSID, and SPA is the supplicant MAC.

Initial Association: AP Perspective

The AP debug is valuable because it shows the radio-side management frames and the forwarding of EAP and EAPOL-Key traffic between the wireless interface and the controller-facing path. It helps determine whether a frame reached the AP, crossed the CAPWAP path, or was lost before reaching the controller.

9130AXI AP: first association, full outputFull debug output
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2941] [1739803420:294130] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2942] [1739803420:294254] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2973] CLSM[9E:E7:45:A3:B7:B7]: US Assoc Req(0) seq 2166 IF 38 slot 1 vap 2 len 337 state AUTH
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2974] CLSM[9E:E7:45:A3:B7:B7]: Not populating DCDS data
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2974] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2975] pmkid[0] :
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2975]             29 3c a6 ae c8 b1 a2 24
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2975]             73 87 92 d9 61 69 42 ae
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2975] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2976] pmkid[0] :
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2976]             29 3c a6 ae c8 b1 a2 24
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2976]             73 87 92 d9 61 69 42 ae
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.2997] CLSM[9E:E7:45:A3:B7:B7]: DS Assoc Resp(10) IF 18 slot 1 vap 2 state AUTH, generated by WLC
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3007] CLSM[9E:E7:45:A3:B7:B7]: Driver send mgmt frame success Radio 1 Vap 2
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3008] CLSM[9E:E7:45:A3:B7:B7]: client moved from AUTH to ASSOC
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3013] CLSM[9E:E7:45:A3:B7:B7]: ADD_MOBILE AID 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3015] CLSM[9E:E7:45:A3:B7:B7]: Driver Add Client success AID 1 Radio 1 Vap 2 Enc 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3019] CLSM[9E:E7:45:A3:B7:B7]: Added to ClientIPTable on apr1v2
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3030] [1739803420:303076] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] DOT11_ASSOC_REQUEST : (.)
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3032] [1739803420:303206] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] DOT11_ASSOC_RESPONSE : (.)
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3164] CLSM[9E:E7:45:A3:B7:B7]: client moved from ASSOC to 8021X
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3166] CLSM[9E:E7:45:A3:B7:B7]: Added to WCP client table AID 1 Radio 1 Vap 2 Enc 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3182] [1739803420:318222] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAP_PACKET.Request : Id 0x01 type 1 Identity
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3183] [1739803420:318296] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAP_PACKET.Request : Id 0x01 type 1 Identity
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3183] chatter: eap_to_cli:   72 | 9ee745a3 b7b7f8c6 509e80ad 888e0200 00360101 00360100 6e657477 6f726b69 643d444f 54315820 4f4b432c 6e617369 643d534f 462d574c 414e2d35 3532302c 706f7274 69643d31
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3504] [1739803420:350418] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] EAP_PACKET.Response : Id 0x01 type 1 Identity
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3505] [1739803420:350497] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [U:E] EAP_PACKET.Response : Id 0x01 type 1 Identity
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.3505] chatter: eap_from_cli:   29 | f8c6509e 80ad9ee7 45a3b7b7 888e0100 000b0201 000b0164 79616e65 76
< The dot1x flow continues until it is completed >
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4467] [1739803420:446698] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAP_PACKET.Success : Id 0x42
//// 4-way handshake process has begun \
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4467] [1739803420:446721] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAPOL_KEY.M1 : DescType 0x02 KeyInfo 0x008a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4467] chatter: eap_to_cli:   22 | 9ee745a3 b7b7f8c6 509e80ad 888e0200 00040342 0004
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4468] chatter: eap_to_cli:  135 | 9ee745a3 b7b7f8c6 509e80ad 888e0203 00750200 8a001000 00000000 0000004a 424be7d8 a3a18d35 2339008a bd6f21be 430ee209 ca0f331e 3d01d647 f5944300 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4472] [1739803420:447242] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAP_PACKET.Success : Id 0x42
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4472] [1739803420:447273] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAPOL_KEY.M1 : DescType 0x02 KeyInfo 0x008a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4573] [1739803420:457382] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] EAPOL_KEY.M2 : DescType 0x02 KeyInfo 0x010a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4574] [1739803420:457447] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [U:E] EAPOL_KEY.M2 : DescType 0x02 KeyInfo 0x010a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4574] chatter: eap_from_cli:  153 | f8c6509e 80ad9ee7 45a3b7b7 888e0103 00870201 0a000000 00000000 00000046 fedaf179 39e5cfaa 4d979a85 2495170e 51c15271 738535e8 652a12cf fad88700 00000000 00000000 00000000 00000000 00000000 00000000 00000000 0000008c 62f4cb94
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4582] [1739803420:458242] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAPOL_KEY.M3 : DescType 0x02 KeyInfo 0x13ca
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4582] [1739803420:458294] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAPOL_KEY.M3 : DescType 0x02 KeyInfo 0x13ca
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4583] chatter: eap_to_cli:  169 | 9ee745a3 b7b7f8c6 509e80ad 888e0203 00970213 ca001000 00000000 0000014a 424be7d8 a3a18d35 2339008a bd6f21be 430ee209 ca0f331e 3d01d647 f5944300 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000004 a15aebe6
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4694] [1739803420:469491] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] EAPOL_KEY.M4 : DescType 0x02 KeyInfo 0x030a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4695] [1739803420:469553] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <wired0> [U:E] EAPOL_KEY.M4 : DescType 0x02 KeyInfo 0x030a
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4695] chatter: eap_from_cli:  113 | f8c6509e 80ad9ee7 45a3b7b7 888e0103 005f0203 0a000000 00000000 00000100 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000bc 09f39bcf
//// 4-way handshake completed \
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4713] CLSM[9E:E7:45:A3:B7:B7]: ADD_MOBILE AID 1
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4719] CLSM[9E:E7:45:A3:B7:B7]: Client ADD Encrypt Key success AID 1 Radio 1 Enc 4 Key Len 16 Key idx 0 Key eb 4d
Feb 17 14:43:40 kernel: [*02/17/2025 14:43:40.4722] CLSM[9E:E7:45:A3:B7:B7]: client moved from 8021X to FWD
Direction legend for this capture
  • D: downlink, toward the client.
  • U: uplink, from the client.
  • E: Ethernet/controller-facing representation.
  • W: wireless/radio-facing representation.

Thus, <wired0> [D:E] EAPOL_KEY.M1 is received on the controller-facing path and <apr1v2> [D:W] is transmitted over the radio. M2 takes the reverse direction. Interface labels differ across AP generations, as shown by <wifi1> on the 2802I.

The AP VAP ID is local to the AP/radio context and is not the same as the AireOS WLAN ID. Use show controllers dot11Radio 0/1/2 wlan, with the applicable radio number, to map the AP VAP before interpreting the debug.

Over-the-Air Capture

Controller and AP debugs show software processing. An OTA capture shows the actual 802.11 frames and information elements. Lock the sniffer to the correct primary channel and width. For a roam across two channels, use two synchronized sniffers where possible; if only one is available, capture the target channel.

wlan.addr == <client-mac> && (wlan.fc.type_subtype <= 3 || eapol)

This is a useful display filter for the relevant management frames and EAPOL, but it intentionally hides ACKs, retransmissions, null-data frames, and other useful context. Remove or broaden it when diagnosing RF loss or retry behavior.

New Association - OKC not triggered
The client’s initial connection to the 9130AXI AP, showing the 802.11 association process, Layer 2 authentication through 802.1X/EAPOL, and the WPA2 4-Way Handshake used to establish the encryption keys.
New Association - OKC not triggered
Probe Response is sent by the AP
New Association - OKC not triggered
Probe Response shows the WLAN’s advertised RSN capabilities. To verify the client’s selected AKM and PMKID list, inspect the client’s Association or Reassociation Request RSN element.

OKC Roam: 9130AXI to 2802I

The target Reassociation Request contains one PMKID. AireOS looks for a valid cached PMK context, calculates the target-BSSID-specific PMKID, and compares it with the value supplied by the client. The CCKM: text in this code path is only an internal function label; Cisco specifically warns not to interpret it as evidence that CCKM was used.

AireOS WLC: OKC roam, full outputFull debug output
*apfOpenDtlSocket: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Received management frame REASSOCIATION REQUEST on BSSID 24:16:9d:27:5c:ad destination addr 24:16:9d:27:5c:ad slotid 1
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_ASSOC_START (1), reasonCode (2), Result (0), Ssid (DOT1X OKC), ApMac (24:16:9d:27:5c:a0), RSSI (-45), SNR (62)
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Reassociation received from mobile on BSSID 24:16:9d:27:5c:ad AP AIR-AP2802I-E-K9
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Max Client Trap Threshold: 0 cur: 0
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 In processSsidIE:7634 setting Central switched to TRUE
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Processing RSN IE type 48, length 38 for mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 RSN Capabilities: 0
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 non-11w Capable mobile
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Received RSN IE(AKM:1) with 1 PMKIDs
*apfMsConnTask_4: Feb 17 06:46:14.005: [PA] 9e:e7:45:a3:b7:b7 Received RSN IE with 1 PMKIDs from mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] Received PMKID: (16)
//// The received PMKID is not displayed in this debug excerpt. If the subsequent validation messages confirm a valid PMKID, the missing value can be treated as a cosmetic logging issue rather than a roaming failure. \
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 Searching for PMKID in MSCB PMKID cache for mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 No valid PMKID found in the MSCB PMKID cache for mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] 24 16 9d 27 5c a0
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] CCKM: Find PMK in cache: realAA = (6)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] 24 16 9d 27 5c ad
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] CCKM: Find PMK in cache: PMKID = (16)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] ed 07 62 8a 03 4f b1 83 ab d2 b7 ab 77 ee a9 09
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] CCKM: AA (6)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] CCKM: SPA (6)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] 9e e7 45 a3 b7 b7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] PMK Key: (32)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] 40 a3 f7 3e f6 bf 62 f8 33 3d b6 e5 20 32 73 28
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0016] e3 c3 c4 77 be 73 41 cb 26 51 c2 e9 9f 3b 83 f7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 computing pmk, received 11w flag: 0
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] Received PMKID (16)
//// The PMKID is again omitted from the debug output; however, the subsequent validation messages confirm that it was processed successfully. \
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] Computed PMKID (16)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] ed 07 62 8a 03 4f b1 83 ab d2 b7 ab 77 ee a9 09
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 Created PMKID PMK Cache for BSSID 24:16:9d:27:5c:ad at index 0 for station 9e:e7:45:a3:b7:b7
                                                                                  (sticky key cache disabled)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] New PMKID: (16)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] [0000] ed 07 62 8a 03 4f b1 83 ab d2 b7 ab 77 ee a9 09
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 Computed a valid PMKID from MSCB PMK cache for mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 mark client PMKID Roamed
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 Reassoc Req BSSID 24:16:9d:27:5c:ad AP(AIR-AP2802I-E-K9) slot 1 ssid (DOT1X OKC) Tmstmp 1084251 AID 1stCode 0/0 apChngd 1 oldAp F8:C6:50:9E:80:A0
*spamApTask1: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 Delete Mobile request with reason 'MN_DEL_INTER_AP_ROAM' on slot 1 sent to the AP f8:c6:50:9e:80:a0 IP: 10.238.103.62:5248.
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 START (0) Change state to AUTHCHECK (2) last state START (0)
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 AuthenticationRequired = 1
*apfMsConnTask_4: Feb 17 06:46:14.006: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)
*spamApTask5: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 APF Initiating 1x to STA 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 dot1x - moving mobile 9e:e7:45:a3:b7:b7 into Force Auth state
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 Skipping EAP-Success to mobile 9e:e7:45:a3:b7:b7 (encryptBit:0)
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 Username entry (dyanev) already exists in name table, length = 253
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 Username entry (dyanev) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] Including PMKID in M1 (16)
<Not displayed due to a cosmetic issue, the PMKID is still included in the PMKID Message 1 frame as expected.>
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] M1 - Key Data: (22)
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] [0000] dd 14 00 0f ac 04 ed 07 62 8a 03 4f b1 83 ab d2
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] [0016] b7 ab 77 ee a9 09
//// The OKC roam has progressed to the 4-Way Handshake. Full EAP authentication is skipped, while fresh transient keys are established for the new AP association. \
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 Starting key exchange to mobile 9e:e7:45:a3:b7:b7, data packets will be dropped
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.010: [PA] 9e:e7:45:a3:b7:b7 Sending EAPOL-Key Message to mobile 9e:e7:45:a3:b7:b7 state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
***
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-key in PTK_START state (message 2) from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Received valid MIC in EAPOL Key Message M2!!!!!
***
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Sending EAPOL-Key Message to mobile 9e:e7:45:a3:b7:b7 state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.035: [PA] 9e:e7:45:a3:b7:b7 Reusing allocated memory for EAP Pkt for retransmission to mobile 9e:e7:45:a3:b7:b7
*dot1xSocketTask: Feb 17 06:46:14.037: [PA] 9e:e7:45:a3:b7:b7 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-Key from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 key Desc Version FT - 0
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 9e:e7:45:a3:b7:b7
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 Resetting client reasonCode
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_L2KEY_DONE (5), reasonCode (0), Result (0)
//// 4-Way handshake completed \
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)
*Dot1x_NW_MsgTask_7: Feb 17 06:46:14.038: [PA] 9e:e7:45:a3:b7:b7 10.238.103.87 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)
What the WLC proves
  1. The client selected the target 2802I and supplied a PMKID.
  2. The WLC retained the original PMK and calculated ed 07 ... a9 09 for the target BSSID.
  3. The supplied and computed PMKIDs matched.
  4. A full EAP method exchange was skipped.
  5. A fresh 4-Way Handshake produced a new PTK and returned the client to RUN.
2802I AP: target-side OKC roam, full outputFull debug output
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4158] [1739803573:415814] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4159] CLSM[9E:E7:45:A3:B7:B7]: US Auth(b0) seq 532 IF 31 slot 1 vap 2 len 30 state NULL
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4161] CLSM[9E:E7:45:A3:B7:B7]: DS Auth len 30 slot 1 vap 2
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4162] [1739803573:416194] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4162] CLSM[9E:E7:45:A3:B7:B7]: Driver send mgmt frame success Radio 1 Vap 2
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4163] CLSM[9E:E7:45:A3:B7:B7]: client moved from UNASSOC to AUTH
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4194] [1739803573:419430] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] DOT11_REASSOC_REQUEST : (.)
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4206] CLSM[9E:E7:45:A3:B7:B7]: US Reassoc Req(20) seq 533 IF 31 slot 1 vap 2 len 305 state AUTH
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4207] CLSM[9E:E7:45:A3:B7:B7]: Not populating DCDS data
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4208] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4208] pmkid[0] :
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4208]             ed 07 62 8a 03 4f b1 83
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4209]             ab d2 b7 ab 77 ee a9 09
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4209] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4209] pmkid[0] :
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4209]             ed 07 62 8a 03 4f b1 83
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4210]             ab d2 b7 ab 77 ee a9 09
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4228] CLSM[9E:E7:45:A3:B7:B7]: DS Reassoc Resp(30) IF 18 slot 1 vap 2 state AUTH, generated by WLC
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4231] [1739803573:423116] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] DOT11_REASSOC_RESPONSE : (.)
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4234] CLSM[9E:E7:45:A3:B7:B7]: Driver send mgmt frame success Radio 1 Vap 2
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4235] CLSM[9E:E7:45:A3:B7:B7]: client moved from AUTH to ASSOC
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4241]
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4241] *** RSN ERROR: Received a data frame when no keys are plumbedCLSM[9E:E7:45:A3:B7:B7]: ADD_MOBILE AID 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4247] CLSM[9E:E7:45:A3:B7:B7]: Driver Add Client success AID 1 Radio 1 Vap 2 Enc 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4250] CLSM[9E:E7:45:A3:B7:B7]: Added to ClientIPTable on apr1v2
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4255] CLSM[9E:E7:45:A3:B7:B7]: client moved from ASSOC to 8021X
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4256] CLSM[9E:E7:45:A3:B7:B7]: Added to WCP client table AID 1 Radio 1 Vap 2 Enc 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4262]
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4262] *** RSN ERROR: Received a data frame when no keys are plumbed
//// Skipping EAP authentication as the roaming is successful and proceeding with the 4-way handshake. \
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4269] [1739803573:426938] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAPOL_KEY.M1 : DescType 0x02 KeyInfo 0x008a
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4270] chatter: eap_to_cli: 135 | 9ee745a3 b7b72416 9d275cad 888e0203 00750200 8a001000 00000000 0000004a 424be7d8 a3a18d35 2339008a bd6f21be 430ee209 ca0f331e 3d01d647 f5944400 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4270] [1739803573:427073] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAPOL_KEY.M1 : DescType 0x02 KeyInfo 0x008a
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4507] [1739803573:450756] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] < wifi1> [U:W] EAPOL_KEY.M2 : DescType 0x02 KeyInfo 0x010a
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4508] chatter: eap_from_cli: 153 | 24169d27 5cad9ee7 45a3b7b7 888e0103 00870201 0a000000 00000000 000000d4 e7eaad70 33f6b97c 3f02c588 4b0ed194 571adda0 6326e9ac 6f32f5b8 7b3e0100 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000cd 950fafbe
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4508] [1739803573:450877] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <wired0> [U:E] EAPOL_KEY.M2 : DescType 0x02 KeyInfo 0x010a
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4515] [1739803573:451566] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <wired0> [D:E] EAPOL_KEY.M3 : DescType 0x02 KeyInfo 0x13ca
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4516] chatter: eap_to_cli: 169 | 9ee745a3 b7b72416 9d275cad 888e0203 00970213 ca001000 00000000 0000014a 424be7d8 a3a18d35 2339008a bd6f21be 430ee209 ca0f331e 3d01d647 f5944400 00000000 00000000 00000000 00000000 00000000 00000000 00000000 000000e8 2e3d7f67
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4516] [1739803573:451680] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] EAPOL_KEY.M3 : DescType 0x02 KeyInfo 0x13ca
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4537] [1739803573:453742] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] < wifi1> [U:W] EAPOL_KEY.M4 : DescType 0x02 KeyInfo 0x030a
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4538] chatter: eap_from_cli: 113 | 24169d27 5cad9ee7 45a3b7b7 888e0103 005f0203 0a000000 00000000 00000100 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 0000002c 2c3a235f
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4538] [1739803573:453833] [AIR-AP2802I-E-K9] [9e:e7:45:a3:b7:b7] <wired0> [U:E] EAPOL_KEY.M4 : DescType 0x02 KeyInfo 0x030a
//// 4-way handshake completed \
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4554] CLSM[9E:E7:45:A3:B7:B7]: ADD_MOBILE AID 1
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4559] CLSM[9E:E7:45:A3:B7:B7]: Client ADD Encrypt Key success AID 1 Radio 1 Enc 4 Key Len 16 Key idx 0 Key 5b a5
Feb 17 14:46:13 kernel: [*02/17/2025 14:46:13.4561] CLSM[9E:E7:45:A3:B7:B7]: client moved from 8021X to FWD

The AP’s 8021X state is a local security-gating state; it does not by itself prove that full EAP authentication occurred. Here, the absence of EAP Identity/method exchanges and the immediate M1–M4 sequence show cached-PMK use.

New Association - OKC not triggered
The client successfully roamed to the 2802I AP using OKC. The PMKID matched on both sides, allowing the full EAP authentication exchange to be skipped while a fresh PTK was derived through the 4-Way Handshake.

In this sample, the controller-side interval from the logged Reassociation Request at 06:46:14.005 to RUN at 06:46:14.038 is approximately 33 ms. AP-side timestamps use a different time base and show roughly 40 ms from authentication activity to FWD. Treat these as measurements of this lab trace, not universal OKC guarantees.

A successful OKC roam still contains EAPOL-Key traffic. What should be absent is the full EAP authentication conversation, such as EAP-Request/Identity, EAP-Response/Identity, method exchanges, and EAP-Success. The simplified logical sequence is Reassociation Request, Reassociation Response, and EAPOL-Key M1–M4. OTA captures also include authentication frames, ACKs, retries, data, and other activity, so do not expect exactly six physical frames.

Return Roam: 2802I to the Original 9130AXI

Because PMKID calculation includes the authenticator address, returning to the original BSSID with the same valid PMK and client MAC produces the same BSSID-specific PMKID seen during the original session.

Return roam: WLC and 9130AXI AP, full outputFull debug output
*apfOpenDtlSocket: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 Received management frame REASSOCIATION REQUEST on BSSID f8:c6:50:9e:80:ad destination addr f8:c6:50:9e:80:ad slotid 1
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 Processing assoc-req station:9e:e7:45:a3:b7:b7 AP:f8:c6:50:9e:80:a0-01 ssid : DOT1X OKC thread:5f9e65d160
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 CL_EVENT_ASSOC_START (1), reasonCode (2), Result (0), Ssid (DOT1X OKC), ApMac (f8:c6:50:9e:80:a0), RSSI (-46), SNR (32)
***
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] CCKM: Find PMK in cache: realAA = (6)
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] [0000] 4e 4c 0e 6d 27 b3 d8 5c 2e 23 a5 2c bc 8d f6 5e
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] Received PMKID (16)
<Not displayed due to a cosmetic issue again.>
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] Computed PMKID (16)
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] [0000] 4e 4c 0e 6d 27 b3 d8 5c 2e 23 a5 2c bc 8d f6 5e
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 Created PMKID PMK Cache for BSSID f8:c6:50:9e:80:ad at index 0 for station 9e:e7:45:a3:b7:b7
                                                                                  (sticky key cache disabled)
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] New PMKID: (16)
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] [0000] 4e 4c 0e 6d 27 b3 d8 5c 2e 23 a5 2c bc 8d f6 5e
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 Computed a valid PMKID from MSCB PMK cache for mobile 9e:e7:45:a3:b7:b7
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 Setting active key cache index 0 ---> 0
*apfMsConnTask_0: Feb 17 06:46:32.297: [PA] 9e:e7:45:a3:b7:b7 mark client PMKID Roamed

9130 AP:
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7303] [1739803591:730354] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [U:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7304] [1739803591:730476] [9130AXI-4CA0] [9e:e7:45:a3:b7:b7] <apr1v2> [D:W] DOT11_AUTHENTICATION : (.)
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7325] CLSM[9E:E7:45:A3:B7:B7]: US Reassoc Req(20) seq 605 IF 38 slot 1 vap 2 len 337 state AUTH
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7326] CLSM[9E:E7:45:A3:B7:B7]: Not populating DCDS data
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7326] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7327] pmkid[0] :
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7327]             4e 4c 0e 6d 27 b3 d8 5c
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7327]             2e 23 a5 2c bc 8d f6 5e
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7327] RSNIE in (Re)Assoc Req contains pmkid count: 1
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7327] pmkid[0] :
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7328]             4e 4c 0e 6d 27 b3 d8 5c
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7328]             2e 23 a5 2c bc 8d f6 5e
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7345] CLSM[9E:E7:45:A3:B7:B7]: DS Reassoc Resp(30) IF 18 slot 1 vap 2 state AUTH, generated by WLC
//// The 4-Way Handshake completed successfully; however, the intermediate messages have been intentionally omitted from this excerpt for brevity. The client then transitioned to the FWD state. \
Feb 17 14:46:31 kernel: [*02/17/2025 14:46:31.7780] CLSM[9E:E7:45:A3:B7:B7]: client moved from 8021X to FWD

The client supplied 4e 4c ... f6 5e; the WLC independently calculated the same value for the original BSSID and marked the client as PMKID-roamed. This confirms successful cache validation for this test. It does not, by itself, prove that every future roam or every AP has a healthy data path.

New Association - OKC not triggered
The client successfully roamed back to the 9130AXI AP. The Reassociation Request contained the original BSSID-specific PMKID, which was successfully validated by the WLC. The full 802.1X/EAP authentication exchange was skipped, and a new 4-Way Handshake established fresh transient keys for the AP association.

Summary of the Key Relationships

ItemBehavior during a valid OKC roam
MSKCreated/exported by the EAP method during the original authentication; not renegotiated merely for the OKC roam.
PMKRetained for the valid PMKSA lifetime and made available within the supported centralized mobility scope.
PMKIDCalculated for the target authenticator address and client MAC; it normally changes when the BSSID changes.
PTKFreshly derived during the target AP’s 4-Way Handshake.
GTKGenerated by the infrastructure’s group-key hierarchy and securely distributed to the client.
EAPFull EAP method exchange is skipped when cached-PMK validation succeeds.

AP Groups, FlexConnect, and Mobility Design

AireOS AP Groups

Roaming across AireOS AP Groups can work when the WLAN is available from both AP Groups and its client VLAN and interface mapping remain consistent.

A “salt-and-pepper” design, where adjacent APs belong to different AP Groups and map the same WLAN to different VLANs, creates a more complex and potentially suboptimal mobility path. This design should be avoided where clients can move frequently between the overlapping RF cells.

When the objective is to distribute clients across multiple VLANs, use an interface group rather than assigning overlapping AP Groups with different static WLAN-to-VLAN mappings.

Different VLAN mappings: If the same SSID maps to VLAN 10 in one AP Group and VLAN 20 in another, do not assume that the result is always a simple reauthentication followed by a new DHCP lease.

Depending on the controller topology, client interfaces, mobility configuration, and whether the roam crosses controller boundaries, the transition may require Layer 3 mobility handling or another data-path adjustment. The expected behavior should be validated against the specific AireOS deployment.

FlexConnect Roaming

FlexConnect roaming behavior depends on whether client traffic is locally or centrally switched, whether the APs belong to the same FlexConnect Group, and which fast-roaming method is selected by the client.

Local-switching requirement: For a client to retain its existing Layer 3 session during a locally switched FlexConnect roam, the WLAN must map to the same client VLAN and IP subnet on the source and target APs.

If the WLAN maps to different subnets at the two APs, seamless local roaming cannot be maintained because the client’s existing IP address is not valid on the target subnet.

FlexConnect Roaming Scenario Local Switching with OKC Central Switching with OKC
APs in the same FlexConnect Group Fast roam1 Fast roam
APs in different FlexConnect Groups Fast roam1 Fast roam
Inter-controller mobility Not applicable Fast roam2

1 For locally switched FlexConnect WLANs, the source and target APs must map the WLAN to the same client VLAN and IP subnet. This allows the client to retain its existing IP address and Layer 3 session after the roam.

2 For inter-controller OKC roaming, the controllers must have a functional mobility relationship and use the same mobility-group name so that the required fast-roaming security context can be shared.

FlexConnect protocol considerations
  • OKC can support fast roaming between APs assigned to different custom FlexConnect Groups because the PMK cache is maintained by the controller, provided that both the controller and client retain a valid PMK context. This behavior does not apply to APs assigned to the default FlexConnect Group , where fast secure roaming is not supported.

Connected vs. standalone operation: OKC is supported for a client whose key context was established while the FlexConnect AP was connected to the controller. In standalone mode, previously distributed cache information may allow an existing client session to continue roaming, but a new authentication cannot depend on controller-based OKC processing while the controller is unreachable.

Mixed AP-mode roaming: Avoid designing a continuous roaming domain that requires clients to move regularly between locally switched FlexConnect APs and centrally switched Local-mode APs.

The forwarding path, VLAN attachment, and roaming capabilities are different between these AP modes. If such a transition is required, validate the exact AireOS release, WLAN configuration, VLAN design, client addressing, and expected authentication behavior in a lab.

AireOS Mobility Peers

  • Controllers in the same AireOS mobility group should use the same virtual gateway or virtual-interface IP address.
  • Controllers that must share fast-roaming cache information should use the same mobility-group name.
  • IP connectivity must be available between the management interfaces of all mobility peers.
  • Controllers should run compatible AireOS releases and, where operationally possible, the same software version.
  • For OKC inter-controller fast roaming, the controllers must have the required mobility relationship and access to the valid client PMK cache.

Common Issues and Troubleshooting

Scenario 1: Reassociation Request contains no PMKID

If the RSN element reports zero PMKIDs, the client did not offer a cached PMKSA for that target. Check whether the client supports OKC, selected the expected AKM, preserved the session, and is actually performing a reassociation rather than a new association. Also verify WLAN consistency and capture the request OTA before concluding that the client is faulty.

Scenario 2: PMKID is present but does not validate

Check PMK lifetime and session deletion, controller mobility-cache scope, WLAN/security consistency, target BSSID selection, client MAC randomization behavior, inter-controller mobility state, FlexConnect group behavior if applicable, and whether the client supplied the PMKID for the actual target authenticator address.

Useful repeatable test

Associate to AP-1, roam to AP-2, then return to AP-1. If the PMK remained valid and the same client MAC and BSSID are used, the PMKID for AP-1 should match the original AP-1 value. A mismatch is evidence to investigate, but it is not sufficient by itself to assign fault without validating the actual PMK lifetime and capture inputs.

For intermittent issues, synchronized WLC, source-AP, target-AP, OTA, RADIUS, and wired-path evidence is stronger than any one debug. Run bounded captures until the failure and use file rotation. OTA is still valuable when the issue is intermittent; it may be the only evidence of a missing, malformed, retried, or rejected over-the-air frame.

Optional PMKID Calculation

Handle key material securely: RADIUS MPPE attributes are protected with the RADIUS shared secret, and ordinary packet capture alone does not expose plaintext PMK/MSK material. Only decrypt and inspect traffic in an authorized lab. Never publish production PMKs, MSKs, shared secrets, user identities, or reusable packet captures.

For the EAP-TLS key hierarchy described in RFC 5216, the 64-byte MSK is exported by the EAP method. The first 32 bytes are identified as the peer-to-authenticator encryption key and are used as the IEEE 802.11 PMK in that profile. The exact key derivation/export behavior must be checked for the EAP method being tested.

MSK = Key_Material(0,63)
Enc-RECV-Key = MSK(0,31) = MS-MPPE-Recv-Key = IEEE 802.11 PMK
Enc-SEND-Key = MSK(32,63) = MS-MPPE-Send-Key

The following corrected lab script validates input lengths and uses valid hexadecimal MAC-address examples:

import hmac
import hashlib

def calculate_pmkid(pmk: bytes, aa: str, spa: str) -> bytes:
    aa_bytes = bytes.fromhex(aa.replace(":", ""))
    spa_bytes = bytes.fromhex(spa.replace(":", ""))
    data = b"PMK Name" + aa_bytes + spa_bytes
    return hmac.new(pmk, data, hashlib.sha1).digest()[:16]

# Example only. Never publish live key material.
eap_msk_hex = (
    "3e8f212d25eccd879e1df9202d6235ab"
    "eda6714b62ef0d9af7fc5b10c1326909"
    "58d5f9b23544fed5c2cbdb7c3b0190d9"
    "8764838ff4fba2e85b8de6cb6678afea"
)
eap_msk = bytes.fromhex(eap_msk_hex)
if len(eap_msk) != 64:
    raise ValueError("EAP MSK must be 64 bytes")

pmk = eap_msk[:32]
aa = "aa:bb:cc:dd:ee:ff"   # Target AP BSSID / authenticator address
spa = "11:22:33:44:55:66"  # Client MAC / supplicant address
print("PMKID:", calculate_pmkid(pmk, aa, spa).hex())

The calculated result should match the PMKID present in the client’s Reassociation Request and the value independently computed by the WLC for the same PMK, target AA/BSSID, and SPA/client MAC.

References

Post Views: 19
Scroll to Top