cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
4361
Views
20
Helpful
11
Replies

Debug Flexconnect

patoberli
VIP Alumni
VIP Alumni

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

1 Accepted Solution

Accepted Solutions

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). 

View solution in original post

11 Replies 11

patoberli
VIP Alumni
VIP Alumni

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 

 

                      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

 



-- Each morning when I wake up and look into the mirror I always say ' Why am I so brilliant ? '
    When the mirror will then always repond to me with ' The only thing that exceeds your brilliance is your beauty! '

Thanks, I've already looked at that and I do see a missing reply by the client there.

What I wonder, has something fundamentally changed in Flexconnect that might need to be adjusted in 8.10.x?




 

 - Does this apply to a specific vendor-client model , or do several different client-types have the same problem ?

 M.



-- Each morning when I wake up and look into the mirror I always say ' Why am I so brilliant ? '
    When the mirror will then always repond to me with ' The only thing that exceeds your brilliance is your beauty! '

All at that location have this problem.

But now the uplink is completely gone, so I'm looking first at that.



Just before that, I saw various "Going to restart CAPWAP (reason : data keepalive not received)" so maybe the reason is something completely different.



I will update once I know more.


 

  - Good thinking ,meaning all underlying link-issues should get resolved first, to avoid having a clouded (!) view on the issue.

 M.



-- Each morning when I wake up and look into the mirror I always say ' Why am I so brilliant ? '
    When the mirror will then always repond to me with ' The only thing that exceeds your brilliance is your beauty! '

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

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) >

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). 

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). 

JPavonM
VIP
VIP

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 ***

Review Cisco Networking for a $25 gift card