8.10.130.0 radius authentication not working

[patoberli]

Hi all

I was in the beta test for 8.10.130.0 and had there an issue with radius authentication not anymore working on the 3504 WLC with 2802i AP. I did submit this bug, but it seems it wasn't important enough.

I have since (today) upgraded to 8.10.130.0 and I still can't authenticate successfully.

To be more exact, the radius sends an authentication OK, including some attributes (like the VLAN) back to the WLC, it also receives it correctly, but then disconnects the clients again. I tested with iPhone, Android and a Windows 10 PC and with none is it working.

I can connect to the WLC, if I connect first to another WLC running 8.5.161.0 and then roam to the WLC with 8.10.130.0. 

Attached an example client debug:

(Cisco Controller) >debug aaa events enable 

(Cisco Controller) >*emWeb: Jul 29 13:02:57.475: 
Debugging session started on Jul 29 13:02:57.475  for WLC AIR-CT3504-K9   Version :8.10.128.154  SN :xxxxxxxxxxx  Hostname wlc-3504-1
debug aaa events enable 

(Cisco Controller) >debug client 34:7d:f6:12:3D:5b                                                                

(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >*apfReceiveTask: Jul 29 13:03:10.731: apfVapRadiusNasIpAddrGet: Client 7C:A1:AE:B3:21:F2  NAS IP Attribute: 172.16.240.242 
*apfOpenDtlSocket: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b Received management frame ASSOCIATION REQUEST  on BSSID 28:6f:7f:e8:d2:ed destination addr 28:6f:7f:e8:d2:ed slotid 1
*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b Updating the client capabiility as 5
*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b Processing assoc-req station:34:7d:f6:12:3d:5b AP:28:6f:7f:e8:d2:e0-01 ssid : eduroam thread:25aab210
*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b apfCreateMobileStationEntryWrapper (apf_ms.c:4510) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Idle to Idle

*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b Adding mobile on LWAPP AP 28:6f:7f:e8:d2:e0(1) 
*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b Created Acct-Session-ID (5f215774/34:7d:f6:12:3d:5b/121) for the mobile
*apfMsConnTask_2: Jul 29 13:03:16.821: 34:7d:f6:12:3d:5b  Setting hasApChnaged Flag as true. It is a fresh assoc request.

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Setting RTTS enabled to 0 
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Association received from mobile on BSSID 28:6f:7f:e8:d2:ed AP 2802AC-1011-2
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Station:  34:7D:F6:12:3D:5B  trying to join WLAN with RSSI -36. Checking for XOR roam conditions on AP:  28:6F:7F:E8:D2:E0  Slot: 1
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Station:  34:7D:F6:12:3D:5B  is associating to AP  28:6F:7F:E8:D2:E0  which is not XOR roam capable
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Global 200 Clients are allowed to AP radio

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Max Client Trap Threshold: 0  cur: 5

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Updated local bridging VLAN to 240 while applying WLAN policy
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Updated session timeout to 0 and Sleep timeout to 720 while applying WLAN policy
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Re-applying interface (int-vlan-240) policy for client
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b After applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3486)
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b 0.0.0.0 START (0) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255),Default action is '0' --- (caller apf_policy.c:3506)
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3527)
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b apf_policy.c:2771 Assigning the SGT 0 to mobile (earlier sgt 0)
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Increment the SGT 0 policy count reference by the clients 13
*apfMsConnTask_2: Jul 29 13:03:16.822: 34:7d:f6:12:3d:5b Check the client SGT 0 policy and push it to AP 28:6f:7f:e8:d2:e0
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b In processSsidIE:7589 setting Central switched to TRUE
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b In processSsidIE:7592 apVapId = 3 and Split Acl Id = 65535
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Applying site-specific Local Bridging override for station 34:7d:f6:12:3d:5b - vapId 3, site 'default-group', interface 'int-vlan-240'
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Applying Local Bridging Interface Policy for station 34:7d:f6:12:3d:5b - vlan 240, interface id 22, interface 'int-vlan-240', nasId:''
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b processSsidIE  statusCode is 0 and status is 0 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b STA - rates (6): 12 164 176 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b suppRates  statusCode is 0 and gotSuppRatesElement is 1 
*apfMsConnTask_2: Jul 29 13:03:16.823: RSNIE in Assoc. Req.: (26)

