10-13-2020 01:46 AM - edited 07-05-2021 12:38 PM
Hi All
I've recently upgraded from 8.5.161.0 to 8.10.130.0 on my WLC 5520. All my APs are in local mode, but one (2802i), which is in Flexconnect Central switching. That AP has OEAP enabled.
For whatever reason, the clients at that remote location can't anymore connect. I'm currently trying to get a client debug, but not many users are there. I rebooted the AP already and it looks correctly connected.
Has anything important changed in regards to Flexconnect?
Is there a way to debug an AP in Flex mode?
Thanks
Patrick
Solved! Go to Solution.
10-13-2020 04:48 AM
And me again. It looks like I might be hitting:
https://bst.cloudapps.cisco.com/bugsearch/bug/CSCvu58082
I will now try with DTLS disabled (it's luckily over a VPN).
10-13-2020 02:05 AM
I was able to acquire a client debug:
*apfOpenDtlSocket: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Received management frame ASSOCIATION REQUEST on BSSID f4:db:e6:d9:fc:ad destination addr f4:db:e6:d9:fc:ad slotid 1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Updating the client capabiility as 4 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Processing assoc-req station:d0:c6:37:65:a4:46 AP:f4:db:e6:d9:fc:a0-01 ssid : eduroam thread:642732a60 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Station: D0:C6:37:65:A4:46 trying to join WLAN with RSSI -51. Checking for XOR roam conditions on AP: F4:DB:E6:D9:FC:A0 Slot: 1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Station: D0:C6:37:65:A4:46 is associating to AP F4:DB:E6:D9:FC:A0 which is not XOR roam capable *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Updating location for mobile on same AP f4:db:e6:d9:fc:a0-1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Setting RTTS enabled to 0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Association received from mobile on BSSID f4:db:e6:d9:fc:ad AP 2802AC-WERZ-1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Station: D0:C6:37:65:A4:46 trying to join WLAN with RSSI -51. Checking for XOR roam conditions on AP: F4:DB:E6:D9:FC:A0 Slot: 1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Station: D0:C6:37:65:A4:46 is associating to AP F4:DB:E6:D9:FC:A0 which is not XOR roam capable *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Global 200 Clients are allowed to AP radio *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Max Client Trap Threshold: 0 cur: 2 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 IP Addr Clear. AP MAC[f4:db:e6:d9:fc:a0] Role[Unassociated] Pem State [8021X_REQD] Connected Time[488] *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) NO release MSCB *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 1 PMK-remove groupcast messages sent *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Deleted global PMK cache and MSCB PMKID/PMK cache entry for the client *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 the value of url acl preserve flag is 0 for mobile d0:c6:37:65:a4:46 (caller pem_api.c:5283) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [f4:db:e6:d9:fc:a0] *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Succesfully freed AID 2, slot 1 on AP f4:db:e6:d9:fc:a0, #client on this slot 1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) mobility role update request from Unassociated to Handoff Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 0.0.0.0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 IP Addr Clear. AP MAC[f4:db:e6:d9:fc:a0] Role[Unassociated] Pem State [8021X_REQD] Connected Time[488] *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) NO release MSCB *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) mobility role update request from Handoff to Unassociated Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 0.0.0.0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) NO release MSCB *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Cleared flex switching flags and local switching vlan *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 apf_policy.c:959 Clearing the SGT 0 of mobile *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Decrement the SGT 0 policy count reference by the clients 869 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Updated local bridging VLAN to 240 while applying WLAN policy *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 override for default ap group, marking intgrp NULL *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 232 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 After applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3486) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255),Default action is '0' --- (caller apf_policy.c:3506) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3527) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Check before Setting the NAS Id to WLAN specific Id '' *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 apf_policy.c:2771 Assigning the SGT 0 to mobile (earlier sgt 0) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Increment the SGT 0 policy count reference by the clients 870 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Check the client SGT 0 policy and push it to AP f4:db:e6:d9:fc:a0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 In processSsidIE:7589 setting Central switched to TRUE *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 In processSsidIE:7592 apVapId = 3 and Split Acl Id = 65535 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Applying site-specific Local Bridging override for station d0:c6:37:65:a4:46 - vapId 3, site 'default-group', interface 'int-vlan-240' *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Applying Local Bridging Interface Policy for station d0:c6:37:65:a4:46 - vlan 240, interface id 22, interface 'int-vlan-240', nasId:'' *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 STA - rates (6): 12 164 176 72 96 108 0 0 0 0 0 0 0 0 0 0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] RSNIE in Assoc. Req.: (22) *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] [0016] ac 01 bc 00 00 00 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Processing RSN IE type 48, length 22 for mobile d0:c6:37:65:a4:46 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Selected Unicast cipher CCMP128 for client device *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Received 802.11i 802.1X key management suite, enabling dot1x Authentication *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 RSN Capabilities: 188 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Marking Mobile as 11w Capable *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Received RSN IE(AKM:1) with 0 PMKIDs *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Setting active key cache index 0 ---> 8 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 unsetting PmkIdValidatedByAp *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Making Group Mgmt Cipher Suite default for mobile d0:c6:37:65:a4:46 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Assigning flex webauth IPv4-ACL ID :65535, IPv6-ACL ID:65535 for AP WLAN ID : 3 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Updating AID for REAP AP Client f4:db:e6:d9:fc:a0 - AID ===> 2 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Assoc Req BSSID f4:db:e6:d9:fc:ad AP(2802AC-WERZ-1) slot 1 ssid (eduroam) Tmstmp 382961 AID 2 stCode 0/0 apChngd 0 oldAp F4:DB:E6:D9:FC:A0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 Authreqd flag unchanged 1 for mobile with macAuthType [0] pemSt 3 secWord 4000 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Initializing policy *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 apfVapSecurity=0x4000 L2=16384 SkipWeb=0 *apfMsConnTask_4: Oct 13 10:56:00.084: [PA] d0:c6:37:65:a4:46 AuthenticationRequired = 1 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Encryption policy is set to 0x80000001 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Flex Central Auth Client *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Setting the action to initiate 1x 4 way handshake upon Add_Mobile_Ack for station with encrypt policy:[80000001] *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 flex webauth ipv4 & ipv6 acl ids to be sent when fabric is disabled:65535/65535 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 flex webauth acl id to be sent :65535 name : client acl id :65535 name : *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 flex webauth ipv6 acl id to be sent :65535 name : client acl id :65535 name : *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Vlan while overriding the policy = -1 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP f4:db:e6:d9:fc:a0 vapId 3 apVapId 3 flex acl-name: v6acl-name *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 apfPemAddUser2 (apf_policy.c:465) Changing state for mobile d0:c6:37:65:a4:46 on AP f4:db:e6:d9:fc:a0 from Associated to Associated *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 apfPemAddUser2:session timeout forstation d0:c6:37:65:a4:46 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Stopping deletion of Mobile Station: (callerId: 48) *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Sending assoc-resp with status 0 station:d0:c6:37:65:a4:46 AP:f4:db:e6:d9:fc:a0-01 on apVapId 3 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 VHT Operation IE: width 80/1 ch 100 freq0 106 freq1 0 msc0 0xff msc1 0xff *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Sending Assoc Response (status: '0') to station on AP 2802AC-WERZ-1 on BSSID f4:db:e6:d9:fc:ad ApVapId 3 Slot 1, mobility role 0 *apfMsConnTask_4: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 apfProcessAssocReq (apf_80211.c:12920) Changing state for mobile d0:c6:37:65:a4:46 on AP f4:db:e6:d9:fc:a0 from Associated to Associated *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Setting DEL_MOBILE (seqno 0, action 6) ack state for STA on AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Setting ADD_MOBILE (idx 3, seqno 204, action 6, count 204, last count 204) ack state for STA on AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Delete Mobile request with reason 'MN_DEL_PEM_CLEANUP' on slot 1 sent to the AP f4:db:e6:d9:fc:a0 IP: 172.16.3.20:5256. *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Add SGT:0 to AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0 *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 MS IP NULL during AddMobile, not sending IP Distribution *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Flex Ipv6 pre-auth acl is not present, not Encoding Flex Ipv6 acl for add mobile Payload *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Flex Ipv6 post auth acl is not present, not updating add mobile Payload *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Successful transmission of LWAPP Add-Mobile to AP f4:db:e6:d9:fc:a0 slotId 1 idx@4 *spamApTask3: Oct 13 10:56:00.085: [PA] d0:c6:37:65:a4:46 Setting ADD_MOBILE (idx 4, seqno 205, action 1, count 205, last count 205) ack state for STA on AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:00.091: [PA] d0:c6:37:65:a4:46 Received add/del ack packet with sequence number: got 204 expected 204 action = 6 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 reauth_sm state transition 0 ---> 1 for mobile d0:c6:37:65:a4:46 at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 EAP-PARAM Debug - eap-params for Wlan-Id :3 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 Station d0:c6:37:65:a4:46 setting dot1x reauth timeout = 0 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 Stopping reauth timeout for d0:c6:37:65:a4:46 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 Received EAPOL START from mobile in dot1x state = 2 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.096: [PA] d0:c6:37:65:a4:46 Ignoring EAPOL-Start as client still ongoing AddMnAckPend:1 or EAPOL-Key HS state:0) *spamApTask3: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 Received add/del ack packet with sequence number: got 205 expected 205 action = 1 *spamApTask3: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 Sent dot1x auth initiate message for mobile d0:c6:37:65:a4:46 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 dot1xProcessInitiate1XtoMobile to mobile station d0:c6:37:65:a4:46 (mscb 3, msg 3) *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 reauth_sm state transition 1 ---> 0 for mobile d0:c6:37:65:a4:46 at 1x_reauth_sm.c:53 *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 EAP-PARAM Debug - eap-params for Wlan-Id :3 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 dot1x - moving mobile d0:c6:37:65:a4:46 into Connecting state *Dot1x_NW_MsgTask_6: Oct 13 10:56:00.116: [PA] d0:c6:37:65:a4:46 Sending EAP-Request/Identity to mobile d0:c6:37:65:a4:46 (EAP Id 1) *apfMsConnTask_7: Oct 13 10:56:00.280: [PA] apfVapRadiusNasIpAddrGet: Client 24:77:03:C4:E7:C4 NAS IP Attribute: 172.16.240.241 *apfMsConnTask_2: Oct 13 10:56:00.830: [PA] apfVapRadiusNasIpAddrGet: Client A0:A4:C5:46:B6:4E NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_6: Oct 13 10:56:01.098: [PA] d0:c6:37:65:a4:46 Received EAPOL START from mobile in dot1x state = 2 *Dot1x_NW_MsgTask_6: Oct 13 10:56:01.098: [PA] d0:c6:37:65:a4:46 reauth_sm state transition 0 ---> 1 for mobile d0:c6:37:65:a4:46 at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_6: Oct 13 10:56:01.098: [PA] d0:c6:37:65:a4:46 Received EAPOL START from mobile d0:c6:37:65:a4:46 *Dot1x_NW_MsgTask_6: Oct 13 10:56:01.098: [PA] d0:c6:37:65:a4:46 dot1x - moving mobile d0:c6:37:65:a4:46 into Connecting state *Dot1x_NW_MsgTask_6: Oct 13 10:56:01.098: [PA] d0:c6:37:65:a4:46 Sending EAP-Request/Identity to mobile d0:c6:37:65:a4:46 (EAP Id 2) *apfMsConnTask_2: Oct 13 10:56:01.458: [PA] apfVapRadiusNasIpAddrGet: Client CC:F9:E4:83:0B:B2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.554: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.612: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.639: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.644: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.648: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.653: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.684: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.694: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.698: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.703: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.712: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.720: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:01.725: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 Received EAPOL START from mobile in dot1x state = 2 *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 Reset the reauth counter since EAPOL START has been received!!! *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 reauth_sm state transition 1 ---> 1 for mobile d0:c6:37:65:a4:46 at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 Received EAPOL START from mobile d0:c6:37:65:a4:46 *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 dot1x - moving mobile d0:c6:37:65:a4:46 into Connecting state *Dot1x_NW_MsgTask_6: Oct 13 10:56:02.100: [PA] d0:c6:37:65:a4:46 Sending EAP-Request/Identity to mobile d0:c6:37:65:a4:46 (EAP Id 3) *apfOpenDtlSocket: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Received management frame DEAUTH on BSSID f4:db:e6:d9:fc:ad destination addr f4:db:e6:d9:fc:ad slotid 1 *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Got deauth frame from D0:C6:37:65:A4:46 BSSID= F4:DB:E6:D9:FC:A0 reasoncode = 1 dataLen = 2 *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 the value of url acl preserve flag is 0 for mobile d0:c6:37:65:a4:46 (caller pem_api.c:5283) *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 0.0.0.0 8021X_REQD (3) Deleted mobile LWAPP rule on AP [f4:db:e6:d9:fc:a0] *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Succesfully freed AID 2, slot 1 on AP f4:db:e6:d9:fc:a0, #client on this slot 1 *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 apfProcessDisassocOrDeauth (apf_80211.c:14315) Changing state for mobile d0:c6:37:65:a4:46 on AP f4:db:e6:d9:fc:a0 from Associated to Disassociated *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Stopping SA Query retry timer and resetting 11w ClientSecure status of Mobile Station *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Scheduling deletion of Mobile Station: reasonCode 4 (callerId: 25) in 30 seconds *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 apfMsAssoStateDec *apfMsConnTask_4: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 apfProcessDisassocOrDeauth (apf_80211.c:14411) Changing state for mobile d0:c6:37:65:a4:46 on AP f4:db:e6:d9:fc:a0 from Disassociated to Idle *spamApTask3: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Setting DEL_MOBILE (seqno 0, action 6) ack state for STA on AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Setting ADD_MOBILE (idx 5, seqno 206, action 6, count 206, last count 206) ack state for STA on AP f4:db:e6:d9:fc:a0 *spamApTask3: Oct 13 10:56:03.107: [PA] d0:c6:37:65:a4:46 Delete Mobile request with reason 'MN_DEL_PEM_CLEANUP' on slot 1 sent to the AP f4:db:e6:d9:fc:a0 IP: 172.16.3.20:5256. *spamApTask3: Oct 13 10:56:03.113: [PA] d0:c6:37:65:a4:46 Received add/del ack packet with sequence number: got 206 expected 206 action = 6 *apfReceiveTask: Oct 13 10:56:03.615: [PA] apfVapRadiusNasIpAddrGet: Client F0:79:60:41:30:F3 NAS IP Attribute: 172.16.240.241 d*apfMsConnTask_2: Oct 13 10:56:04.519: [PA] apfVapRadiusNasIpAddrGet: Client C8:58:C0:EB:3F:F2 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:05.335: [PA] apfVapRadiusNasIpAddrGet: Client 5E:0C:5E:6F:9C:92 NAS IP Attribute: 172.16.240.241 *DHCP Socket Task: Oct 13 10:56:05.605: [PA] IP Context distribution - event: (DHCP IP LEARN) msCount: 1 ToAllAps: 1 *DHCP Socket Task: Oct 13 10:56:05.605: [PA] apfVapRadiusNasIpAddrGet: Client 6A:39:B5:AC:B5:21 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:06.687: [PA] apfVapRadiusNasIpAddrGet: Client 1A:63:E5:BF:C7:C1 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:07.976: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:08.029: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:08.040: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:08.045: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:08.050: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:08.055: [PA] apfVapRadiusNasIpAddrGet: Client 92:1C:2F:87:78:B9 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:10.367: [PA] apfVapRadiusNasIpAddrGet: Client B8:53:AC:D7:4B:74 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:10.561: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:10.582: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:10.594: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:10.601: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:10.647: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:13.227: [PA] apfVapRadiusNasIpAddrGet: Client 78:67:D7:41:D9:09 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:13.654: [PA] apfVapRadiusNasIpAddrGet: Client A4:D9:31:69:AC:F8 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:13.681: [PA] apfVapRadiusNasIpAddrGet: Client A4:D9:31:69:AC:F8 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:13.709: [PA] apfVapRadiusNasIpAddrGet: Client A4:D9:31:69:AC:F8 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:13.719: [PA] apfVapRadiusNasIpAddrGet: Client A4:D9:31:69:AC:F8 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.358: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.390: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.398: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.403: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.632: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:14.639: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 eb*Dot1x_NW_MsgTask_2: Oct 13 10:56:15.196: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:15.205: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 ug*Dot1x_NW_MsgTask_2: Oct 13 10:56:15.360: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:15.365: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:15.388: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:15.407: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:15.444: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 ds*Dot1x_NW_MsgTask_0: Oct 13 10:56:16.097: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.117: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.127: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.136: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.157: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.166: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.173: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.179: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.204: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.218: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_0: Oct 13 10:56:16.225: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 i*Dot1x_NW_MsgTask_3: Oct 13 10:56:16.363: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 a*Dot1x_NW_MsgTask_3: Oct 13 10:56:16.410: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.431: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.437: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.442: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.455: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.473: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.479: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.484: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.489: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.497: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.506: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_3: Oct 13 10:56:16.511: [PA] apfVapRadiusNasIpAddrGet: Client 84:AB:1A:AC:E0:C3 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:17.107: [PA] apfVapRadiusNasIpAddrGet: Client 14:C8:8B:61:70:D9 NAS IP Attribute: 172.16.240.241 Incorrect usage. Use the '?' or <TAB> key to list commands. (Cisco Controller) >*Dot1x_NW_MsgTask_1: Oct 13 10:56:18.834: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:18.841: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:18.849: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:18.853: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:18.857: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_1: Oct 13 10:56:18.866: [PA] apfVapRadiusNasIpAddrGet: Client AC:FD:CE:F3:6A:29 NAS IP Attribute: 172.16.240.241 debug dsia*apfOrphanSocketTask: Oct 13 10:56:19.660: [PA] apfVapRadiusNasIpAddrGet: Client 00:F7:6F:AA:7A:DA NAS IP Attribute: 172.16.240.241 debug client d0:c6:37:65:a4:46*apfReceiveTask: Oct 13 10:56:19.910: [PA] apfVapRadiusNasIpAddrGet: Client D6:56:78:BF:A8:DA NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:19.931: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:19.973: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:19.994: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.001: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.006: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.016: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.037: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.042: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.046: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.052: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.058: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.065: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:20.070: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:20.187: [PA] apfVapRadiusNasIpAddrGet: Client B0:C0:90:9E:E5:8C NAS IP Attribute: 172.16.240.241 debug dsi*apfOrphanSocketTask: Oct 13 10:56:21.705: [PA] apfVapRadiusNasIpAddrGet: Client 04:4F:4C:0E:FB:08 NAS IP Attribute: 172.16.240.241 *DHCP Socket Task: Oct 13 10:56:21.719: [PA] IP Context distribution - event: (DHCP IP LEARN) msCount: 1 ToAllAps: 1 i*apfReceiveTask: Oct 13 10:56:22.643: [PA] apfVapRadiusNasIpAddrGet: Client 14:87:6A:6A:23:49 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:23.055: [PA] apfVapRadiusNasIpAddrGet: Client 54:99:63:C1:C4:A2 NAS IP Attribute: 172.16.240.241 *apfReceiveTask: Oct 13 10:56:23.259: [PA] apfVapRadiusNasIpAddrGet: Client B0:CA:68:00:6C:5F NAS IP Attribute: 172.16.240.241 *Dot1x_NW_MsgTask_2: Oct 13 10:56:23.264: [PA] apfVapRadiusNasIpAddrGet: Client 98:28:A6:78:1D:6A NAS IP Attribute: 172.16.240.241
10-13-2020 03:24 AM
And I told https://cway.cisco.com/tools/WirelessDebugAnalyzer/ eat it baby :
( you may want to do it yourself too, there is more info if you check the flag Show Original, the forum may also wrap some essential output
TimeTaskTranslated
Oct 13 10:56:00.084 | *apfMsConnTask_4 | Client made new Association to AP/BSSID BSSID f4:db:e6:d9:fc:ad AP 2802AC-WERZ-1 |
Oct 13 10:56:00.084 | *apfMsConnTask_4 | The WLC/AP has found from client association request Information Element that claims PMKID Caching support |
Oct 13 10:56:00.085 | *apfMsConnTask_4 | Client is entering the 802.1x or PSK Authentication state |
Oct 13 10:56:00.085 | *apfMsConnTask_4 | WLC/AP is sending an Association Response to the client with status code 0 = Successful association |
Oct 13 10:56:00.096 | *Dot1x_NW_MsgTask_6 | Client will be required to Reauthenticate in 0 seconds |
Oct 13 10:56:00.116 | *Dot1x_NW_MsgTask_6 | WLC/AP is sending EAP-Identity-Request to the client |
Oct 13 10:56:01.098 | *Dot1x_NW_MsgTask_6 | WLC/AP is sending EAP-Identity-Request to the client |
Oct 13 10:56:02.100 | *Dot1x_NW_MsgTask_6 | WLC/AP is sending EAP-Identity-Request to the client |
Oct 13 10:56:03.107 | *apfMsConnTask_4 | Client expiration timer code set for 30 seconds. The reason: Dissasociation or deauthentication received from client, this is valid on 802.11w scenario |
10-13-2020 03:47 AM
10-13-2020 04:15 AM
- Does this apply to a specific vendor-client model , or do several different client-types have the same problem ?
M.
10-13-2020 04:20 AM
10-13-2020 04:27 AM
- Good thinking ,meaning all underlying link-issues should get resolved first, to avoid having a clouded (!) view on the issue.
M.
10-13-2020 04:35 AM
Connection is back.
It seems to be some other issue, the AP is constantly loosing its CAPWAP connection and restarting it.
From the AP log:
Oct 13 11:30:51 kernel: [*10/13/2020 11:30:51.2757] set cleanair [slot0][band0] enabled Oct 13 11:30:51 NCI: I0: openSensor(slot=0) Oct 13 11:30:51 kernel: [*10/13/2020 11:30:51.2815] set cleanair [slot0][band1] enabled Oct 13 11:30:51 kernel: [*10/13/2020 11:30:51.2870] set cleanair [slot1][band1] enabled Oct 13 11:30:52 NCI: I : Entering spawned RxLoop Oct 13 11:30:52 NCI: I0: SensorApp=cbfc6f1f Oct 13 11:30:52 NCI: I0: SensorHdw=1.2.300 Oct 13 11:30:52 NCI: I0: Hardware Radio Band = [4890, 5935] MHz, BW=150625 Oct 13 11:30:52 NCI: I0: Hardware Radio Band = [2400, 2500] MHz, BW=150625 Oct 13 11:30:52 NCI: slot=0 mode=2 chanCnt=1 cw=1 Oct 13 11:30:52 NCI: chans: 1 0 0 0 0 0 0 0 0 0 0 Oct 13 11:30:52 NCI: I0: channel map channels: in=1 cloned=1 Oct 13 11:30:52 NCI: I0: Requesting MonBand [2412, 2412] bw=20MHz/0 ant=0xbc Oct 13 11:30:52 NCI: I0: Monitoring (cf=2412, span=20), RadioUsage=3% Oct 13 11:30:52 NCI: I0: dwell=25000us, update=1000ms, resBW=78126 Oct 13 11:30:52 NCI: CLEANAIR: Slot 0 enabled Oct 13 11:30:55 NCI: I1: openSensor(slot=1) Oct 13 11:30:55 mrvlfwd: radio 1: cfg loopback only mode 0 Oct 13 11:30:57 NCI: I1: SensorApp=cbfc6f1f Oct 13 11:30:57 NCI: I1: SensorHdw=1.2.300 Oct 13 11:30:57 NCI: I1: Hardware Radio Band = [4890, 5935] MHz, BW=150625 Oct 13 11:30:57 NCI: slot=1 mode=2 chanCnt=4 cw=4 Oct 13 11:30:57 NCI: chans: 100 104 108 112 0 0 0 0 0 0 0 Oct 13 11:30:57 NCI: I1: channel map channels: in=4 cloned=4 Oct 13 11:30:57 NCI: I1: Requesting MonBand [5530, 5530] bw=80MHz/0 ant=0xbc Oct 13 11:30:57 NCI: I1: Monitoring (cf=5530, span=79), RadioUsage=3% Oct 13 11:30:57 NCI: I1: dwell=20000us, update=1000ms, resBW=312502 Oct 13 11:30:57 NCI: CLEANAIR: Slot 1 enabled Oct 13 11:31:21 kernel: [*10/13/2020 11:31:21.8181] CAPWAP HW tunnel params changed, DELETING the existing Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8197] Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8197] Going to restart CAPWAP (reason : data keepalive not received)... Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8197] Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8197] Restarting CAPWAP State Machine. Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8202] Flexconnect Switching to Standalone Mode! Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8227] systemd[1]: Starting dhcpv6 client watcher... Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8428] systemd[1]: Stopping DHCPv6 client... Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.8669] systemd[1]: Starting DHCPv6 client... Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.9362] systemd[1]: Started DHCPv6 client. Oct 13 11:32:19 kernel: [*10/13/2020 11:32:19.9889] systemd[1]: Started dhcpv6 client watcher. Oct 13 11:32:20 kernel: [*10/13/2020 11:32:20.0399] Oct 13 11:32:20 kernel: [*10/13/2020 11:32:20.0399] CAPWAP State: DTLS Teardown Oct 13 11:32:20 NCI: CLEANAIR: Slot 0 CAPWAP down Oct 13 11:32:20 NCI: I0: shutdownNci Oct 13 11:32:20 NCI: CLEANAIR: Slot 1 CAPWAP down Oct 13 11:32:20 NCI: I1: shutdownNci Oct 13 11:32:20 upgrade: Script called with args:[ABORT] Oct 13 11:32:20 kernel: [*10/13/2020 11:32:20.1258] upgrade.sh: Script called with args:[ABORT] Oct 13 11:32:20 kernel: [*10/13/2020 11:32:20.1830] do ABORT, part1 is active part Oct 13 11:32:20 upgrade: Cleanup tmp files ... Oct 13 11:32:20 kernel: [*10/13/2020 11:32:20.1983] upgrade.sh: Cleanup tmp files ... Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.7836] systemd[1]: Starting dhcpv6 client watcher... Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.8026] systemd[1]: Stopping DHCPv6 client... Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.8070] systemd[1]: Starting DHCPv6 client... Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.8534] Discovery Response from 172.16.102.11 Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.8537] Discovery Response from 172.16.102.11 Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.8602] systemd[1]: Started DHCPv6 client. Oct 13 11:32:34 kernel: [*10/13/2020 11:32:34.9021] systemd[1]: Started dhcpv6 client watcher. Oct 13 11:32:44 kernel: [*10/13/2020 11:32:44.0003] Oct 13 11:32:44 kernel: [*10/13/2020 11:32:44.0003] CAPWAP State: DTLS Setup Oct 13 11:32:44 kernel: [*10/13/2020 11:32:44.7873] Oct 13 11:32:44 kernel: [*10/13/2020 11:32:44.7873] CAPWAP State: Join Oct 13 11:32:44 kernel: [*10/13/2020 11:32:44.8195] Sending Join request to 172.16.102.11 through port 5256 Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5217] Join Response from 172.16.102.11 Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5217] AC accepted join request with result code: 0 Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5226] Received wlcType 0, timer 30 Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5233] Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5233] CAPWAP State: Image Data Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5237] AP image version 8.10.130.0 backup 8.5.161.0, Controller 8.10.130.0 Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5237] Version is the same, do not need update. Oct 13 11:32:49 upgrade: Script called with args:[NO_UPGRADE] Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.5508] upgrade.sh: Script called with args:[NO_UPGRADE] Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.6110] do NO_UPGRADE, part1 is active part Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.6178] Oct 13 11:32:49 kernel: [*10/13/2020 11:32:49.6178] CAPWAP State: Configure Oct 13 11:32:54 kernel: [*10/13/2020 11:32:54.4260] Oct 13 11:32:54 kernel: [*10/13/2020 11:32:54.4260] CAPWAP State: Run Oct 13 11:32:54 kernel: [*10/13/2020 11:32:54.5500] AP has joined controller wlc-5520-1 Oct 13 11:32:54 kernel: [*10/13/2020 11:32:54.6633] Flexconnect Switching to Connected Mode! Oct 13 11:32:54 kernel: [*10/13/2020 11:32:54.8499] USB Device Disconnected from the AP Oct 13 11:32:55 kernel: [*10/13/2020 11:32:55.7864] Dot11Classifier: Mgmt frame not supported 0 Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.3381] Setting efficientUpgradeState 0 Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.4722] DOT11_CFG[0]: New RADIUS server "Primary Auth Radius Server" already exists Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.4726] DOT11_CFG[1]: New RADIUS server "Primary Auth Radius Server" already exists Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.4846] DOT11_CFG[0]: New RADIUS server "Secondary Auth Radius Server" already exists Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.4850] DOT11_CFG[1]: New RADIUS server "Secondary Auth Radius Server" already exists Oct 13 11:32:57 kernel: [*10/13/2020 11:32:57.6183] Got WSA Server config TLVs Oct 13 11:32:58 kernel: [*10/13/2020 11:32:57.9923] Oct 13 11:32:58 kernel: [*10/13/2020 11:32:57.9923] Same LSC mode, no action needed Oct 13 11:32:58 kernel: [*10/13/2020 11:32:58.7317] systemd[1]: Starting Cisco syslogd watcher... Oct 13 11:32:58 syslogd exiting Oct 13 11:32:58 syslogd started: BusyBox v1.29.3 Oct 13 11:32:58 kernel: [*10/13/2020 11:32:58.8405] systemd[1]: Started Cisco syslogd watcher. Oct 13 11:33:22 kernel: [*10/13/2020 11:33:22.9048] set cleanair [slot0][band0] enabled Oct 13 11:33:22 kernel: [*10/13/2020 11:33:22.9107] set cleanair [slot0][band1] enabled Oct 13 11:33:22 kernel: [*10/13/2020 11:33:22.9278] set cleanair [slot1][band1] enabled Oct 13 11:33:23 NCI: I0: SensorApp=cbfc6f1f Oct 13 11:33:23 NCI: I0: SensorHdw=1.2.300 Oct 13 11:33:23 NCI: I0: Hardware Radio Band = [4890, 5935] MHz, BW=150625 Oct 13 11:33:23 NCI: I0: Hardware Radio Band = [2400, 2500] MHz, BW=150625 Oct 13 11:33:23 NCI: slot=0 mode=2 chanCnt=1 cw=1 Oct 13 11:33:23 NCI: chans: 1 0 0 0 0 0 0 0 0 0 0 Oct 13 11:33:23 NCI: I0: channel map channels: in=1 cloned=1 Oct 13 11:33:23 NCI: I0: Requesting MonBand [2412, 2412] bw=20MHz/0 ant=0xbc Oct 13 11:33:24 NCI: I0: Monitoring (cf=2412, span=20), RadioUsage=3% Oct 13 11:33:24 NCI: I0: dwell=25000us, update=1000ms, resBW=78126 Oct 13 11:33:24 NCI: CLEANAIR: Slot 0 enabled Oct 13 11:33:27 NCI: I1: openSensor(slot=1) Oct 13 11:33:27 mrvlfwd: radio 1: cfg loopback only mode 0 Oct 13 11:33:29 NCI: I1: SensorApp=cbfc6f1f Oct 13 11:33:29 NCI: I1: SensorHdw=1.2.300 Oct 13 11:33:29 NCI: I1: Hardware Radio Band = [4890, 5935] MHz, BW=150625 Oct 13 11:33:29 NCI: slot=1 mode=2 chanCnt=4 cw=4 Oct 13 11:33:29 NCI: chans: 100 104 108 112 0 0 0 0 0 0 0 Oct 13 11:33:29 NCI: I1: channel map channels: in=4 cloned=4 Oct 13 11:33:29 NCI: I1: Requesting MonBand [5530, 5530] bw=80MHz/0 ant=0xbc Oct 13 11:33:29 NCI: I1: Monitoring (cf=5530, span=79), RadioUsage=3% Oct 13 11:33:29 NCI: I1: dwell=20000us, update=1000ms, resBW=312502 Oct 13 11:33:29 NCI: CLEANAIR: Slot 1 enabled Oct 13 11:33:51 kernel: [*10/13/2020 11:33:51.6384] CAPWAP HW tunnel params changed, DELETING the existing
10-13-2020 04:38 AM
One more log from the WLC:
(Cisco Controller) >show ap join stats detailed f4:db:e6:de:de:a6 Sync phase statistics - Time at sync request received............................ Not applicable - Time at sync completed................................... Not applicable Discovery phase statistics - Discovery requests received.............................. 41 - Successful discovery responses sent...................... 41 - Unsuccessful discovery request processing................ 0 - Reason for last unsuccessful discovery attempt........... Not applicable - Time at last successful discovery attempt................ Oct 13 13:35:08.258 - Time at last unsuccessful discovery attempt.............. Not applicable Join phase statistics - Join requests received................................... 20 - Successful join responses sent........................... 20 - Unsuccessful join request processing..................... 0 - Reason for last unsuccessful join attempt................ Not applicable - Time at last successful join attempt..................... Oct 13 13:35:23.289 - Time at last unsuccessful join attempt................... Not applicable Configuration phase statistics --More-- or (q)uit - Configuration requests received.......................... 144 - Successful configuration responses sent.................. 62 - Unsuccessful configuration request processing............ 0 - Reason for last unsuccessful configuration attempt....... Not applicable - Time at last successful configuration attempt............ Oct 13 13:35:26.951 - Time at last unsuccessful configuration attempt.......... Not applicable Last AP message decryption failure details - Reason for last message decryption failure............... Not applicable Last AP disconnect details - Reason for last AP connection failure.................... Timed out while waiting for ECHO repsonse from the AP - Last AP disconnect reason................................ Unknown failure reason Last join error summary - Type of error that occurred last......................... AP got or has been disconnected - Reason for error that occurred last...................... Timed out while waiting for ECHO repsonse from the AP - Time at which the last join error occurred............... Oct 13 13:17:08.101 AP disconnect details - Reason for last AP connection failure.................... Timed out while waiting for ECHO repsonse from the AP Ethernet Mac : f4:db:e6:de:de:a6 Ip Address : 172.16.3.20 --More-- or (q)uit (Cisco Controller) >ping 172.16.3.20 Send count=3, Receive count=3 from 172.16.3.20 (Cisco Controller) >
10-13-2020 04:48 AM
And me again. It looks like I might be hitting:
https://bst.cloudapps.cisco.com/bugsearch/bug/CSCvu58082
I will now try with DTLS disabled (it's luckily over a VPN).
10-13-2020 05:07 AM - edited 10-13-2020 05:08 AM
And i can confirm, Data Encryption caused this issue. Once it was disabled for the AP, the clients are able again to connect. Should be fixed in 8.10.140.0 (it's fixed in the beta 8.10MR4).
10-13-2020 04:36 AM
I've encountered similar problems with Windows 10 clients not finishing EAP negotiation process and deauthenticating.
Microsoft is analysing the DisAssociation problem and.
If you clients are Windows10, try to gather some information from this command (CLI with elevated rights): "netsh wlan show wlanreport".
HTH
-Jesus
*** Please Rate Helpful Responses ***
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide