I would like to understand why a PMKID cache entry is being deleted by an AP (AP2, 78:72:5d:74:7e:60 / 78:72:5d:74:7e:6f) when an STA first connects to a WLAN dedicated to it under the following circumstances.
Requires:
- Android 11 Mobile Device
- Cisco 3504 WLC
- 2x 3800 series APs, associated with individual AP groups, with unique WLANs associated to each group.
o One WLAN SSID is configured for 802.11b/g only, 2.4GHz, AP3
o The other WLAN SSID is configured for 802.11a/g only, 5GHz, AP2
Device MAC Address Information:
STA MAC Address: 04:7b:cb:6c:ce:5c
AP2 MAC Address: 78:72:5d:74:7e:60 / 78:72:5d:74:7e:6f
AP3 MAC Address: a0:93:51:c9:24:a0
The Scenario:
1.First, manually connect to 5GHz WLAN (Security: WPA3-Personal) dedicated to AP2, 5GHz only AP Group. WLAN SSID is saved on Android 11 device STA and device successfully connects.
2. Next, connect to 2.4GHz WLAN (Security: WPA3-Personal) dedicated to AP3, 2.4GHz only AP Group. New WLAN SSID is saved on Android device STA and device successfully connects, while 5GHz SSID remains saved on STA.
The Logs:
1. STA connects to a WLAN dedicated to AP2 (78:72:5d:74:7e:60 / 78:72:5d:74:7e:6f), 5GHz only WPA3-Personal security. PMKID created for STA and stored in cache.
*apfMsConnTask_5: Sep 06 10:24:42.720: 04:7b:cb:6c:ce:5c Received SAE auth Request from station 04:7b:cb:6c:ce:5c on AP 78:72:5d:74:7e:60
*apfMsConnTask_5: Sep 06 10:24:42.729: 04:7b:cb:6c:ce:5c PMKID:a5747045ce03162336d3736e8e2500aa
*apfMsConnTask_5: Sep 06 10:24:42.729: 04:7b:cb:6c:ce:5c Successfully derived PMK and KCK
*apfMsConnTask_5: Sep 06 10:24:42.735: 04:7b:cb:6c:ce:5c apfCreatePmkCacheEntry: added a new pmk cache entry for 04:7b:cb:6c:ce:5c
*apfOpenDtlSocket: Sep 06 10:24:42.744: 04:7b:cb:6c:ce:5c Received management frame ASSOCIATION REQUEST on BSSID 78:72:5d:74:7e:6f
*apfMsConnTask_5: Sep 06 10:24:42.747: 04:7b:cb:6c:ce:5c Sending Assoc Response (status: '0') to station on AP AP2 on BSSID 78:72:5d:74:7e:6f ApVapId 1 Slot 1
*Dot1x_NW_MsgTask_4: Sep 06 10:24:42.776: 04:7b:cb:6c:ce:5c Creating a PKC PMKID Cache entry for station 04:7b:cb:6c:ce:5c (RSN 2)
*Dot1x_NW_MsgTask_4: Sep 06 10:24:42.776: 04:7b:cb:6c:ce:5c Created PMKID PMK Cache for BSSID 78:72:5d:74:7e:6f at index 0 for station 04:7b:cb:6c:ce:5c
*DHCP Socket Task: Sep 06 10:24:43.208: 04:7b:cb:6c:ce:5c 192.168.1.179 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7)
*osapiBsnTimer: Sep 06 10:24:52.550: 04:7b:cb:6c:ce:5c sae 'saeBlock life' Timer expired for sae Block Id:04:7b:cb:6c:ce:5c-78:72:5d:74:7e:6f I am not sure what these logs indicate.
*apfMsConnTask_2: Sep 06 10:24:52.550: 04:7b:cb:6c:ce:5c successfully deleted the SaeCb
2. I then manually connect to another WLAN dedicated to another AP. AP3 (a0:93:51:c9:24:a0), 2.4GHz only WPA3-Personal security.
*apfOpenDtlSocket: Sep 06 10:24:58.751: 04:7b:cb:6c:ce:5c Received management frame DEAUTH on BSSID 78:72:5d:74:7e:6f destination addr 78:72:5d:74:7e:6f slotid 1
*apfMsConnTask_5: Sep 06 10:24:58.752: 04:7b:cb:6c:ce:5c Got deauth frame from 04:7B:CB:6C:CE:5C BSSID= 78:72:5D:74:7E:60 reasoncode = 3 dataLen = 8
*spamApTask7: Sep 06 10:24:58.752: 04:7b:cb:6c:ce:5c Delete Mobile request with reason 'MN_DEL_PEM_CLEANUP' on slot 1 sent to the AP 78:72:5d:74:7e:60 IP: 192.168.1.50:5248.
- Within milliseconds the STA tries to connect to AP3 (a0:93:51:c9:24:a0). A PMKID is created for the STA and stored in cache.
*apfMsConnTask_7: Sep 06 10:24:58.999: 04:7b:cb:6c:ce:5c Received SAE auth Request from station 04:7b:cb:6c:ce:5c on AP a0:93:51:c9:24:a0
*apfMsConnTask_7: Sep 06 10:24:59.007: 04:7b:cb:6c:ce:5c PMKID:44de7a3b5dad214eb2f0ff09c367712f
*apfMsConnTask_7: Sep 06 10:24:59.027: 04:7b:cb:6c:ce:5c Deleting PMK cache for the client as security association is changed. Not sure if these logs are related to AP2?
*apfMsConnTask_7: Sep 06 10:24:59.028: 04:7b:cb:6c:ce:5c Removing PMK cache entry for station 04:7b:cb:6c:ce:5c
*apfMsConnTask_7: Sep 06 10:24:59.028: 04:7b:cb:6c:ce:5c apfCreatePmkCacheEntry: added a new pmk cache entry for 04:7b:cb:6c:ce:5c
*apfOpenDtlSocket: Sep 06 10:24:59.048: 04:7b:cb:6c:ce:5c Received management frame ASSOCIATION REQUEST on BSSID a0:93:51:c9:24:a0 destination addr a0:93:51:c9:24:a0 slotid 0
*apfMsConnTask_7: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c Received RSN IE(AKM:8) with 0 PMKIDs
3. Global PMK cache entry deletion happens. I am not sure what this is related to?
*apfMsConnTask_7: Sep 06 10:24:59.048: 04:7b:cb:6c:ce:5c Removing PMK cache entry for station 04:7b:cb:6c:ce:5c
*apfMsConnTask_7: Sep 06 10:24:59.048: 04:7b:cb:6c:ce:5c 0 PMK-remove groupcast messages sent
*apfMsConnTask_7: Sep 06 10:24:59.048: 04:7b:cb:6c:ce:5c Deleted global PMK cache and MSCB PMKID/PMK cache entry for the client
*apfMsConnTask_7: Sep 06 10:24:59.048: 04:7b:cb:6c:ce:5c pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
4. Assoc response sent with invalid PMKID(53).
*apfMsConnTask_7: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c no PMK cache entry for SAE client. Can't allow association.
*IPv6_Msg_Task: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c IP Addr Clear. AP MAC[78:72:5d:74:7e:60] Role[Unassociated] Pem State [DHCP_REQD] Connected Time[17]
*apfMsConnTask_7: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c Sending assoc-resp with status 53 station:04:7b:cb:6c:ce:5c AP:78:72:5d:74:7e:60-01 on apVapId 1
*apfMsConnTask_7: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c Sending Assoc Response (status: '53') to station on AP AP3 on BSSID a0:93:51:c9:24:a0 ApVapId 1 Slot 0, mobility role 0
*apfMsConnTask_7: Sep 06 10:24:59.050: 04:7b:cb:6c:ce:5c Client already in state(7) above L2 complete. Better delete it immediately to avoid enforcing changed policies
5. Assoc response sent with assoc denied(12), as deletion of STA entry is in progress.
*apfMsConnTask_7: Sep 06 10:24:59.164: 04:7b:cb:6c:ce:5c Received SAE auth Request from station 04:7b:cb:6c:ce:5c on AP a0:93:51:c9:24:a0
*apfMsConnTask_7: Sep 06 10:24:59.172: 04:7b:cb:6c:ce:5c PMKID:40b6a7c85fefbc4e037fd9a8c836487a
*apfMsConnTask_7: Sep 06 10:24:59.182: 04:7b:cb:6c:ce:5c apfCreatePmkCacheEntry: added a new pmk cache entry for 04:7b:cb:6c:ce:5c
*apfOpenDtlSocket: Sep 06 10:24:59.210: 04:7b:cb:6c:ce:5c Received management frame ASSOCIATION REQUEST on BSSID a0:93:51:c9:24:a0 destination addr a0:93:51:c9:24:a0
*apfMsConnTask_7: Sep 06 10:24:59.210: 04:7b:cb:6c:ce:5c Ignoring 802.11 assoc request from mobile pending deletion
*apfMsConnTask_7: Sep 06 10:24:59.210: 04:7b:cb:6c:ce:5c Sending assoc-resp with status 12 station:04:7b:cb:6c:ce:5c AP:78:72:5d:74:7e:60-01 on apVapId
6. Assoc response sent with assoc denied(12), as deletion of STA is in progress.
*apfMsConnTask_7: Sep 06 10:25:00.032: 04:7b:cb:6c:ce:5c Received SAE auth Request from station 04:7b:cb:6c:ce:5c on AP a0:93:51:c9:24:a0
*apfMsConnTask_7: Sep 06 10:25:00.040: 04:7b:cb:6c:ce:5c PMKID:f2fcd70f62550d27cb54949dbbc2569a
*apfMsConnTask_7: Sep 06 10:25:00.060: 04:7b:cb:6c:ce:5c Ignoring 802.11 assoc request from mobile pending deletion
*apfMsConnTask_7: Sep 06 10:25:00.060: 04:7b:cb:6c:ce:5c Sending assoc-resp with status 12 station:04:7b:cb:6c:ce:5c AP:78:72:5d:74:7e:60-01
7. Deleted the mobile entry
*apfReceiveTask: Sep 06 10:25:00.087: 04:7b:cb:6c:ce:5c Delete PMK cache along with client. Reason code: 1, Mobility Role: Unassociated
*apfReceiveTask: Sep 06 10:25:00.087: 04:7b:cb:6c:ce:5c Removing PMK cache entry for station 04:7b:cb:6c:ce:5c
*apfReceiveTask: Sep 06 10:25:00.087: 04:7b:cb:6c:ce:5c 0 PMK-remove groupcast messages sent
*apfReceiveTask: Sep 06 10:25:00.087: 04:7b:cb:6c:ce:5c Deleted global PMK cache and MSCB PMKID/PMK cache entry for the client
*apfReceiveTask: Sep 06 10:25:00.088: 04:7b:cb:6c:ce:5c apfMs1xStateDec
*apfReceiveTask: Sep 06 10:25:00.088: 04:7b:cb:6c:ce:5c Deleting mobile on AP 78:72:5d:74:7e:60 Looks like the deletion process with AP2 is still going on.