*apfMsConnTask_2: Jul 29 13:03:16.823:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Jul 29 13:03:16.823:      [0016] ac 01 bc 00 00 00 00 0f ac 06

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Processing RSN IE type 48, length 26 for mobile 34:7d:f6:12:3d:5b
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b RSN Capabilities:  188
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Marking Mobile as 11w Capable 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b creating SA query timer
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Received RSN IE(AKM:1) with 0 PMKIDs
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Received RSN IE with 0 PMKIDs from mobile 34:7d:f6:12:3d:5b
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Setting active key cache index 8 ---> 8
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b apfValidateDot11wGroupMgmtCipher:2514, 11w Group Mgmt Cipher Suite 6 validation succeeded for STA

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Assigning flex webauth IPv4-ACL ID :65535, IPv6-ACL ID:65535 for AP WLAN ID : 3
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Allocate AID 9 slot 1 on AP 2802AC-1011-2 #clients on this slot 6
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Assoc Req BSSID 28:6f:7f:e8:d2:ed AP(2802AC-1011-2) slot 1 ssid (eduroam) Tmstmp 6524 AID 9 stCode 0/0 apChngd 0 oldAp 00:00:00:00:00:00 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b  AuthenticationRequired = 1 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Setting the action to initiate 1x 4 way handshake upon Add_Mobile_Ack for station with encrypt policy:[80000001] 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Not Using WMM Compliance code qosCap 00
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b flex webauth ipv4 & ipv6 acl ids to be sent when fabric is disabled:65535/65535
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b flex webauth acl id to be sent :65535 name : client acl id :65535 name :
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b flex webauth ipv6 acl id to be sent :65535 name : client acl id :65535 name :
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Vlan while overriding the policy = -1
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 28:6f:7f:e8:d2:e0 vapId 3 apVapId 3 flex acl-name: v6acl-name
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b apfMsAssoStateInc
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b apfPemAddUser2 (apf_policy.c:465) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Idle to Associated

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b apfPemAddUser2:session timeout forstation 34:7d:f6:12:3d:5b - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0 
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Sending assoc-resp with status 0 station:34:7d:f6:12:3d:5b AP:28:6f:7f:e8:d2:e0-01 on apVapId 3
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b VHT Operation IE: width 80/1 ch 128 freq0 122 freq1 0 msc0 0xff msc1 0xff
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b Sending Assoc Response (status: '0') to station on AP 2802AC-1011-2 on BSSID 28:6f:7f:e8:d2:ed ApVapId 3 Slot 1, mobility role 0
*apfMsConnTask_2: Jul 29 13:03:16.823: 34:7d:f6:12:3d:5b apfProcessAssocReq (apf_80211.c:12920) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Associated to Associated

*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Add SGT:0 to AP 28:6f:7f:e8:d2:e0
*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Flex Ipv6 pre-auth acl is not present, not Encoding Flex Ipv6 acl for add mobile Payload
*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Flex Ipv6 post auth acl is not present, not updating add mobile Payload
*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Successful transmission of LWAPP Add-Mobile to AP 28:6f:7f:e8:d2:e0 slotId 1 idx@191
*spamApTask4: Jul 29 13:03:16.824: 34:7d:f6:12:3d:5b Setting ADD_MOBILE (idx 191, seqno 80, action 1, count 80, last count 80) ack state for STA on AP 28:6f:7f:e8:d2:e0
*spamApTask4: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Received add/del ack packet with sequence number: got 80 expected 80 action = 1
*spamApTask4: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Received ADD_MOBILE ack - Initiating 1x to STA 34:7d:f6:12:3d:5b (idx 191)
*spamApTask4: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b APF Initiating 1x to STA 34:7d:f6:12:3d:5b
*spamApTask4: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Sent dot1x auth initiate message for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b dot1xProcessInitiate1XtoMobile to mobile station 34:7d:f6:12:3d:5b (mscb 1, msg 1)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b reauth_sm state transition 0 ---> 1 for mobile 34:7d:f6:12:3d:5b at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b EAP-PARAM Debug - eap-params for Wlan-Id :3 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Station 34:7d:f6:12:3d:5b setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Stopping reauth timeout for 34:7d:f6:12:3d:5b 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Connecting state
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.826: 34:7d:f6:12:3d:5b Sending EAP-Request/Identity to mobile 34:7d:f6:12:3d:5b (EAP Id 1)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b Received EAPOL START from mobile in dot1x state = 2
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b reauth_sm state transition 1 ---> 1 for mobile 34:7d:f6:12:3d:5b at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b Received EAPOL START from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Connecting state
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.827: 34:7d:f6:12:3d:5b Sending EAP-Request/Identity to mobile 34:7d:f6:12:3d:5b (EAP Id 2)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Received Identity Response (count=1) from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Resetting reauth count 1 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b EAP State update from Connecting to Authenticating for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Authenticating state
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Created Cisco-Audit-Session-ID for the mobile: ac10660c000000205f215774 type: local
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.840: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:38 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:16.840: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 38) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-03:00
*radiusTransportThread: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Access-Reject received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:38
*radiusTransportThread: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Error Response code for AAA Authentication : -4
*radiusTransportThread: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b [Error] Client requested no retries for mobile 34:7D:F6:12:3D:5B 
*radiusTransportThread: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Returning AAA Error 'Authentication Failed' (-4) for mobile 34:7d:f6:12:3d:5b serverIdx 2
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Processing Access-Reject for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b 1 PMK-remove groupcast messages sent 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Deleted global PMK cache and MSCB PMKID/PMK cache entry for the client
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Removing PMK cache due to EAP-Failure for mobile 34:7d:f6:12:3d:5b (EAP Id -1)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Sending EAP-Failure to mobile 34:7d:f6:12:3d:5b (EAP Id -1)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b Entering Backend Auth Failure state (id=-1) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:16.849: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Unknown state
*apfOpenDtlSocket: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Received management frame ASSOCIATION REQUEST  on BSSID 28:6f:7f:e8:d2:ed destination addr 28:6f:7f:e8:d2:ed slotid 1
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Updating the client capabiility as 5
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Processing assoc-req station:34:7d:f6:12:3d:5b AP:28:6f:7f:e8:d2:e0-01 ssid : eduroam thread:25aab210
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Station:  34:7D:F6:12:3D:5B  trying to join WLAN with RSSI -35. Checking for XOR roam conditions on AP:  28:6F:7F:E8:D2:E0  Slot: 1
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Station:  34:7D:F6:12:3D:5B  is associating to AP  28:6F:7F:E8:D2:E0  which is not XOR roam capable
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Updating location for mobile on same AP 28:6f:7f:e8:d2:e0-1
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Setting RTTS enabled to 0 
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Association received from mobile on BSSID 28:6f:7f:e8:d2:ed AP 2802AC-1011-2
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Station:  34:7D:F6:12:3D:5B  is associating to AP  28:6F:7F:E8:D2:E0  which is not XOR roam capable
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Global 200 Clients are allowed to AP radio

*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Max Client Trap Threshold: 0  cur: 6

*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Updated local bridging VLAN to 240 while applying WLAN policy
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Updated session timeout to 0 and Sleep timeout to 720 while applying WLAN policy
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Re-applying interface (int-vlan-240) policy for client
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b After applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3486)
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b 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_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3527)
*apfMsConnTask_2: Jul 29 13:03:17.458: 34:7d:f6:12:3d:5b Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Check the client SGT 0 policy and push it to AP 28:6f:7f:e8:d2:e0
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b In processSsidIE:7589 setting Central switched to TRUE
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b In processSsidIE:7592 apVapId = 3 and Split Acl Id = 65535
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Applying site-specific Local Bridging override for station 34:7d:f6:12:3d:5b - vapId 3, site 'default-group', interface 'int-vlan-240'
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Applying Local Bridging Interface Policy for station 34:7d:f6:12:3d:5b - vlan 240, interface id 22, interface 'int-vlan-240', nasId:''
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b processSsidIE  statusCode is 0 and status is 0 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b STA - rates (6): 12 164 176 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b suppRates  statusCode is 0 and gotSuppRatesElement is 1 
*apfMsConnTask_2: Jul 29 13:03:17.459: RSNIE in Assoc. Req.: (26)

*apfMsConnTask_2: Jul 29 13:03:17.459:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Jul 29 13:03:17.459:      [0016] ac 01 bc 00 00 00 00 0f ac 06

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Processing RSN IE type 48, length 26 for mobile 34:7d:f6:12:3d:5b
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b RSN Capabilities:  188
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Marking Mobile as 11w Capable 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Received RSN IE(AKM:1) with 0 PMKIDs
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Received RSN IE with 0 PMKIDs from mobile 34:7d:f6:12:3d:5b
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Setting active key cache index 0 ---> 8
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b apfValidateDot11wGroupMgmtCipher:2514, 11w Group Mgmt Cipher Suite 6 validation succeeded for STA

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Assigning flex webauth IPv4-ACL ID :65535, IPv6-ACL ID:65535 for AP WLAN ID : 3
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Assoc Req BSSID 28:6f:7f:e8:d2:ed AP(2802AC-1011-2) slot 1 ssid (eduroam) Tmstmp 6525 AID 9 stCode 0/0 apChngd 0 oldAp 28:6F:7F:E8:D2:E0 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Authreqd flag unchanged 1 for mobile with macAuthType [0] pemSt 3 secWord 4000
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Not changing skipL2auth flag with authReqd [1] macauth [0] pemSt 3 secWord 4000
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Initializing policy
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b  apfVapSecurity=0x4000 L2=16384 SkipWeb=0 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Encryption policy is set to 0x80000001
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Setting the action to initiate 1x 4 way handshake upon Add_Mobile_Ack for station with encrypt policy:[80000001] 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b flex webauth ipv4 & ipv6 acl ids to be sent when fabric is disabled:65535/65535
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b flex webauth acl id to be sent :65535 name : client acl id :65535 name :
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Vlan while overriding the policy = -1
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 28:6f:7f:e8:d2:e0 vapId 3 apVapId 3 flex acl-name: v6acl-name
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b apfPemAddUser2 (apf_policy.c:465) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Associated to Associated

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b apfPemAddUser2:session timeout forstation 34:7d:f6:12:3d:5b - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0 
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Jul 29 13:03:17.459: 34:7d:f6:12:3d:5b VHT Operation IE: width 80/1 ch 128 freq0 122 freq1 0 msc0 0xff msc1 0xff
*apfMsConnTask_2: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Sending Assoc Response (status: '0') to station on AP 2802AC-1011-2 on BSSID 28:6f:7f:e8:d2:ed ApVapId 3 Slot 1, mobility role 0
*apfMsConnTask_2: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b apfProcessAssocReq (apf_80211.c:12920) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Associated to Associated

*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Add SGT:0 to AP 28:6f:7f:e8:d2:e0
*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Flex Ipv6 pre-auth acl is not present, not Encoding Flex Ipv6 acl for add mobile Payload
*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Flex Ipv6 post auth acl is not present, not updating add mobile Payload
*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Successful transmission of LWAPP Add-Mobile to AP 28:6f:7f:e8:d2:e0 slotId 1 idx@192
*spamApTask4: Jul 29 13:03:17.460: 34:7d:f6:12:3d:5b Setting ADD_MOBILE (idx 192, seqno 81, action 1, count 81, last count 81) ack state for STA on AP 28:6f:7f:e8:d2:e0
*spamApTask4: Jul 29 13:03:17.462: 34:7d:f6:12:3d:5b Received add/del ack packet with sequence number: got 81 expected 81 action = 1
*spamApTask4: Jul 29 13:03:17.462: 34:7d:f6:12:3d:5b Received ADD_MOBILE ack - Initiating 1x to STA 34:7d:f6:12:3d:5b (idx 192)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.462: 34:7d:f6:12:3d:5b Received EAPOL START from mobile in dot1x state = 6
*spamApTask4: Jul 29 13:03:17.462: 34:7d:f6:12:3d:5b APF Initiating 1x to STA 34:7d:f6:12:3d:5b
*spamApTask4: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b Sent dot1x auth initiate message for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b dot1xProcessInitiate1XtoMobile to mobile station 34:7d:f6:12:3d:5b (mscb 2, msg 2)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b reauth_sm state transition 1 ---> 0 for mobile 34:7d:f6:12:3d:5b at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b EAP-PARAM Debug - eap-params for Wlan-Id :3 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Connecting state
*Dot1x_NW_MsgTask_3: Jul 29 13:03:17.463: 34:7d:f6:12:3d:5b Sending EAP-Request/Identity to mobile 34:7d:f6:12:3d:5b (EAP Id 1)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Received Identity Response (count=1) from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Resetting reauth count 1 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b EAP State update from Connecting to Authenticating for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Authenticating state
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.832: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:39 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:24.832: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 39) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:00
*radiusTransportThread: Jul 29 13:03:24.847: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:39
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.847: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.847: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=2) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.847: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 2)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.847: 34:7d:f6:12:3d:5b Allocating EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 2, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.849: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:40 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:24.849: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 40) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:01
*radiusTransportThread: Jul 29 13:03:24.852: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:40
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.852: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.852: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=3) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.852: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 3)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:24.852: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.389: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.389: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.390: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:41 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.390: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.390: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.390: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 41) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:02
*radiusTransportThread: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:41
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=6) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b WARNING: updated EAP-Identifier 3 ===> 6 for STA 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 6)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.394: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 6, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.396: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:42 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.396: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 42) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:03
*radiusTransportThread: Jul 29 13:03:25.399: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:42
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.399: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.399: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=7) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.399: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 7)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.399: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.400: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.400: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 7, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.400: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.400: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.400: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:43 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.401: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 43) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:04
*radiusTransportThread: Jul 29 13:03:25.402: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:43
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.403: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.403: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=8) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.403: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 8)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.403: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.404: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:44 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.404: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 44) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:05
*radiusTransportThread: Jul 29 13:03:25.429: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:44
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.429: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.429: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=9) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.429: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 9)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.429: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 9, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.432: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:45 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.432: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 45) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:06
*radiusTransportThread: Jul 29 13:03:25.443: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:45
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.443: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.443: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=10) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.443: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 10)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.443: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.444: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.444: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 10, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.444: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.444: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.445: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:46 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.445: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 46) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:07
*radiusTransportThread: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b Access-Challenge received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:46
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b Processing Access-Challenge for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b Entering Backend Auth Req state (id=12) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b WARNING: updated EAP-Identifier 10 ===> 12 for STA 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b Sending EAP Request from AAA to mobile 34:7d:f6:12:3d:5b (EAP Id 12)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.447: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Received EAPOL EAPPKT from mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Received EAP Response from mobile 34:7d:f6:12:3d:5b (EAP Id 12, EAP Type PEAP)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Resetting reauth count 0 to 0 for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Entering Backend Auth Response state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.449: apfVapRadiusNasIpAddrGet: Client 34:7D:F6:12:3D:5B  NAS IP Attribute: 172.16.240.242 
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is ready 172.16.240.7 port 1812 index 2 active 1
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b radiusServerFallbackPassiveStateUpdate: RADIUS server is maybe-ready 172.16.240.8 port 1812 index 3 active 1
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Found a server : 172.16.240.7 from the WLAN server list of radius server index 3
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Send Radius Auth Request with pktId:47 into qid:11 of server at index:2
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl actual port MTU :1430
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b AAARadiusSendPktToDtl:Sending PDU to DTL SRC MAC: 00:BC:60:FC:1D:85
*aaaQueueReader: Jul 29 13:03:25.449: 34:7d:f6:12:3d:5b Successful transmission of Authentication Packet (pktId 47) to 172.16.240.7:1812 from server queue 11, proxy state 34:7d:f6:12:3d:5b-04:08
*radiusTransportThread: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Radius AVP MPPE send key decrypted key: keylen: 32

