Solved: Re: Random disconnections noticed by multiple users in the same campus

deepak george · ‎08-31-2018

Hello experts,

Need your advice here.

We noticed multiple users in different areas of the building observing random disconnects from the network. We reached out to Cisco TAC and they suggested the following.

1>Disable optimized roaming

2>Disable Fast transition

3>Change the data rates on 5ghz channels

4>Do a site survey again

We followed all the instructions and also called a Cisco partner to do a site survey. They suggested us to add more access points and redesign the location of access points. We did the same. However we still see users noticing random disconnects.

We started noticing the issue the moment we moved from 8.2 code to 8.3. We thought the latest code might fix the issue. We are currently running 8.3.143. However we still see issues. Hence i ran a debug for certain users and was successful in capturing the drops. I'm attaching the same. We need experts to review this and tell us what are the other possible options.

xxxxx >*apfOpenDtlSocket: Aug 31 15:05:58.426: [PA] 06:87:bc:6a:79:02 Recevied management frame ASSOCIATION REQUEST on BSSID 78:72:5d:3d:6d:8e destination addr 78:72:5d:3d:6d:8e
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 Received EAPOL START, dot1x state = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 0 ---> 1 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 Received EAPOL START from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.451: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 2)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 Received Identity Response (count=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 Resetting reauth count 1 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 EAP State update from Connecting to Authenticating for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticating state
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.461: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.507: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.507: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=236) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.507: [PA] 06:87:bc:6a:79:02 WARNING: updated EAP-Identifier 2 ===> 236 for STA 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.507: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 236)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.507: [PA] 06:87:bc:6a:79:02 Allocating EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.511: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.511: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 236, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.511: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.511: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.556: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.556: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=237) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.556: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 237)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.556: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.582: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.582: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 237, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.582: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.582: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.630: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.630: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=238) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.630: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 238)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.630: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.637: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.637: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 238, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.637: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.637: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.691: [PA] 06:87:bc:6a:79:02 Processing Access-Accept for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.691: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 acl from 255 to 255

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.691: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 Flex acl from 65535 to 65535

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.691: [PA] 06:87:bc:6a:79:02 Received MPPE_SEND_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.691: [PA] 06:87:bc:6a:79:02 Received MPPE_RECV_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Station 06:87:bc:6a:79:02 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Stopping reauth timeout for 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Creating a PKC PMKID Cache entry for station 06:87:bc:6a:79:02 (RSN 2)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Removing BSSID 78:72:5d:3d:6d:8e from PMKID cache of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Created PMKID PMK Cache for BSSID 78:72:5d:3d:6d:8e at index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] New PMKID: (16)

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] [0000] 8e cc 1c 31 78 a5 82 d2 a4 1f d6 2c b7 83 99 0b

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 CCKM: Create a global PMK cache entry, AKM:0
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 PMK: Sending Flexconnect group cache delete message to spam task
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Uninit the PMK Cache entry. Client has changed the AKM type from 0 to 1 (username:XXXX)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Updated existing pmk cache for client having username: XXXX and audit-session-id:0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 1x: Updated the audit-session-id to PMK-Cache from client mscb: 0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Zeroize AAA Overrides from local for station
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.692: [PA] 06:87:bc:6a:79:02 Adding Audit session ID payload in Mobility handoff

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 0 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 PMK sent to mobility group
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Sending EAP-Success to mobile 06:87:bc:6a:79:02 (EAP Id 238)
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] [0000] 8e cc 1c 31 78 a5 82 d2 a4 1f d6 2c b7 83 99 0b

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] M1 - Key Data: (22)

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] [0000] dd 14 00 0f ac 04 8e cc 1c 31 78 a5 82 d2 a4 1f

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] [0016] d6 2c b7 83 99 0b

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Starting key exchange to mobile 06:87:bc:6a:79:02, data packets will be dropped
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Success state (id=238) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 Received Auth Success while in Authenticating state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.693: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticated state
*dot1xSocketTask: Aug 31 15:05:59.716: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.716: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.716: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.716: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:05:59.716: [PA] 06:87:bc:6a:79:02 Received EAPOL-key message with invalid version number from mobile 06:87:bc:6a:79:02 received version#: 2, expected :3
*osapiBsnTimer: Aug 31 15:06:00.737: [PA] 06:87:bc:6a:79:02 802.1x 'timeoutEvt' Timer expired for station 06:87:bc:6a:79:02 and for message = M2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:00.737: [PA] 06:87:bc:6a:79:02 Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 15:06:00.741: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:00.741: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:00.741: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:00.741: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:00.741: [PA] 06:87:bc:6a:79:02 Received EAPOL-key message with invalid version number from mobile 06:87:bc:6a:79:02 received version#: 2, expected :3
*osapiBsnTimer: Aug 31 15:06:01.737: [PA] 06:87:bc:6a:79:02 802.1x 'timeoutEvt' Timer expired for station 06:87:bc:6a:79:02 and for message = M2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:01.737: [PA] 06:87:bc:6a:79:02 Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 15:06:01.741: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:01.741: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:01.741: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:01.741: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:01.741: [PA] 06:87:bc:6a:79:02 Received EAPOL-key message with invalid version number from mobile 06:87:bc:6a:79:02 received version#: 2, expected :3
*osapiBsnTimer: Aug 31 15:06:02.737: [PA] 06:87:bc:6a:79:02 802.1x 'timeoutEvt' Timer expired for station 06:87:bc:6a:79:02 and for message = M2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:02.737: [PA] 06:87:bc:6a:79:02 Retransmit 3 of EAPOL-Key M1 (length 121) for mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 15:06:02.741: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:02.741: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:02.741: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:02.742: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:02.742: [PA] 06:87:bc:6a:79:02 Received EAPOL-key message with invalid version number from mobile 06:87:bc:6a:79:02 received version#: 2, expected :3
*osapiBsnTimer: Aug 31 15:06:03.737: [PA] 06:87:bc:6a:79:02 802.1x 'timeoutEvt' Timer expired for station 06:87:bc:6a:79:02 and for message = M2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:03.738: [PA] 06:87:bc:6a:79:02 Retransmit 4 of EAPOL-Key M1 (length 121) for mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 15:06:03.740: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:03.740: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:03.740: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:03.740: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 1

*Dot1x_NW_MsgTask_2: Aug 31 15:06:03.740: [PA] 06:87:bc:6a:79:02 Received EAPOL-key message with invalid version number from mobile 06:87:bc:6a:79:02 received version#: 2, expected :3
*osapiBsnTimer: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 802.1x 'timeoutEvt' Timer expired for station 06:87:bc:6a:79:02 and for message = M2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Retransmit failure for EAPOL-Key M1 to mobile 06:87:bc:6a:79:02, retransmit count 5, mscb deauth count 0
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Removing BSSID 78:72:5d:3d:6d:8e from PMKID cache of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Deleting the PMK cache when de-authenticating the client.
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 CCKM: Sending cache delete
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Removing PMK cache entry for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.737: [PA] 06:87:bc:6a:79:02 Succesfully freed AID 89, slot 1 on AP 78:72:5d:3d:6d:80, #client on this slot 13
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.738: [PA] 06:87:bc:6a:79:02 Sent Deauthenticate to mobile on BSSID 78:72:5d:3d:6d:8e slot 1(caller 1x_ptsm.c:655)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.738: [PA] 06:87:bc:6a:79:02 Scheduling deletion of Mobile Station: (callerId: 57) in 10 seconds
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.738: [PA] 06:87:bc:6a:79:02 Freeing EAP Retransmit Bufer for mobile 06:87:bc:6a:79:02
*apfOpenDtlSocket: Aug 31 15:06:04.918: [PA] 06:87:bc:6a:79:02 Recevied management frame REASSOCIATION REQUEST on BSSID 78:72:5d:3d:6d:8e destination addr 78:72:5d:3d:6d:8e
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Processing assoc-req station:06:87:bc:6a:79:02 AP:78:72:5d:3d:6d:80-01 ssid : XXXXthread:1a93fa60
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP 78:72:5D:3D:6D:80
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Reassociation received from mobile on BSSID 78:72:5d:3d:6d:8b AP blr4ap211
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP 78:72:5D:3D:6D:80
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Max Client Trap Threshold: 12 cur: 13

*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 override for default ap group, marking intgrp NULL
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_7: Aug 31 15:06:04.919: [PA] 06:87:bc:6a:79:02 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 In processSsidIE:6558 setting Central switched to TRUE
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 In processSsidIE:6561 apVapId = 2 and Split Acl Id = 65535
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Applying site-specific Local Bridging override for station 06:87:bc:6a:79:02 - vapId 5, site 'BXXXXX', interface 'vlan118'
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Applying Local Bridging Interface Policy for station 06:87:bc:6a:79:02 - vlan 118, interface id 14, interface 'vlan118'
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 override from ap group, removing intf group from mscb
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Applying site-specific override for station 06:87:bc:6a:79:02 - vapId 5, site 'XXXX', interface 'vlan118'
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Setting the NAS Id to AP group specific Id 'BLR4WL11'
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 STA - rates (6): 12 164 48 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] RSNIE in Assoc. Req.: (38)

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] [0016] ac 01 3c 00 01 00 8e cc 1c 31 78 a5 82 d2 a4 1f

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] [0032] d6 2c b7 83 99 0b

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Processing RSN IE type 48, length 38 for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 RSN Capabilities: 60
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Marking Mobile as non-11w Capable
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] 06:87:bc:6a:79:02 Received RSN IE with 1 PMKIDs from mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] Received PMKID: (16)

*apfMsConnTask_7: Aug 31 15:06:04.920: [PA] [0000] 8e cc 1c 31 78 a5 82 d2 a4 1f d6 2c b7 83 99 0b

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Searching for PMKID in MSCB PMKID cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 No valid PMKID found in the MSCB PMKID cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Trying to compute a PMKID from MSCB PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] CCKM: Find PMK in cache: BSSID = (6)

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] [0000] 78 72 5d 3d 6d 80

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] CCKM: Find PMK in cache: realAA = (6)

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] [0000] 78 72 5d 3d 6d 8e

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] CCKM: Find PMK in cache: PMKID = (16)

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] [0000] 8e cc 1c 31 78 a5 82 d2 a4 1f d6 2c b7 83 99 0b

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Unable to compute a valid PMKID from MSCB PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Searching for PMK in global PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Unable to compute a valid PMKID from global PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 8
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Allocate AID 104 slot 1 on AP blr4ap211 #clients on this slot 14
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Initializing policy
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 apfVapSecurity=0x4000 L2=16384 SkipWeb=0
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 AuthenticationRequired = 1
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 10.252.241.170 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Encryption policy is set to 0x80000001
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 78:72:5d:3d:6d:80 vapId 5 apVapId 2 flex-acl-name:
*apfMsConnTask_7: Aug 31 15:06:04.921: [PA] 06:87:bc:6a:79:02 apfPemAddUser2 (apf_policy.c:416) Changing state for mobile 06:87:bc:6a:79:02 on AP 78:72:5d:3d:6d:80 from Associated to Associated

*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 apfPemAddUser2:session timeout forstation 06:87:bc:6a:79:02 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 Sending assoc-resp with status 0 station:06:87:bc:6a:79:02 AP:78:72:5d:3d:6d:8e-01 on apVapId 2
*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 VHT Operation IE: width 20/0 ch 52 freq0 0 freq1 0 msc0 0x3f msc1 0x3f
*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 Sending Assoc Response (status: '0') to station on AP xxxx on BSSID 78:72:5d:3d:6d:8e ApVapId 2 Slot 1, mobility role 1
*apfMsConnTask_7: Aug 31 15:06:04.922: [PA] 06:87:bc:6a:79:02 apfProcessAssocReq (apf_80211.c:11039) Changing state for mobile 06:87:bc:6a:79:02 on AP 78:72:5d:3d:6d:80 from Associated to Associated

*spamApTask4: Aug 31 15:06:04.924: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP 78:72:5d:3d:6d:80
*spamApTask4: Aug 31 15:06:04.926: [PA] 06:87:bc:6a:79:02 Received ADD_MOBILE ack - Initiating 1x to STA 06:87:bc:6a:79:02 (idx 35)
*spamApTask4: Aug 31 15:06:04.926: [PA] 06:87:bc:6a:79:02 Sent dot1x auth initiate message for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.926: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 0 ---> 1 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 Station 06:87:bc:6a:79:02 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 Stopping reauth timeout for 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.927: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 1)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 Received EAPOL START, dot1x state = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 1 ---> 1 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 Received EAPOL START from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.944: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 2)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.955: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.955: [PA] 06:87:bc:6a:79:02 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 Received Identity Response (count=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 Resetting reauth count 1 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 EAP State update from Connecting to Authenticating for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticating state
*Dot1x_NW_MsgTask_2: Aug 31 15:06:04.965: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.011: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.011: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=111) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.011: [PA] 06:87:bc:6a:79:02 WARNING: updated EAP-Identifier 2 ===> 111 for STA 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.011: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 111)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.011: [PA] 06:87:bc:6a:79:02 Allocating EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.013: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.013: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 111, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.013: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.013: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.058: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.058: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=112) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.058: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 112)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.058: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.075: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.075: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 112, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.075: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.075: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.123: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.123: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=113) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.123: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 113)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.123: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.127: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.127: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 113, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.127: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.127: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Processing Access-Accept for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 acl from 255 to 255

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 Flex acl from 65535 to 65535

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Received MPPE_SEND_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Received MPPE_RECV_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Station 06:87:bc:6a:79:02 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Stopping reauth timeout for 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Creating a PKC PMKID Cache entry for station 06:87:bc:6a:79:02 (RSN 2)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 Created PMKID PMK Cache for BSSID 78:72:5d:3d:6d:8e at index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] New PMKID: (16)

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] [0000] 32 f8 45 39 c7 fb 46 de ea 6d ea f0 1b 20 70 2e

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.179: [PA] 06:87:bc:6a:79:02 802.11i: Create a global PMK cache entry, AKM-type = 1
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 apfCreatePmkCacheEntry: added a new pmk cache entry for 06:87:bc:6a:79:02

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 1x: Updated the audit-session-id to PMK-Cache from client mscb: 0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Zeroize AAA Overrides from local for station
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Adding Audit session ID payload in Mobility handoff

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 0 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 PMK sent to mobility group
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Sending EAP-Success to mobile 06:87:bc:6a:79:02 (EAP Id 113)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] [0000] 32 f8 45 39 c7 fb 46 de ea 6d ea f0 1b 20 70 2e

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] M1 - Key Data: (22)

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] [0000] dd 14 00 0f ac 04 32 f8 45 39 c7 fb 46 de ea 6d

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] [0016] ea f0 1b 20 70 2e

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Starting key exchange to mobile 06:87:bc:6a:79:02, data packets will be dropped
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.180: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.181: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Success state (id=113) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.181: [PA] 06:87:bc:6a:79:02 Received Auth Success while in Authenticating state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.181: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticated state
*dot1xSocketTask: Aug 31 15:06:05.190: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTK_START state (message 2) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Compare RSN IE in association and EAPOL-M2 frame(Skip pmkIdLen:16,and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in Association request:
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000000: 30 26 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0&..............
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000010: 00 0f ac 01 3c 00 01 00 8e cc 1c 31 78 a5 82 d2 ....<......1x...
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000020: a4 1f d6 2c b7 83 99 0b ...,....
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in EAPOL M2 :
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000010: ac 01 3c 00 01 00 8e cc 1c 31 78 a5 82 d2 a4 1f ..<......1x.....
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 00000020: d6 2c b7 83 99 0b .,....
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Not Flex client. Do not distribute PMK Key cache.
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.191: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.192: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.192: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 15:06:05.193: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.193: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 Freeing EAP Retransmit Bufer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 apfMs1xStateInc
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqSuccessCntInc
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 78:72:5d:3d:6d:80 vapId 5 apVapId 2 flex-acl-name:
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 apfMsRunStateInc
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Reached PLUMBFASTPATH: from line 6894, null
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Adding Fast Path rule
type = Airespace AP Client
on AP 78:72:5d:3d:6d:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255, IPv6 ACL ID
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 118, Local Bridging intf id = 14
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.194: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.195: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255)
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.195: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) No 11v BTM
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.195: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) NO release MSCB
*Dot1x_NW_MsgTask_2: Aug 31 15:06:05.195: [PA] 06:87:bc:6a:79:02 Successfully Plumbed PTK session Keysfor mobile 06:87:bc:6a:79:02
*spamApTask4: Aug 31 15:06:05.195: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP 78:72:5d:3d:6d:80
*pemReceiveTask: Aug 31 15:06:05.197: [PA] 06:87:bc:6a:79:02 10.252.241.170 Added NPU entry of type 1, dtlFlags 0x0
*pemReceiveTask: Aug 31 15:06:05.197: [PA] 06:87:bc:6a:79:02 Pushing IPv6: fe80:0000:0000:0000:8967:aa79:34cc:e542 , intfId:14 and MAC: 06:87:BC:6A:79:02 , Binding to Data Plane. SUCCESS !!
*pemReceiveTask: Aug 31 15:06:05.197: [PA] 06:87:bc:6a:79:02 Pushing IPv6: fe80:0000:0000:0000:f156:5754:a75d:d21f , intfId:14 and MAC: 06:87:BC:6A:79:02 , Binding to Data Plane. SUCCESS !!
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREQUEST (1) (len 308,vlan 176, port 13, encap 0xec03, xid 0x61cb7c5)
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 1 - control block settings:
dhcpServer: xxxxxx, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP mscbVapLocalAddr=10.252.240.11 mscbVapLocalNetMask= 255.255.240.0 mscbdhcpRelay=10.252.240.11
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP selected relay 1 - xxxxx. (local address 10.252.240.11, gateway 10.252.240.1, VLAN 118, port 13)
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP REQUEST (3)
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP xid: 0x61cb7c5 (102545349), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 10.252.240.11
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP requested ip: 10.252.241.170
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP sending REQUEST to 10.252.240.1 (len 350, port 13, vlan 118)
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 2 - control block settings:
dhcpServer: x.x.x.x, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 15:06:05.223: [PA] 06:87:bc:6a:79:02 DHCP selected relay 2 - NONE
*DHCP Socket Task: Aug 31 15:06:05.224: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREPLY (2) (len 315,vlan 118, port 13, encap 0xec00, xid 0x61cb7c5)
*DHCP Socket Task: Aug 31 15:06:05.224: [PA] 06:87:bc:6a:79:02 DHCP setting server from ACK (mscb=0x481d41c8 ip=0xafcf1aa)(server xxxxx yiaddr 10.252.241.170)
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP sending REPLY to STA (len 426, port 13, vlan 176)
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP ACK (5)
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP xid: 0x61cb7c5 (102545349), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 10.252.241.170
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 15:06:05.225: [PA] 06:87:bc:6a:79:02 DHCP server id: 1.1.1.1 rcvd server id: xxxxxx
?

Leo Laohoo · ‎09-07-2018

1. VERIFY the issue - Go to the place(s) where people believe there is wireless coverage hole and take sampled readings. Don't just go there with a single wireless client to take the reading. Bring at least two.

2. Take down the nearby APs and verify the radio power setting of the APs: Are they in power level 1 or 8?

3. Talk to the people who are complaining. Look at their wireless clients. Can you replicate what the people are talking about?

4. Get the MAC address of some affected wireless clients and run a debug. Compare it with something that works.

I cannot begin to stress how important #1 is because this makes-or-break everything.

View solution in original post

Leo Laohoo · ‎08-31-2018

The above logs only show a wireless client re-authenticate. There is no evidence to show anything.
If the partner recommends putting more AP, the question is WHERE are the new APs deployed and are the newly deployed APs in the vicinity of where the blackspots are occurring or not?

deepak george · ‎09-01-2018

Hello Leo,

Thanks for getting back.

The partner recommended new AP's as they detected Coverage holes in the network. Hence new AP's have been added to the existing infra.

I'm sharing another set of logs and also please help me to understand how do i read the logs, if there is a method or a way

(xxxx) >*IPv6_Msg_Task: Aug 31 10:42:39.176: [PA] 06:87:bc:6a:79:02 Link Local address fe80::8967:aa79:34cc:e542 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_A
*apfOpenDtlSocket: Aug 31 10:42:54.649: [PA] 06:87:bc:6a:79:02 Recevied management frame REASSOCIATION REQUEST on BSSID b0:8b:cf:a9:77:8e destination addr b0:8b:cf:a9:77:8e
*apfMsConnTask_2: Aug 31 10:42:54.649: [PA] 06:87:bc:6a:79:02 Processing assoc-req station:06:87:bc:6a:79:02 AP:b0:8b:cf:a9:77:80-01 ssid : xxxxxx thread:1a93e6d8
*apfMsConnTask_2: Aug 31 10:42:54.649: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP B0:8B:CF:A9:77:80
*apfMsConnTask_2: Aug 31 10:42:54.649: [PA] 06:87:bc:6a:79:02 Reassociation received from mobile on BSSID b0:8b:cf:a9:77:8b AP xxxxxap212
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP B0:8B:CF:A9:77:80
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Max Client Trap Threshold: 12 cur: 13

*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 override for default ap group, marking intgrp NULL
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 In processSsidIE:6558 setting Central switched to TRUE
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 In processSsidIE:6561 apVapId = 2 and Split Acl Id = 65535
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Applying site-specific Local Bridging override for station 06:87:bc:6a:79:02 - vapId 5, site 'xxxxx_xxxxx_Bldg', interface 'vlan118'
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Applying Local Bridging Interface Policy for station 06:87:bc:6a:79:02 - vlan 118, interface id 14, interface 'vlan118'
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 override from ap group, removing intf group from mscb
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Applying site-specific override for station 06:87:bc:6a:79:02 - vapId 5, site 'xxxxxxxxxx', interface 'vlan118'
*apfMsConnTask_2: Aug 31 10:42:54.650: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Setting the NAS Id to AP group specific Id xxxxxx
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 STA - rates (6): 12 164 48 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] RSNIE in Assoc. Req.: (38)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0016] ac 01 3c 00 01 00 7a 37 36 0e ba db 53 2e 88 9a

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0032] 7e 17 f0 9f be d2

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Processing RSN IE type 48, length 38 for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 RSN Capabilities: 60
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Marking Mobile as non-11w Capable
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Received RSN IE with 1 PMKIDs from mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] Received PMKID: (16)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0000] 7a 37 36 0e ba db 53 2e 88 9a 7e 17 f0 9f be d2

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 No valid PMKID found in the MSCB PMKID cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] 06:87:bc:6a:79:02 Trying to compute a PMKID from MSCB PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] CCKM: Find PMK in cache: BSSID = (6)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] CCKM: Find PMK in cache: realAA = (6)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0000] b0 8b cf a9 77 8e

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] CCKM: Find PMK in cache: PMKID = (16)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0000] 7a 37 36 0e ba db 53 2e 88 9a 7e 17 f0 9f be d2

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] CCKM: AA (6)

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] [0000] b0 8b cf a9 77 8e

*apfMsConnTask_2: Aug 31 10:42:54.651: [PA] CCKM: SPA (6)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 06 87 bc 6a 79 02

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] PMK Key: (32)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 8b e5 9b 22 ca 40 02 f0 26 a4 80 f7 83 dc 04 ba

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 computing pmk, received 11w flag: 0
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Inside dot1xDoesPmkIdMatchPmk2:458
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] Received PMKID (16)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 7a 37 36 0e ba db 53 2e 88 9a 7e 17 f0 9f be d2

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] Computed PMKID (16)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 98 77 25 00 4e 11 97 46 2f 97 89 63 ae b7 dd 55

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Unable to compute a valid PMKID from MSCB PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Searching for PMK in global PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Found an entry in the global PMK cache for station 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] CCKM: AA (6)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] b0 8b cf a9 77 8e

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] CCKM: SPA (6)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 06 87 bc 6a 79 02

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] PMK Key: (32)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 8b e5 9b 22 ca 40 02 f0 26 a4 80 f7 83 dc 04 ba

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0016] 23 af e0 1a eb 14 73 1d 3a 0a 7c a9 75 4a 86 f5

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 computing pmk, received 11w flag: 0
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Inside dot1xDoesPmkIdMatchPmk2:458
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] Received PMKID (16)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 7a 37 36 0e ba db 53 2e 88 9a 7e 17 f0 9f be d2

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] Computed PMKID (16)

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] [0000] 98 77 25 00 4e 11 97 46 2f 97 89 63 ae b7 dd 55

*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Unable to compute a valid PMKID from global PMK cache for mobile 06:87:bc:6a:79:02
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 Setting active key cache index 0 ---> 8
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*apfMsConnTask_2: Aug 31 10:42:54.652: [PA] 06:87:bc:6a:79:02 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Deleted mobile LWAPP rule on AP [78:72:5d:3d:6d:80]
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Succesfully freed AID 18, slot 1 on AP 78:72:5d:3d:6d:80, #client on this slot 6
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 New ctxOwnerMwarIp: 10.252.192.11 New ctxOwnerApMac: B0:8B:CF:A9:77:80 New ctxOwnerApEthMac: 78:72:5D:38:A6:E8 New ctxOwnerApSlotId: 1
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Updated location for station old AP 78:72:5d:3d:6d:80 oldSlot 1, new AP b0:8b:cf:a9:77:80 newSlot 1, AID 0 MsType 0 MobilityRole 1
*spamApTask4: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Delete Mobile request on slot 1 sent to the AP 78:72:5d:3d:6d:80 IP: 10.140.14.70:35440

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Allocate AID 24 slot 1 on AP xxxxxap212 #clients on this slot 14
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 apfMsRunStateDec
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 apfMs1xStateDec
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Initializing policy
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 apfVapSecurity=0x4000 L2=16384 SkipWeb=0
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 AuthenticationRequired = 1
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Encryption policy is set to 0x80000001
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Plumbed mobile LWAPP rule on AP b0:8b:cf:a9:77:80 vapId 5 apVapId 2 flex-acl-name:
*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 apfPemAddUser2 (apf_policy.c:416) Changing state for mobile 06:87:bc:6a:79:02 on AP b0:8b:cf:a9:77:80 from Associated to Associated

*apfMsConnTask_2: Aug 31 10:42:54.653: [PA] 06:87:bc:6a:79:02 apfPemAddUser2:session timeout forstation 06:87:bc:6a:79:02 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 Sending assoc-resp with status 0 station:06:87:bc:6a:79:02 AP:b0:8b:cf:a9:77:80-01 on apVapId 2
*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 VHT Operation IE: width 20/0 ch 161 freq0 0 freq1 0 msc0 0x3f msc1 0x3f
*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 Sending Assoc Response (status: '0') to station on AP xxxxxap212 on BSSID b0:8b:cf:a9:77:8e ApVapId 2 Slot 1, mobility role 1
*apfMsConnTask_2: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 apfProcessAssocReq (apf_80211.c:11039) Changing state for mobile 06:87:bc:6a:79:02 on AP b0:8b:cf:a9:77:80 from Associated to Associated

*pemReceiveTask: Aug 31 10:42:54.654: [PA] 06:87:bc:6a:79:02 10.252.241.170 Removed NPU entry.
*spamApTask4: Aug 31 10:42:54.655: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP b0:8b:cf:a9:77:80
*spamApTask4: Aug 31 10:42:54.655: [PA] 06:87:bc:6a:79:02 apfUpdateDeleteAckInMscb (apf_api.c:51702) Expiring Mobile!
*spamApTask4: Aug 31 10:42:54.656: [PA] 06:87:bc:6a:79:02 Received ADD_MOBILE ack - Initiating 1x to STA 06:87:bc:6a:79:02 (idx 57)
*spamApTask4: Aug 31 10:42:54.656: [PA] 06:87:bc:6a:79:02 Sent dot1x auth initiate message for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.657: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 1 ---> 0 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.657: [PA] 06:87:bc:6a:79:02 EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.657: [PA] 06:87:bc:6a:79:02 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.657: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.657: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 1)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.668: [PA] 06:87:bc:6a:79:02 Received EAPOL START, dot1x state = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.668: [PA] 06:87:bc:6a:79:02 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.669: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 0 ---> 1 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.669: [PA] 06:87:bc:6a:79:02 Received EAPOL START from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.669: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.669: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 2)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.689: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.689: [PA] 06:87:bc:6a:79:02 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 Received Identity Response (count=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 Resetting reauth count 1 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 EAP State update from Connecting to Authenticating for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticating state
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.700: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.746: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.746: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=33) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.746: [PA] 06:87:bc:6a:79:02 WARNING: updated EAP-Identifier 2 ===> 33 for STA 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.746: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 33)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.746: [PA] 06:87:bc:6a:79:02 Allocating EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.749: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.749: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 33, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.749: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.749: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.794: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.794: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=34) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.795: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 34)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.795: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.815: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.815: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 34, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.815: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.815: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.863: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.863: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=35) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.863: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 35)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.863: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.869: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.869: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 35, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.869: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.869: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Processing Access-Accept for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 acl from 255 to 255

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 Flex acl from 65535 to 65535

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Received MPPE_SEND_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Received MPPE_RECV_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Station 06:87:bc:6a:79:02 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Stopping reauth timeout for 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Creating a PKC PMKID Cache entry for station 06:87:bc:6a:79:02 (RSN 2)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Removing BSSID 78:72:5d:3d:6d:8e from PMKID cache of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] 06:87:bc:6a:79:02 Created PMKID PMK Cache for BSSID b0:8b:cf:a9:77:8e at index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] New PMKID: (16)

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.921: [PA] [0000] 14 06 00 b0 25 4a 0e 90 3b fc a0 9b a6 89 19 95

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 802.11i: Create a global PMK cache entry, AKM-type = 1
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 PMK: Sending Flexconnect group cache delete message to spam task
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Updated existing pmk cache for client having username: xxxxxkiranv and audit-session-id:0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 1x: Updated the audit-session-id to PMK-Cache from client mscb: 0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Zeroize AAA Overrides from local for station
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Adding Audit session ID payload in Mobility handoff

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 0 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 PMK sent to mobility group
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Sending EAP-Success to mobile 06:87:bc:6a:79:02 (EAP Id 35)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID b0:8b:cf:a9:77:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID b0:8b:cf:a9:77:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] [0000] 14 06 00 b0 25 4a 0e 90 3b fc a0 9b a6 89 19 95

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.922: [PA] M1 - Key Data: (22)

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] [0000] dd 14 00 0f ac 04 14 06 00 b0 25 4a 0e 90 3b fc

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] [0016] a0 9b a6 89 19 95

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 Starting key exchange to mobile 06:87:bc:6a:79:02, data packets will be dropped
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Success state (id=35) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 Received Auth Success while in Authenticating state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.923: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticated state
*dot1xSocketTask: Aug 31 10:42:54.944: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTK_START state (message 2) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Compare RSN IE in association and EAPOL-M2 frame(Skip pmkIdLen:16,and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in Association request:
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000000: 30 26 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0&..............
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000010: 00 0f ac 01 3c 00 01 00 7a 37 36 0e ba db 53 2e ....<...z76...S.
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000020: 88 9a 7e 17 f0 9f be d2 ..~.....
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in EAPOL M2 :
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000010: ac 01 3c 00 01 00 7a 37 36 0e ba db 53 2e 88 9a ..<...z76...S...
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 00000020: 7e 17 f0 9f be d2 ~.....
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Not Flex client. Do not distribute PMK Key cache.
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.945: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.946: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.946: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.946: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Freeing EAP Retransmit Bufer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 apfMs1xStateInc
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqSuccessCntInc
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP b0:8b:cf:a9:77:80 vapId 5 apVapId 2 flex-acl-name:
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 apfMsRunStateInc
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.949: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Reached PLUMBFASTPATH: from line 6894, null
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Adding Fast Path rule
type = Airespace AP Client
on AP b0:8b:cf:a9:77:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255, IPv6 ACL ID
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 118, Local Bridging intf id = 14
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255)
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) No 11v BTM
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) NO release MSCB
*Dot1x_NW_MsgTask_2: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 Successfully Plumbed PTK session Keysfor mobile 06:87:bc:6a:79:02
*spamApTask4: Aug 31 10:42:54.950: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP b0:8b:cf:a9:77:80
*pemReceiveTask: Aug 31 10:42:54.952: [PA] 06:87:bc:6a:79:02 10.252.241.170 Added NPU entry of type 1, dtlFlags 0x0
*pemReceiveTask: Aug 31 10:42:54.952: [PA] 06:87:bc:6a:79:02 Pushing IPv6: fe80:0000:0000:0000:8967:aa79:34cc:e542 , intfId:14 and MAC: 06:87:BC:6A:79:02 , Binding to Data Plane. SUCCESS !!
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREQUEST (1) (len 308,vlan 176, port 13, encap 0xec03, xid 0xf96c8239)
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 1 - control block settings:
dhcpServer: 10.140.50.5, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP mscbVapLocalAddr=10.252.240.11 mscbVapLocalNetMask= 255.255.240.0 mscbdhcpRelay=10.252.240.11
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP selected relay 1 - 10.140.50.5 (local address 10.252.240.11, gateway 10.252.240.1, VLAN 118, port 13)
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP REQUEST (3)
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP xid: 0xf96c8239 (4184638009), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 10.252.240.11
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP requested ip: 10.252.241.170
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP sending REQUEST to 10.252.240.1 (len 350, port 13, vlan 118)
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 2 - control block settings:
dhcpServer: 10.140.50.5, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 10:42:54.969: [PA] 06:87:bc:6a:79:02 DHCP selected relay 2 - NONE
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREPLY (2) (len 315,vlan 118, port 13, encap 0xec00, xid 0xf96c8239)
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP setting server from ACK (mscb=0x481d41c8 ip=0xafcf1aa)(server 10.140.50.5, yiaddr 10.252.241.170)
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP sending REPLY to STA (len 426, port 13, vlan 176)
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP ACK (5)
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP xid: 0xf96c8239 (4184638009), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 10:42:54.970: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 10.252.241.170
*DHCP Socket Task: Aug 31 10:42:54.971: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 10:42:54.971: [PA] 06:87:bc:6a:79:02 DHCP server id: 1.1.1.1 rcvd server id: 10.140.50.5
?

clear Clear selected configuration elements.
config Configure switch options and settings.
cping Send capwap echo packets to a specified mobility peer IP address.
debug Manages system debug options.
eping Send Ethernet-over-IP echo packets to a specified mobility peer IP address.
grep Print lines matching a pattern.
help Help
license Manage Software License
linktest Perform a link test to a specified MAC address.
logout Exit this session. Any unsaved changes are lost.
mping Send Mobility echo packets to a specified mobility peer IP address.
ping Send ICMP echo packets to a specified IP address.
redundancy Manage HA Redundancy
reset Reboot (hard reload) options.
rping Send Redundancy ping packets to peer RP and RMI
save Save switch configurations.
show Display switch options and settings.
test Test trigger commands
transfer Transfer a file to or from the switch.

(xxxxxxxxwl11) >*IPv6_Msg_Task: Aug 31 10:42:55.440: [PA] 06:87:bc:6a:79:02 Link Local address fe80::8967:aa79:34cc:e542 updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_A
*apfOpenDtlSocket: Aug 31 10:45:55.421: [PA] 06:87:bc:6a:79:02 Recevied management frame REASSOCIATION REQUEST on BSSID 78:72:5d:3d:6d:8e destination addr 78:72:5d:3d:6d:8e
*apfMsConnTask_7: Aug 31 10:45:55.421: [PA] 06:87:bc:6a:79:02 Processing assoc-req station:06:87:bc:6a:79:02 AP:78:72:5d:3d:6d:80-01 ssid : xxxxx thread:1a93fa60
*apfMsConnTask_7: Aug 31 10:45:55.421: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP 78:72:5D:3D:6D:80
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Reassociation received from mobile on BSSID 78:72:5d:3d:6d:8b AP xxxxxxxap211
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Station: 06:87:BC:6A:79:02 11v BSS Transition not enabled on the AP 78:72:5D:3D:6D:80
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Max Client Trap Threshold: 12 cur: 3

*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 override for default ap group, marking intgrp NULL
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 In processSsidIE:6558 setting Central switched to TRUE
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 In processSsidIE:6561 apVapId = 2 and Split Acl Id = 65535
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Applying site-specific Local Bridging override for station 06:87:bc:6a:79:02 - vapId 5, site 'xxxxx', interface 'vlan118'
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 Applying Local Bridging Interface Policy for station 06:87:bc:6a:79:02 - vlan 118, interface id 14, interface 'vlan118'
*apfMsConnTask_7: Aug 31 10:45:55.422: [PA] 06:87:bc:6a:79:02 override from ap group, removing intf group from mscb
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Applying site-specific override for station 06:87:bc:6a:79:02 - vapId 5, site 'xxxxx', interface 'vlan118'
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Applying Interface(vlan118) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 118

*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Re-applying interface policy for client

*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Setting the NAS Id to AP group specific Id 'xxxx1'
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 STA - rates (6): 12 164 48 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] RSNIE in Assoc. Req.: (22)

*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] [0016] ac 01 3c 00 00 00

*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Processing RSN IE type 48, length 22 for mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Received 802.11i 802.1X key management suite, enabling dot1x Authentication
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 RSN Capabilities: 60
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Marking Mobile as non-11w Capable
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Received RSN IE with 0 PMKIDs from mobile 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID b0:8b:cf:a9:77:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Removing BSSID b0:8b:cf:a9:77:8e from PMKID cache of station 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 Setting active key cache index 0 ---> 8
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*apfMsConnTask_7: Aug 31 10:45:55.423: [PA] 06:87:bc:6a:79:02 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Deleted mobile LWAPP rule on AP [b0:8b:cf:a9:77:80]
*pemReceiveTask: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 Removed NPU entry.
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Succesfully freed AID 24, slot 1 on AP b0:8b:cf:a9:77:80, #client on this slot 14
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 New ctxOwnerMwarIp: 10.252.192.11 New ctxOwnerApMac: 78:72:5D:3D:6D:80 New ctxOwnerApEthMac: A0:93:51:28:B9:E4 New ctxOwnerApSlotId: 1
*spamApTask4: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Delete Mobile request on slot 1 sent to the AP b0:8b:cf:a9:77:80 IP: 10.140.14.71:35744

*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Updated location for station old AP b0:8b:cf:a9:77:80 oldSlot 1, new AP 78:72:5d:3d:6d:80 newSlot 1, AID 0 MsType 0 MobilityRole 1
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Allocate AID 18 slot 1 on AP xxxxxap211 #clients on this slot 4
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 apfMsRunStateDec
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 apfMs1xStateDec
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Initializing policy
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 apfVapSecurity=0x4000 L2=16384 SkipWeb=0
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 AuthenticationRequired = 1
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Encryption policy is set to 0x80000001
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 78:72:5d:3d:6d:80 vapId 5 apVapId 2 flex-acl-name:
*apfMsConnTask_7: Aug 31 10:45:55.424: [PA] 06:87:bc:6a:79:02 apfPemAddUser2:session timeout forstation 06:87:bc:6a:79:02 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 Sending assoc-resp with status 0 station:06:87:bc:6a:79:02 AP:78:72:5d:3d:6d:80-01 on apVapId 2
*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 VHT Operation IE: width 20/0 ch 52 freq0 0 freq1 0 msc0 0x3f msc1 0x3f
*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 Sending Assoc Response (status: '0') to station on AP xxxxxap211 on BSSID 78:72:5d:3d:6d:8e ApVapId 2 Slot 1, mobility role 1
*apfMsConnTask_7: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 apfProcessAssocReq (apf_80211.c:11039) Changing state for mobile 06:87:bc:6a:79:02 on AP 78:72:5d:3d:6d:80 from Associated to Associated

*spamApTask4: Aug 31 10:45:55.425: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP 78:72:5d:3d:6d:80
*spamApTask4: Aug 31 10:45:55.426: [PA] 06:87:bc:6a:79:02 apfUpdateDeleteAckInMscb (apf_api.c:51702) Expiring Mobile!
*spamApTask4: Aug 31 10:45:55.427: [PA] 06:87:bc:6a:79:02 Received ADD_MOBILE ack - Initiating 1x to STA 06:87:bc:6a:79:02 (idx 35)
*spamApTask4: Aug 31 10:45:55.427: [PA] 06:87:bc:6a:79:02 Sent dot1x auth initiate message for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.427: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 1 ---> 0 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.428: [PA] 06:87:bc:6a:79:02 EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.428: [PA] 06:87:bc:6a:79:02 Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.428: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.428: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 1)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 Received EAPOL START, dot1x state = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 Reset the reauth counter since EAPOL START has been received!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 reauth_sm state transition 0 ---> 1 for mobile 06:87:bc:6a:79:02 at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 Received EAPOL START from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Connecting state
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.437: [PA] 06:87:bc:6a:79:02 Sending EAP-Request/Identity to mobile 06:87:bc:6a:79:02 (EAP Id 2)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.455: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.455: [PA] 06:87:bc:6a:79:02 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 Received Identity Response (count=1) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 Resetting reauth count 1 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 EAP State update from Connecting to Authenticating for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticating state
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.468: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.514: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.514: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=25) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.514: [PA] 06:87:bc:6a:79:02 WARNING: updated EAP-Identifier 2 ===> 25 for STA 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.514: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.514: [PA] 06:87:bc:6a:79:02 Allocating EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.520: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.520: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 25, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.520: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.520: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.565: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.565: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=26) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.565: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 26)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.565: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.587: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.587: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 26, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.587: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.587: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.636: [PA] 06:87:bc:6a:79:02 Processing Access-Challenge for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.636: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Req state (id=27) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.636: [PA] 06:87:bc:6a:79:02 Sending EAP Request from AAA to mobile 06:87:bc:6a:79:02 (EAP Id 27)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.636: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.641: [PA] 06:87:bc:6a:79:02 Received EAPOL EAPPKT from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.641: [PA] 06:87:bc:6a:79:02 Received EAP Response from mobile 06:87:bc:6a:79:02 (EAP Id 27, EAP Type 25)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.641: [PA] 06:87:bc:6a:79:02 Resetting reauth count 0 to 0 for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.642: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Response state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Processing Access-Accept for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 acl from 255 to 255

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Resetting web IPv4 Flex acl from 65535 to 65535

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Received MPPE_SEND_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Received MPPE_RECV_KEY: KeyLen: 32

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Station 06:87:bc:6a:79:02 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Stopping reauth timeout for 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Creating a PKC PMKID Cache entry for station 06:87:bc:6a:79:02 (RSN 2)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Resetting MSCB PMK Cache Entry @index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 Created PMKID PMK Cache for BSSID 78:72:5d:3d:6d:8e at index 0 for station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] New PMKID: (16)

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] [0000] 71 ed 94 30 be 94 90 53 5f c0 ff 27 69 88 a7 31

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.693: [PA] 06:87:bc:6a:79:02 802.11i: Create a global PMK cache entry, AKM-type = 1
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 PMK: Sending Flexconnect group cache delete message to spam task
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Updated existing pmk cache for client having username: xxxxxkiranv and audit-session-id:0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 1x: Updated the audit-session-id to PMK-Cache from client mscb: 0afcc00b00023b4f5b88ccfb
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Zeroize AAA Overrides from local for station
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Adding Audit session ID payload in Mobility handoff

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 0 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 PMK sent to mobility group
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Sending EAP-Success to mobile 06:87:bc:6a:79:02 (EAP Id 27)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] 06:87:bc:6a:79:02 Found an cache entry for BSSID 78:72:5d:3d:6d:8e in PMKID cache at index 0 of station 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] [0000] 71 ed 94 30 be 94 90 53 5f c0 ff 27 69 88 a7 31

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] M1 - Key Data: (22)

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] [0000] dd 14 00 0f ac 04 71 ed 94 30 be 94 90 53 5f c0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.694: [PA] [0016] ff 27 69 88 a7 31

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 Starting key exchange to mobile 06:87:bc:6a:79:02, data packets will be dropped
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 Entering Backend Auth Success state (id=27) for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 Received Auth Success while in Authenticating state for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.695: [PA] 06:87:bc:6a:79:02 dot1x - moving mobile 06:87:bc:6a:79:02 into Authenticated state
*dot1xSocketTask: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTK_START state (message 2) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.717: [PA] 06:87:bc:6a:79:02 Compare RSN IE in association and EAPOL-M2 frame(Skip pmkIdLen:0,and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in Association request:
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 00000000: 30 16 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0...............
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 00000010: 00 0f ac 01 3c 00 00 00 ....<...
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Dumping RSNIE received in EAPOL M2 :
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 00000010: ac 01 3c 00 00 00 ..<...
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Not Flex client. Do not distribute PMK Key cache.
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Sending EAPOL-Key Message to mobile 06:87:bc:6a:79:02
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.718: [PA] 06:87:bc:6a:79:02 Reusing allocated memory for EAP Pkt for retransmission to mobile 06:87:bc:6a:79:02
*dot1xSocketTask: Aug 31 10:45:55.721: [PA] 06:87:bc:6a:79:02 validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.721: [PA] 06:87:bc:6a:79:02 Received EAPOL-Key from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.721: [PA] 06:87:bc:6a:79:02 key Desc Version FT - 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.721: [PA] 06:87:bc:6a:79:02 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 Stopping retransmission timer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 Freeing EAP Retransmit Bufer for mobile 06:87:bc:6a:79:02
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 apfMs1xStateInc
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqCntInc
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 apfMsPeapSimReqSuccessCntInc
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 78:72:5d:3d:6d:80 vapId 5 apVapId 2 flex-acl-name:
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 apfMsRunStateInc
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Reached PLUMBFASTPATH: from line 6894, null
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Adding Fast Path rule
type = Airespace AP Client
on AP 78:72:5d:3d:6d:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255, IPv6 ACL ID
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 14 Local Bridging Vlan = 118, Local Bridging intf id = 14
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.722: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 4, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255)
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) No 11v BTM
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 10.252.241.170 RUN (20) NO release MSCB
*Dot1x_NW_MsgTask_2: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 Successfully Plumbed PTK session Keysfor mobile 06:87:bc:6a:79:02
*spamApTask4: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 Successful transmission of LWAPP Add-Mobile to AP 78:72:5d:3d:6d:80
*pemReceiveTask: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 10.252.241.170 Added NPU entry of type 1, dtlFlags 0x0
*pemReceiveTask: Aug 31 10:45:55.723: [PA] 06:87:bc:6a:79:02 Pushing IPv6: fe80:0000:0000:0000:8967:aa79:34cc:e542 , intfId:14 and MAC: 06:87:BC:6A:79:02 , Binding to Data Plane. SUCCESS !!
*DHCP Socket Task: Aug 31 10:45:55.744: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREQUEST (1) (len 308,vlan 176, port 13, encap 0xec03, xid 0x47790ac)
*DHCP Socket Task: Aug 31 10:45:55.744: [PA] 06:87:bc:6a:79:02 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff
*DHCP Socket Task: Aug 31 10:45:55.744: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 1 - control block settings:
dhcpServer: 10.140.50.5, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP mscbVapLocalAddr=10.252.240.11 mscbVapLocalNetMask= 255.255.240.0 mscbdhcpRelay=10.252.240.11
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP selected relay 1 - 10.140.50.5 (local address 10.252.240.11, gateway 10.252.240.1, VLAN 118, port 13)
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP REQUEST (3)
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP xid: 0x47790ac (74944684), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 10.252.240.11
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP requested ip: 10.252.241.170
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP sending REQUEST to 10.252.240.1 (len 350, port 13, vlan 118)
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP selecting relay 2 - control block settings:
dhcpServer: 10.140.50.5, dhcpNetmask: 255.255.240.0,
dhcpGateway: 10.252.240.1, dhcpRelay: 10.252.240.11 VLAN: 1
*DHCP Socket Task: Aug 31 10:45:55.745: [PA] 06:87:bc:6a:79:02 DHCP selected relay 2 - NONE
*DHCP Socket Task: Aug 31 10:45:55.746: [PA] 06:87:bc:6a:79:02 DHCP received op BOOTREPLY (2) (len 315,vlan 118, port 13, encap 0xec00, xid 0x47790ac)
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP setting server from ACK (mscb=0x481d41c8 ip=0xafcf1aa)(server 10.140.50.5, yiaddr 10.252.241.170)
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP sending REPLY to STA (len 426, port 13, vlan 176)
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP transmitting DHCP ACK (5)
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP xid: 0x47790ac (74944684), secs: 0, flags: 0
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP chaddr: 06:87:bc:6a:79:02
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP ciaddr: 0.0.0.0, yiaddr: 10.252.241.170
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0
*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP server id: 1.1.1.1 rcvd server id: 10.140.50.5

Leo Laohoo · ‎09-01-2018

Again, these are debugs from wireless client successfully authenticating to the SSID. Nothing spectacular.
So, extra APs are added for the coverage hole. So answer this question: WHERE is the wireless client located when they are complaining about disconnection? In the places where additional APs were added or somewhere else?

deepak george · ‎09-01-2018

Hi Leo, I would say it is mixed as in we have user disconnections where there are no new AP' s added and also an area where new AP's existed. I'm not sure if i'm missing something regarding the debugs as these were captured when the user saw a disconnection and at the same time i verified that the user's statement was correct, he was indeed disconnected. Do you have any suggestions/recommendations Thanks

Rasika Nayanajith · ‎09-07-2018

As you said if that occurs when you upgrade from 8.2.x to 8.3.x , that strongly suggest it is due to behavior of 8.3.x code.

If you want to verify that, you can roll back to 8.2.x. Else try 8.5.135.0 to if that shows same behavior (as long as your AP models supported by that code version

HTH

Rasika

deepak george · ‎09-07-2018

Hello Rasika,

Thanks for getting back on the same.
It is always a best practice do keep upgrading the firmware ,hence rolling back and getting stuck with 8.2 will be a bad idea according to me. However i will be able to confirm if it is a firmware issue after i roll back to 8.2.

Another point i would like to add is that we upgraded to 8.3 code at the same time at all our sites, it is just one particular site we are seeing multiple issues which i strange. hence we started debugging the issue and also opened TAC cases. TAC's suggestion is as follows.

Line 206: *osapiBsnTimer: Aug 31 10:54:26.984: [PA] x.x.x.x 802.1x 'timeoutEvt' Timer expired for station x.x.x.x and for message = M2
Line 215: *osapiBsnTimer: Aug 31 10:54:27.984: [PA] x.x.x.x 802.1x 'timeoutEvt' Timer expired for station x.x.xxand for message = M2
Line 224: *osapiBsnTimer: Aug 31 10:54:28.984: [PA] x.x.x.x802.1x 'timeoutEvt' Timer expired for station x.x.x.x and for message = M2
Line 233: *osapiBsnTimer: Aug 31 10:54:29.984: [PA] x.x.x.x 802.1x 'timeoutEvt' Timer expired for station x.x.x.xxand for message = M2

the client by no receiving m2 message for the EAPOL exchange for the encryption as the following:
All the symptoms indicates a client side behavior and so my suggestions are as below:

• Update the client wireless driver (Mandatory step)
• Increase the EAPOL timers to give the client more time to respond.
• Disable the FT 802.1x in case the client is not supporting this method and test the behavior after.

The drivers were updated and i put the clients on another SSID with FT 802.1x =disabled and FT set to adaptive mode.
Now we are seeing a new issue.

""WLC cannot find a valid PMKID to match the one provided by the client. However, if the client performs OKC and not SKC, the WLC computes a new PMKID based on the information gathered (the cached PMK, the client MAC address, and the new AP MAC address)""

The client roams to another AP when the client is stationary. I'm aware that roaming depends on the client and not the AP. The RSSI value of the client was at -82 dbm. However another user adjacent to this client had an RSSI value of -63dbm.This client with -63dbm too had issues but we didn't see any drops yesterday

The same client which currently has got an issue told me that before the 8.3 upgrade he didnt face a single disconnection.

Leo Laohoo · ‎09-07-2018

1. VERIFY the issue - Go to the place(s) where people believe there is wireless coverage hole and take sampled readings. Don't just go there with a single wireless client to take the reading. Bring at least two.

2. Take down the nearby APs and verify the radio power setting of the APs: Are they in power level 1 or 8?

3. Talk to the people who are complaining. Look at their wireless clients. Can you replicate what the people are talking about?

4. Get the MAC address of some affected wireless clients and run a debug. Compare it with something that works.

I cannot begin to stress how important #1 is because this makes-or-break everything.

deepak george · ‎09-07-2018

Hi Leo,

Thanks, I've posted my update

Leo Laohoo · ‎09-08-2018

Is this client an Apple iPad?

deepak george · ‎09-08-2018

Windows machine

Brian McPhillips · ‎05-09-2019

Hi Deepak,

Did you get this issue resolved. I have a similar issue with 'timeoutEvt' Timer expired for station and for message = M2

deepak george · ‎05-10-2019

Hi Brian,

Sorry for the delay here.

We did a site survey again and added more AP's to our environment, since then users stopped complaining.

Cisco TAC was of no use here as each time they suggested some changes which did not resolve the issue.

Hope this helps.

Brian McPhillips · ‎05-20-2019

Thanks Deepak, disabling fast transition resolved my issue.

patoberli · ‎09-10-2018

I also suggest to not use 802.11ft, if you don't manage all the clients yourself (at least don't use the feature yet), wait one more year or two.

Regardless of your main issue, you have also a second small issue:

*DHCP Socket Task: Aug 31 10:45:55.747: [PA] 06:87:bc:6a:79:02 DHCP server id: 1.1.1.1 rcvd server id: 10.140.50.5

You should change the IP 1.1.1.1 to a private one, because that IP is now a Cloudflare DNS server and is publically routable!