(Cisco Controller) >debug client a4:d1:8c:81:68:7b (Cisco Controller) >*osapiBsnTimer: Oct 04 14:36:16.503: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:36:16.503: a4:d1:8c:81:68:7b pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Oct 04 14:36:16.503: a4:d1:8c:81:68:7b 10.110.48.211 START (0) Deleted mobile LWAPP rule on AP [d4:a0:2a:10:36:90] *pemReceiveTask: Oct 04 14:36:16.503: a4:d1:8c:81:68:7b 10.110.48.211 Removed NPU entry. *apfReceiveTask: Oct 04 14:36:16.503: a4:d1:8c:81:68:7b Deleting mobile on AP d4:a0:2a:10:36:90(0) *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Processing assoc-req station:a4:d1:8c:81:68:7b AP:d4:a0:2a:10:36:90-00 thread:15147fa0 *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Adding mobile on LWAPP AP d4:a0:2a:10:36:90(0) *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Association received from mobile on BSSID d4:a0:2a:10:36:97 AP AP-ACAD19-106-S *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Global 200 Clients are allowed to AP radio *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Max Client Trap Threshold: 0 cur: 0 *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b override for default ap group, marking intgrp NULL *apfMsConnTask_0: Oct 04 14:36:22.241: a4:d1:8c:81:68:7b Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Re-applying interface policy for client *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2435) *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2456) *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid: *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Check before Setting the NAS Id to WLAN specific Id '' *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b In processSsidIE:5737 setting Central switched to TRUE *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b In processSsidIE:5740 apVapId = 8 and Split Acl Id = 65535 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Applying site-specific Local Bridging override for station a4:d1:8c:81:68:7b - vapId 8, site 'default-group', interface 'guest' *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Applying Local Bridging Interface Policy for station a4:d1:8c:81:68:7b - vlan 1105, interface id 14, interface 'guest', nasId:'' *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b STA - rates (8): 139 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b STA - rates (10): 139 150 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_0: Oct 04 14:36:22.242: RSNIE in Assoc. Req.: (20) *apfMsConnTask_0: Oct 04 14:36:22.242: [0000] 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_0: Oct 04 14:36:22.242: [0016] ac 02 0c 00 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Processing RSN IE type 48, length 20 for mobile a4:d1:8c:81:68:7b *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Received 802.11i PSK key management suite, enabling Authentication *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b RSN Capabilities: 12 *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b Marking Mobile as non-11w Capable *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Initializing policy *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0) *apfMsConnTask_0: Oct 04 14:36:22.242: a4:d1:8c:81:68:7b 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Encryption policy is set to 0x80000001 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Not Using WMM Compliance code qosCap 00 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP d4:a0:2a:10:36:90 vapId 8 apVapId 8 flex-acl-name: *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b apfMsAssoStateInc *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b apfMsWepPskStateInc *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b apfPemAddUser2 (apf_policy.c:353) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Idle to Associated *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b apfPemAddUser2:session timeout forstation a4:d1:8c:81:68:7b - Session Tout 28000, apfMsTimeOut '28000' and sessionTimerRunning flag is 0 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 49) in 28000 seconds *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Func: apfPemAddUser2, Ms Timeout = 28000, Session Timeout = 28000 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Sending assoc-resp with status 0 station:a4:d1:8c:81:68:7b AP:d4:a0:2a:10:36:90-00 on apVapId 8 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b Sending Assoc Response to station on BSSID d4:a0:2a:10:36:97 (status 0) ApVapId 8 Slot 0 *apfMsConnTask_0: Oct 04 14:36:22.243: a4:d1:8c:81:68:7b apfProcessAssocReq (apf_80211.c:9582) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Associated to Associated *spamApTask2: Oct 04 14:36:22.246: a4:d1:8c:81:68:7b Sent 1x initiate message to multi thread task for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b reauth_sm state transition 0 ---> 1 for mobile a4:d1:8c:81:68:7b at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Creating a PKC PMKID Cache entry for station a4:d1:8c:81:68:7b (RSN 2) *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Resetting MSCB PMK Cache Entry 0 for station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Setting active key cache index 8 ---> 8 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Setting active key cache index 8 ---> 0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Adding BSSID d4:a0:2a:10:36:97 to PMKID cache at index 0 for station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: New PMKID: (16) *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: [0000] 6e e9 c3 57 f7 92 8c 79 f8 06 68 2f 53 10 ae bc *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Initiating RSN PSK to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b EAP-PARAM Debug - eap-params for Wlan-Id :8 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b dot1x - moving mobile a4:d1:8c:81:68:7b into Force Auth state *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Skipping EAP-Success to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Found an cache entry for BSSID d4:a0:2a:10:36:97 in PMKID cache at index 0 of station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Found an cache entry for BSSID d4:a0:2a:10:36:97 in PMKID cache at index 0 of station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: [0000] 6e e9 c3 57 f7 92 8c 79 f8 06 68 2f 53 10 ae bc *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Starting key exchange to mobile a4:d1:8c:81:68:7b, data packets will be dropped *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Sending EAPOL-Key Message to mobile a4:d1:8c:81:68:7b state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.247: a4:d1:8c:81:68:7b Allocating EAP Pkt for retransmission to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: a4:d1:8c:81:68:7b Received EAPOL-Key from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: a4:d1:8c:81:68:7b Received EAPOL-key in PTK_START state (message 2) from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: a4:d1:8c:81:68:7b Dumping RSNIE received in Association request: *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: 00000000: 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 0............... *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: 00000010: 00 0f ac 02 0c 00 ...... *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.251: a4:d1:8c:81:68:7b Dumping RSNIE received in EAPOL M2 : *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.252: 00000000: 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ................ *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.252: 00000010: ac 02 0c 00 .... *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.252: a4:d1:8c:81:68:7b Stopping retransmission timer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.252: a4:d1:8c:81:68:7b Sending EAPOL-Key Message to mobile a4:d1:8c:81:68:7b state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.252: a4:d1:8c:81:68:7b Reusing allocated memory for EAP Pkt for retransmission to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Received EAPOL-Key from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Stopping retransmission timer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Freeing EAP Retransmit Bufer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b apfMs1xStateInc *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3) *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Mobility query, PEM State: L2AUTHCOMPLETE *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Building Mobile Announce : *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.255: a4:d1:8c:81:68:7b Building Client Payload: *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Client Ip: 0.0.0.0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Client Vlan Ip: 10.110.48.2, Vlan mask : 255.255.240.0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Client Vap Security: 1073758208 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Virtual Ip: 1.1.1.1 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b ssid: WC-iDevices *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Building VlanIpPayload. *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP d4:a0:2a:10:36:90 vapId 8 apVapId 8 flex-acl-name: *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4) *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6575, Adding TMP rule *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule type = Airespace AP - Learn IP address on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, IP *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *apfReceiveTask: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.100.20.10 *apfReceiveTask: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED *apfReceiveTask: Oct 04 14:36:22.256: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6191, Adding TMP rule *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule type = Airespace AP - Learn IP address on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *pemReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *IPv6_Msg_Task: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b Link Local address fe80::2f:33a8:8f33:bc62 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_ASS *pemReceiveTask: Oct 04 14:36:22.257: a4:d1:8c:81:68:7b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 04 14:36:22.258: a4:d1:8c:81:68:7b Sent an XID frame *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP received op BOOTREQUEST (1) (len 308,vlan 20, port 13, encap 0xec03) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0 VLAN: 0 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP selected relay 1 - 10.100.1.11 (local address 10.110.48.2, gateway 10.110.48.1, VLAN 1105, port 13) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1d (269138461), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP siaddr: 0.0.0.0, giaddr: 10.110.48.2 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP requested ip: 10.110.48.211 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP sending REQUEST to 10.110.48.1 (len 350, port 13, vlan 1105) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.110.48.2 VLAN: 1105 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP selected relay 2 - 10.100.1.12 (local address 10.110.48.2, gateway 10.110.48.1, VLAN 1105, port 13) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2 *DHCP Socket Task: Oct 04 14:36:23.076: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1d (269138461), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP siaddr: 0.0.0.0, giaddr: 10.110.48.2 *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP requested ip: 10.110.48.211 *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP sending REQUEST to 10.110.48.1 (len 350, port 13, vlan 1105) *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP received op BOOTREPLY (2) (len 316,vlan 1105, port 13, encap 0xec00) *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP setting server from ACK (mscb=0x43254af0 ip=0xa6e30d3)(server 10.100.1.12, yiaddr 10.110.48.211) *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b DHCP setting server from ACK (server 10.100.1.12, yiaddr 10.110.48.211) *DHCP Socket Task: Oct 04 14:36:23.077: a4:d1:8c:81:68:7b Static IP client associated to interface guest which can support client subnet. *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b apfMsRunStateInc *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7) *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Reached PLUMBFASTPATH: from line 7241 *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Replacing Fast Path rule type = Airespace AP Client on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, IPv6 ACL I *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b Assigning Address 10.110.48.211 to mobile *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b DHCP success event for client. Clearing dhcp failure count for interface guest. *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b DHCP success event for client. Clearing dhcp failure count for interface guest. *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b DHCP sending REPLY to STA (len 426, port 13, vlan 20) *DHCP Socket Task: Oct 04 14:36:23.078: a4:d1:8c:81:68:7b DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1d (269138461), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 10.110.48.211 *DHCP Socket Task: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b DHCP server id: 1.1.1.1 rcvd server id: 10.100.1.12 *pemReceiveTask: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b 10.110.48.211 Added NPU entry of type 1, dtlFlags 0x0 *pemReceiveTask: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b Pushing IPv6: fe80:0000:0000:0000:002f:33a8:8f33:bc62 , intfId:14 and MAC: A4:D1:8C:81:68:7B , Binding to Data Plane. SUCCESS !! *pemReceiveTask: Oct 04 14:36:23.079: a4:d1:8c:81:68:7b Sending a gratuitous ARP for 10.110.48.211, VLAN Id 1105 *IPv6_Msg_Task: Oct 04 14:36:23.134: a4:d1:8c:81:68:7b Link Local address fe80::2f:33a8:8f33:bc62 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_ASS *dtlArpTask: Oct 04 14:36:28.854: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 84) in 1 seconds *dtlArpTask: Oct 04 14:36:28.854: a4:d1:8c:81:68:7b In apfRegisterIpAddrOnMscb_debug --- Duplicate static IP detected for the client. IP is used by the client - a4:d1:8c:81:68:7b *dtlArpTask: Oct 04 14:36:28.854: a4:d1:8c:81:68:7b IPv4 Addr: 10:110:48:68 *osapiBsnTimer: Oct 04 14:36:29.703: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:36:29.707: a4:d1:8c:81:68:7b apfMsExpireMobileStation (apf_ms.c:7069) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Associated to Disassociated *apfReceiveTask: Oct 04 14:36:29.707: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds *osapiBsnTimer: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Sent Deauthenticate to mobile on BSSID d4:a0:2a:10:36:90 slot 0(caller apf_ms.c:7163) *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Resetting MSCB PMK Cache Entry 0 for station a4:d1:8c:81:68:7b *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Removing BSSID d4:a0:2a:10:36:97 from PMKID cache of station a4:d1:8c:81:68:7b *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Setting active key cache index 0 ---> 8 *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Deleting the PMK cache when de-authenticating the client. *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b Global PMK Cache deletion failed. *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b apfMsAssoStateDec *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b apfMsWepPskStateDec *apfReceiveTask: Oct 04 14:36:39.703: a4:d1:8c:81:68:7b apfMsExpireMobileStation (apf_ms.c:7201) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Disassociated to Idle *apfReceiveTask: Oct 04 14:36:39.704: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 47) in 10 seconds *osapiBsnTimer: Oct 04 14:36:49.710: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:36:49.711: a4:d1:8c:81:68:7b pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Oct 04 14:36:49.711: a4:d1:8c:81:68:7b 10.110.48.211 START (0) Deleted mobile LWAPP rule on AP [d4:a0:2a:10:36:90] *apfReceiveTask: Oct 04 14:36:49.711: a4:d1:8c:81:68:7b Deleting mobile on AP d4:a0:2a:10:36:90(0) *pemReceiveTask: Oct 04 14:36:49.712: a4:d1:8c:81:68:7b 10.110.48.211 Removed NPU entry. *apfMsConnTask_0: Oct 04 14:37:01.234: a4:d1:8c:81:68:7b Processing assoc-req station:a4:d1:8c:81:68:7b AP:d4:a0:2a:10:36:90-00 thread:15147fa0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Adding mobile on LWAPP AP d4:a0:2a:10:36:90(0) *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Association received from mobile on BSSID d4:a0:2a:10:36:97 AP AP-ACAD19-106-S *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Global 200 Clients are allowed to AP radio *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Max Client Trap Threshold: 0 cur: 0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b override for default ap group, marking intgrp NULL *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Re-applying interface policy for client *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2435) *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2456) *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid: *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Check before Setting the NAS Id to WLAN specific Id '' *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b In processSsidIE:5737 setting Central switched to TRUE *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b In processSsidIE:5740 apVapId = 8 and Split Acl Id = 65535 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Applying site-specific Local Bridging override for station a4:d1:8c:81:68:7b - vapId 8, site 'default-group', interface 'guest' *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b Applying Local Bridging Interface Policy for station a4:d1:8c:81:68:7b - vlan 1105, interface id 14, interface 'guest', nasId:'' *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b STA - rates (8): 139 150 24 36 48 72 96 108 0 0 0 0 0 0 0 0 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_0: Oct 04 14:37:01.235: a4:d1:8c:81:68:7b STA - rates (10): 139 150 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_0: Oct 04 14:37:01.236: RSNIE in Assoc. Req.: (20) *apfMsConnTask_0: Oct 04 14:37:01.236: [0000] 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_0: Oct 04 14:37:01.236: [0016] ac 02 0c 00 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Processing RSN IE type 48, length 20 for mobile a4:d1:8c:81:68:7b *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Received 802.11i PSK key management suite, enabling Authentication *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b RSN Capabilities: 12 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Marking Mobile as non-11w Capable *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Initializing policy *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0) *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Encryption policy is set to 0x80000001 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Not Using WMM Compliance code qosCap 00 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP d4:a0:2a:10:36:90 vapId 8 apVapId 8 flex-acl-name: *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b apfMsAssoStateInc *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b apfMsWepPskStateInc *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b apfPemAddUser2 (apf_policy.c:353) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Idle to Associated *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b apfPemAddUser2:session timeout forstation a4:d1:8c:81:68:7b - Session Tout 28000, apfMsTimeOut '28000' and sessionTimerRunning flag is 0 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 49) in 28000 seconds *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Func: apfPemAddUser2, Ms Timeout = 28000, Session Timeout = 28000 *apfMsConnTask_0: Oct 04 14:37:01.236: a4:d1:8c:81:68:7b Sending assoc-resp with status 0 station:a4:d1:8c:81:68:7b AP:d4:a0:2a:10:36:90-00 on apVapId 8 *apfMsConnTask_0: Oct 04 14:37:01.237: a4:d1:8c:81:68:7b Sending Assoc Response to station on BSSID d4:a0:2a:10:36:97 (status 0) ApVapId 8 Slot 0 *spamApTask2: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Sent 1x initiate message to multi thread task for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b reauth_sm state transition 0 ---> 1 for mobile a4:d1:8c:81:68:7b at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Creating a PKC PMKID Cache entry for station a4:d1:8c:81:68:7b (RSN 2) *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Resetting MSCB PMK Cache Entry 0 for station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Setting active key cache index 8 ---> 8 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Setting active key cache index 8 ---> 0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Adding BSSID d4:a0:2a:10:36:97 to PMKID cache at index 0 for station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: New PMKID: (16) *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: [0000] 6e e9 c3 57 f7 92 8c 79 f8 06 68 2f 53 10 ae bc *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b Initiating RSN PSK to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.239: a4:d1:8c:81:68:7b EAP-PARAM Debug - eap-params for Wlan-Id :8 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b dot1x - moving mobile a4:d1:8c:81:68:7b into Force Auth state *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Skipping EAP-Success to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Found an cache entry for BSSID d4:a0:2a:10:36:97 in PMKID cache at index 0 of station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Found an cache entry for BSSID d4:a0:2a:10:36:97 in PMKID cache at index 0 of station a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: [0000] 6e e9 c3 57 f7 92 8c 79 f8 06 68 2f 53 10 ae bc *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Starting key exchange to mobile a4:d1:8c:81:68:7b, data packets will be dropped *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Sending EAPOL-Key Message to mobile a4:d1:8c:81:68:7b state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.240: a4:d1:8c:81:68:7b Allocating EAP Pkt for retransmission to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: a4:d1:8c:81:68:7b Received EAPOL-Key from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: a4:d1:8c:81:68:7b Received EAPOL-key in PTK_START state (message 2) from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: a4:d1:8c:81:68:7b Dumping RSNIE received in Association request: *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: 00000000: 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 0............... *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: 00000010: 00 0f ac 02 0c 00 ...... *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: a4:d1:8c:81:68:7b Dumping RSNIE received in EAPOL M2 : *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: 00000000: 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ................ *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: 00000010: ac 02 0c 00 .... *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.245: a4:d1:8c:81:68:7b Stopping retransmission timer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.246: a4:d1:8c:81:68:7b Sending EAPOL-Key Message to mobile a4:d1:8c:81:68:7b state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.246: a4:d1:8c:81:68:7b Reusing allocated memory for EAP Pkt for retransmission to mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Received EAPOL-Key from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Stopping retransmission timer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Freeing EAP Retransmit Bufer for mobile a4:d1:8c:81:68:7b *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b apfMs1xStateInc *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3) *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Mobility query, PEM State: L2AUTHCOMPLETE *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Building Mobile Announce : *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Building Client Payload: *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Client Ip: 0.0.0.0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Client Vlan Ip: 10.110.48.2, Vlan mask : 255.255.240.0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Client Vap Security: 1073758208 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Virtual Ip: 1.1.1.1 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b ssid: WC-iDevices *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Building VlanIpPayload. *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP d4:a0:2a:10:36:90 vapId 8 apVapId 8 flex-acl-name: *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.249: a4:d1:8c:81:68:7b 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4) *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6575, Adding TMP rule *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule type = Airespace AP - Learn IP address on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, IP *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_3: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.100.20.10 *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6191, Adding TMP rule *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule type = Airespace AP - Learn IP address on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 04 14:37:01.250: a4:d1:8c:81:68:7b 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *pemReceiveTask: Oct 04 14:37:01.251: a4:d1:8c:81:68:7b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 04 14:37:01.251: a4:d1:8c:81:68:7b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 04 14:37:01.251: a4:d1:8c:81:68:7b Sent an XID frame *IPv6_Msg_Task: Oct 04 14:37:01.251: a4:d1:8c:81:68:7b Link Local address fe80::2f:33a8:8f33:bc62 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_ASS *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP received op BOOTREQUEST (1) (len 308,vlan 20, port 13, encap 0xec03) *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0 VLAN: 0 *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP selected relay 1 - 10.100.1.11 (local address 10.110.48.2, gateway 10.110.48.1, VLAN 1105, port 13) *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1e (269138462), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP siaddr: 0.0.0.0, giaddr: 10.110.48.2 *DHCP Socket Task: Oct 04 14:37:01.820: a4:d1:8c:81:68:7b DHCP requested ip: 10.110.48.211 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP sending REQUEST to 10.110.48.1 (len 350, port 13, vlan 1105) *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 10.110.48.2 VLAN: 1105 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP selected relay 2 - 10.100.1.12 (local address 10.110.48.2, gateway 10.110.48.1, VLAN 1105, port 13) *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1e (269138462), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP siaddr: 0.0.0.0, giaddr: 10.110.48.2 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP requested ip: 10.110.48.211 *DHCP Socket Task: Oct 04 14:37:01.821: a4:d1:8c:81:68:7b DHCP sending REQUEST to 10.110.48.1 (len 350, port 13, vlan 1105) *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b DHCP received op BOOTREPLY (2) (len 316,vlan 1105, port 13, encap 0xec00) *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b DHCP setting server from ACK (mscb=0x42a2f9a0 ip=0xa6e30d3)(server 10.100.1.12, yiaddr 10.110.48.211) *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b DHCP setting server from ACK (server 10.100.1.12, yiaddr 10.110.48.211) *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b Static IP client associated to interface guest which can support client subnet. *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b apfMsRunStateInc *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7) *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Reached PLUMBFASTPATH: from line 7241 *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Replacing Fast Path rule type = Airespace AP Client on AP d4:a0:2a:10:36:90, slot 0, interface = 13, QOS = 0 IPv4 ACL ID = 255, IPv6 ACL I *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 1105, Local Bridging intf id = 14 *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 04 14:37:01.822: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b 10.110.48.211 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b Assigning Address 10.110.48.211 to mobile *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP success event for client. Clearing dhcp failure count for interface guest. *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP success event for client. Clearing dhcp failure count for interface guest. *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP sending REPLY to STA (len 426, port 13, vlan 20) *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP xid: 0x100aba1e (269138462), secs: 0, flags: 0 *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP chaddr: a4:d1:8c:81:68:7b *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP ciaddr: 0.0.0.0, yiaddr: 10.110.48.211 *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP siaddr: 10.100.1.69, giaddr: 0.0.0.0 *DHCP Socket Task: Oct 04 14:37:01.823: a4:d1:8c:81:68:7b DHCP server id: 1.1.1.1 rcvd server id: 10.100.1.12 *pemReceiveTask: Oct 04 14:37:01.825: a4:d1:8c:81:68:7b 10.110.48.211 Added NPU entry of type 1, dtlFlags 0x0 *pemReceiveTask: Oct 04 14:37:01.825: a4:d1:8c:81:68:7b Pushing IPv6: fe80:0000:0000:0000:002f:33a8:8f33:bc62 , intfId:14 and MAC: A4:D1:8C:81:68:7B , Binding to Data Plane. SUCCESS !! *pemReceiveTask: Oct 04 14:37:01.825: a4:d1:8c:81:68:7b Sending a gratuitous ARP for 10.110.48.211, VLAN Id 1105 *IPv6_Msg_Task: Oct 04 14:37:01.871: a4:d1:8c:81:68:7b Link Local address fe80::2f:33a8:8f33:bc62 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_ASS *dtlArpTask: Oct 04 14:37:08.328: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 84) in 1 seconds *dtlArpTask: Oct 04 14:37:08.328: a4:d1:8c:81:68:7b In apfRegisterIpAddrOnMscb_debug --- Duplicate static IP detected for the client. IP is used by the client - a4:d1:8c:81:68:7b *dtlArpTask: Oct 04 14:37:08.328: a4:d1:8c:81:68:7b IPv4 Addr: 10:110:48:68 *osapiBsnTimer: Oct 04 14:37:09.311: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:37:09.311: a4:d1:8c:81:68:7b apfMsExpireMobileStation (apf_ms.c:7069) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Associated to Disassociated *apfReceiveTask: Oct 04 14:37:09.311: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds *osapiBsnTimer: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b Sent Deauthenticate to mobile on BSSID d4:a0:2a:10:36:90 slot 0(caller apf_ms.c:7163) *apfReceiveTask: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b Resetting MSCB PMK Cache Entry 0 for station a4:d1:8c:81:68:7b *apfReceiveTask: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b Removing BSSID d4:a0:2a:10:36:97 from PMKID cache of station a4:d1:8c:81:68:7b *apfReceiveTask: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b Setting active key cache index 0 ---> 8 *apfReceiveTask: Oct 04 14:37:19.311: a4:d1:8c:81:68:7b Deleting the PMK cache when de-authenticating the client. *apfReceiveTask: Oct 04 14:37:19.312: a4:d1:8c:81:68:7b Global PMK Cache deletion failed. *apfReceiveTask: Oct 04 14:37:19.312: a4:d1:8c:81:68:7b apfMsAssoStateDec *apfReceiveTask: Oct 04 14:37:19.312: a4:d1:8c:81:68:7b apfMsWepPskStateDec *apfReceiveTask: Oct 04 14:37:19.312: a4:d1:8c:81:68:7b apfMsExpireMobileStation (apf_ms.c:7201) Changing state for mobile a4:d1:8c:81:68:7b on AP d4:a0:2a:10:36:90 from Disassociated to Idle *apfReceiveTask: Oct 04 14:37:19.312: a4:d1:8c:81:68:7b Scheduling deletion of Mobile Station: (callerId: 47) in 10 seconds (Cisco Controller) >debug disable-all*Apf Guest: Oct 04 14:37:23.111: Wired client head is NULL, no clients in the list. Number of clients = 0 *osapiBsnTimer: Oct 04 14:37:29.310: a4:d1:8c:81:68:7b apfMsExpireCallback (apf_ms.c:637) Expiring Mobile! *apfReceiveTask: Oct 04 14:37:29.311: a4:d1:8c:81:68:7b pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Oct 04 14:37:29.311: a4:d1:8c:81:68:7b 10.110.48.211 START (0) Deleted mobile LWAPP rule on AP [d4:a0:2a:10:36:90]