*radiusTransportThread: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Radius AVP MPPE recv key: keylen: 32

*radiusTransportThread: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Access-Accept received from RADIUS server 172.16.240.7 (qid:11) with port:1812, pktId:47
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Processing Access-Accept for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Previous Radius Overrides:(0)

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Received MPPE_SEND_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Received MPPE_RECV_KEY: KeyLen: 32 

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Found an interface name:'int-vlan-204' corresponds to interface name received: int-vlan-204
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Applying new AAA override for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values for station 34:7d:f6:12:3d:5b
                                                                                                                source: 4, valid bits: 0x200
        qosLevel: -1, dscp: 0xffffffff, dot1pTag: 0xffffffff, sessionTimeout: -1         Interim Interval: 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..) dataAvgC: -1, rTAvgC: -1, dataBurstC: -1, rTimeBurstC: -1
                        vlanIfName: 'int-vlan-204', vlanId:0, aclName: ', ipv6AclName: , avcProfileName: '

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..2) dataAvgCUs: -1, rTAvgCUs: -1, dataBurstCUs: -1, rTimeBurstCUs: -1
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b  Applying Fabric vnid override for client 34:7d:f6:12:3d:5b, client->reap 1 ,over bits 200,isover TRUE
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b  Clearing the DHCP state for the mobile as there is change in override VLAN/Interface params.

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Updated local bridging VLAN to 240 while applying WLAN policy
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Updated session timeout to 0 and Sleep timeout to 720 while applying WLAN policy
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Re-applying interface (int-vlan-240) policy for client
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b After applying Interface(int-vlan-240) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3486)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b 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)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3527)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Values before applying NASID - interfacetype:3, ovrd:0, mscb nasid:, interface nasid:, APgrpset:0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Check before Setting the NAS Id to WLAN specific Id ''
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Check the client SGT 0 policy and push it to AP 28:6f:7f:e8:d2:e0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Inserting AAA Override struct for mobile
        MAC: 34:7d:f6:12:3d:5b, source: L2 Auth

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Inserting new RADIUS override into chain for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values for station 34:7d:f6:12:3d:5b
                                                                                                                source: 4, valid bits: 0x200
        qosLevel: -1, dscp: 0xffffffff, dot1pTag: 0xffffffff, sessionTimeout: -1         Interim Interval: 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..) dataAvgC: -1, rTAvgC: -1, dataBurstC: -1, rTimeBurstC: -1
                        vlanIfName: 'int-vlan-204', vlanId:0, aclName: ', ipv6AclName: , avcProfileName: '

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..2) dataAvgCUs: -1, rTAvgCUs: -1, dataBurstCUs: -1, rTimeBurstCUs: -1
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Applying override policy from source Override Summation: with value 200 
    
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values for station 34:7d:f6:12:3d:5b
                                                                                                                source: 256, valid bits: 0x200
        qosLevel: -1, dscp: 0xffffffff, dot1pTag: 0xffffffff, sessionTimeout: -1         Interim Interval
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..) dataAvgC: -1, rTAvgC: -1, dataBurstC: -1, rTimeBurstC: -1
                        vlanIfName: 'int-vlan-204', vlanId:0, aclName: ', ipv6AclName: , avcProfileName: '

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Override values (cont..2) dataAvgCUs: -1, rTAvgCUs: -1, dataBurstCUs: -1, rTimeBurstCUs: -1
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Found an interface name:'int-vlan-204' corresponds to interface name received: int-vlan-204
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Applying Interface(int-vlan-204) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 240

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b Re-applying interface (int-vlan-204) policy for client
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.452: 34:7d:f6:12:3d:5b After applying Interface(int-vlan-204) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 204

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3486)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b 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)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:3527)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Not computing ipsk-tag for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Station 34:7d:f6:12:3d:5b setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Stopping reauth timeout for 34:7d:f6:12:3d:5b 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Username entry (patrick.oberli@ost.ch) created for mobile, length = 253 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Username entry (patrick.oberli@ost.ch) created in mscb for mobile, length = 253 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Creating a PKC PMKID Cache entry for station 34:7d:f6:12:3d:5b (RSN 2)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Resetting MSCB PMK Cache Entry @index 0 for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Created PMKID PMK Cache for BSSID 28:6f:7f:e8:d2:ed  at index 0 for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: New PMKID: (16)

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453:      [0000] 48 bc bd 28 28 cd 12 f7 ef 06 da 42 7f 51 3f 99

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b 802.11i: Create a global PMK cache entry, AKM-type = 1
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b apfCreatePmkCacheEntry: added a new pmk cache entry for 34:7d:f6:12:3d:5b

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b 1x: Updated the audit-session-id of PMK-Cache from client mscb: ac10660c000000205f215774
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Updating AAA Overrides from local for station
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Building Audit session ID (ac10660c000000205f215774) payload in Mobility handoff
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 3	 4:7d:f6:12:3d:5b 1 PMK-update groupcast messages sent 
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b PMK sent to mobility group
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Sending EAP-Success to mobile 34:7d:f6:12:3d:5b (EAP Id 12)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Freeing AAACB from Dot1xCB as AAA auth is done for  mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b key Desc Version FT - 0

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Found an cache entry for BSSID 28:6f:7f:e8:d2:ed in PMKID cache at index 0 of station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Found an cache entry for BSSID 28:6f:7f:e8:d2:ed in PMKID cache at index 0 of station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453:      [0000] 48 bc bd 28 28 cd 12 f7 ef 06 da 42 7f 51 3f 99

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: M1 - Key Data: (22)

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453:      [0000] dd 14 00 0f ac 04 48 bc bd 28 28 cd 12 f7 ef 06

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453:      [0016] da 42 7f 51 3f 99

*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Starting key exchange to mobile 34:7d:f6:12:3d:5b, data packets will be dropped
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Sending EAPOL-Key Message to mobile 34:7d:f6:12:3d:5b
                                                                                                                    state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Reusing allocated memory for  EAP Pkt for retransmission to mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Entering Backend Auth Success state (id=12) for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b Received Auth Success while in Authenticating state for mobile 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:25.453: 34:7d:f6:12:3d:5b dot1x - moving mobile 34:7d:f6:12:3d:5b into Authenticated state
*osapiBsnTimer: Jul 29 13:03:27.496: 34:7d:f6:12:3d:5b 802.1x 'timeoutEvt' Timer expired for station 34:7d:f6:12:3d:5b and for message = M2
*Dot1x_NW_MsgTask_3: Jul 29 13:03:27.496: 34:7d:f6:12:3d:5b Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 34:7d:f6:12:3d:5b
*osapiBsnTimer: Jul 29 13:03:29.479: 34:7d:f6:12:3d:5b 802.1x 'timeoutEvt' Timer expired for station 34:7d:f6:12:3d:5b and for message = M2
*Dot1x_NW_MsgTask_3: Jul 29 13:03:29.479: 34:7d:f6:12:3d:5b Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 34:7d:f6:12:3d:5b
*osapiBsnTimer: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b 802.1x 'timeoutEvt' Timer expired for station 34:7d:f6:12:3d:5b and for message = M2
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Retransmit failure for EAPOL-Key M1 to mobile 34:7d:f6:12:3d:5b, retransmit count 3, mscb deauth count 0
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Resetting MSCB PMK Cache Entry @index 0 for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Removing BSSID 28:6f:7f:e8:d2:ed from PMKID cache of station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b 4way handshake timeout, send deauth and cleanup the mscb
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Deleting the PMK cache when de-authenticating the client.
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Removing PMK cache entry for station 34:7d:f6:12:3d:5b
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Succesfully freed AID 9, slot 1 on AP 28:6f:7f:e8:d2:e0, #client on this slot 5
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Stopping SA Query retry timer  and resetting 11w and clientSecure status of Mobile Station
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Sent Deauthenticate to mobile on BSSID 28:6f:7f:e8:d2:ed slot 1 reason code 15 (caller 1x_ptsm.c:693)
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Scheduling deletion of Mobile Station: reasonCode 1 (callerId: 57) in 10 seconds
*Dot1x_NW_MsgTask_3: Jul 29 13:03:31.463: 34:7d:f6:12:3d:5b Freeing EAP Retransmit Bufer for mobile 34:7d:f6:12:3d:5b
d*osapiBsnTimer: Jul 29 13:03:41.381: 34:7d:f6:12:3d:5b apfMsExpireCallback (apf_ms.c:688) Expiring Mobile!
*apfReceiveTask: Jul 29 13:03:41.381: 34:7d:f6:12:3d:5b apfMsExpireMobileStation (apf_ms.c:8147) Changing state for mobile 34:7d:f6:12:3d:5b on AP 28:6f:7f:e8:d2:e0 from Associated to Disassociated

*apfReceiveTask: Jul 29 13:03:41.381: 34:7d:f6:12:3d:5b Scheduling deletion of Mobile Station: reasonCode 2 (callerId: 45) in 10 seconds
ebug disable-all 

(Cisco Controller) >

The exactly same configuration worked with 8.8.130.0. 

SSID is WPA2-Enterprise with CCMP128(AES) and Fast Transition on Adaptive. PMF is Optional. 

Anybody else having this issue?

[patoberli · Accepted solution]

Good news, I found the source of the problems.
I had on this SSID (I think for testing) 802.1X-SHA2 somewhen enabled in the past, additionally to the other two CCKM and 802.1X-SHA1. Once I disabled that option the clients were able to connect again.
No idea if it's a combination issue of the various options (WPA3 is not enabled, PMF optional, for example) or a bug on the WLC or something else.

[JPavonM]

I had same issue when configuring dot1X+SHA1+SHA256 with optional PMF but in my case, iPhones and Android 10 (Mi8) are working fine. Windows laptop with Intel AC8265 is also associating fine but Intel AX200 and Intel AC3165 chipset-based laptops are unable to connect. Additionally they are not connecting using only dot1X+SHA256, but iPhones and Androids do. Client stations are never responding to Key M2 in the 4-way handshake.

I've been testing with IOS-XE 17.3.1.9 but also with previous 16.12.2s and they are both "affected".

I have open a differnt thread on Cisco Comunity and Intel Community and after talking to an engineer they say this is Cisco issue.

I have also open a TAC case with Cisco because of this and they say this is client issue, what I subscribe.

HTH
-Jesus
*** Please Rate Helpful Responses ***

[tsadduq]

Can you please explain in details what the change you have made that fixed the issue?

[patoberli]

Disable on the SSID Layer2 configuration the option 802.1X-SHA2.

[tsadduq]

Thanks.

[patoberli]

Small update.

Today I upgraded my 5520 WLC from 8.5.161.0 to 8.10.130.0. It had 802.1X-SHA2 after the upgrade enabled by default. This option does not exist on 8.5 releases (as it's part of WPA3, if I'm not mistaken). This caused again the outage, that my clients were unable to connect. This time I luckily could quickly disable it within my maintenance window. I'm using WPA2-Enterprise with CCMP128(AES) and 802.1X-SHA1 plus CCKM enabled.

So please watch out when upgrading from 8.8 or 8.5 to 8.10.130.0, as this option seems to get enabled by default. 

[merlin76]

I've had the same issue when upgrading from 8.8 to 8.10 with PMF set to optional. To avoid the issue, disable PMF before upgrading.