DHCP Problem with Wireless Controller

fariasrod · ‎05-23-2012

Hello Guys,

see if you can help me out with this.

We are having an issue with our DHCP release in the WIRELESS CONTROLLER 5500. I have a interface called GUEST, and the dhcp scope from this interface is enable and have more then 300 address avaible to develop to the clients. But the clients , cant get IP ADDRESS, they associate with the access point, but dont get the ip address.

The internal DHCP is working fine.

Ps: I already tested this options that the WCS asked for:

Check whether the DHCP server is reachable.
Check whether dhcp server is configured to serve the wlan.
Check whether dhcp scope is exhausted.
Check whether multiple dhcp servers are configured with overlapping scopes.
Check local dhcp server is present if dhcp bridging mode enabled (move it to second) client is configured to get address from dhcp server.
Check if client has static ip configured and ensure client generates ip traffic * if ipsec wlan, ensure that client is configured to do dhcp exchanges in open(safenet/netscreen default config does not include it).

daviwatk · ‎05-23-2012

RODRIGO FARIAS wrote:

The internal DHCP is working fine.

So, since internal DHCP is working, I presume this issue involves wireless clients not able to get an IP address from an "external" DHCP server?

Can you perform a client debug on a problem client from the WLC CLI?

>debug client

Do you see the WLC forwarding the DHCP DISCOVER (presuming the client is generating one), to the various relays (DHCP servers) defined on the applicable interface? Perhaps post the client debug of the client trying to connect/get an IP.

fariasrod · ‎05-23-2012

I did the debug client, but didnt told me so much....

i will show a little bit what he answered me...

Time :05/23/2012 15:23:22 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. siaddr: 192.168.111.94, giaddr: 10.169.64.2

Time :05/23/2012 15:23:22 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. requested ip: 192.168.1.3

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. transmitting DHCP REQUEST (3)

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. xid: 0xfe3973 (16660851), secs: 4, flags: 0

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. chaddr: a0:0b:ba:e1:a3:43

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. ciaddr: 0.0.0.0, yiaddr: 0.0.0.0

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. siaddr: 0.0.0.0, giaddr: 10.169.64.2

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. requested ip: 192.168.1.3

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. transmitting DHCP REQUEST (3)

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. xid: 0xfe3973 (16660851), secs: 4, flags: 0

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. chaddr: a0:0b:ba:e1:a3:43

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. ciaddr: 0.0.0.0, yiaddr: 0.0.0.0

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. siaddr: 192.168.111.94, giaddr: 10.169.64.2

Time :05/23/2012 15:23:26 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. requested ip: 192.168.1.3

Time :05/23/2012 15:23:36 BRT Severity :INFO Controller IP :192.168.111.94 Message :Controller association request message received.

Time :05/23/2012 15:23:36 BRT Severity :INFO Controller IP :192.168.111.94 Message :Association request received from a client has an invalid RSN IE.(One reason could be mismatch in WPA2 algorithm).

Time :05/23/2012 15:23:36 BRT Severity :INFO Controller IP :192.168.111.94 Message :Received reassociation request from client.

Time :05/23/2012 15:23:36 BRT Severity :INFO Controller IP :192.168.111.94 Message :The wlan to which client is connecting requires 802 1x authentication.

Time :05/23/2012 15:23:36 BRT Severity :INFO Controller IP :192.168.111.94 Message :Client moved to associated state successfully.

Time :05/23/2012 15:23:36 BRT Severity :ERROR Controller IP :192.168.111.94 Message :802.1x authentication message received, static dynamic wep supported.

Time :05/23/2012 15:23:37 BRT Severity :ERROR Controller IP :192.168.111.94 Message :EAPOL-key is retransmitted.

Time :05/23/2012 15:23:37 BRT Severity :INFO Controller IP :192.168.111.94 Message :802.1x authentication was completed successfully.

Time :05/23/2012 15:23:37 BRT Severity :INFO Controller IP :192.168.111.94 Message :Client Moved to DHCP Required State.

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :DHCP offer received,dhcp server set.

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. transmitting DHCP OFFER (2)

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. xid: 0x8b019a76 (2332138102), secs: 0, flags: 0

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. chaddr: a0:0b:ba:e1:a3:43

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. ciaddr: 0.0.0.0, yiaddr: 10.169.67.151

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. siaddr: 0.0.0.0, giaddr: 0.0.0.0

Time :05/23/2012 15:23:50 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. server id: 1.1.1.1 rcvd server id: 192.168.111.94

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. transmitting DHCP OFFER (2)

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. xid: 0x8b019a76 (2332138102), secs: 0, flags: 0

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. chaddr: a0:0b:ba:e1:a3:43

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. ciaddr: 0.0.0.0, yiaddr: 10.169.67.151

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. siaddr: 0.0.0.0, giaddr: 0.0.0.0

Time :05/23/2012 15:23:58 BRT Severity :INFO Controller IP :192.168.111.94 Message :Dhcp Information. server id: 1.1.1.1 rcvd server id: 192.168.111.94 - controller wifi (dhcp server)

Time :05/23/2012 15:24:01 BRT Severity :ERROR Controller IP :192.168.111.94 Message :De-authentication sent to client. slot 0 (claller apf_ms.c:4972)

Mike Clites · ‎09-18-2013

I am running 7.0.240 on WLC 5508.

I have a client trying to connect to an wlan with wpa2, AES & 802.1x auth key.

This client keeps attempting to connect but eventually fails.

I have some debug captured via putty if that helps.

Here is one of the lines I copied frm the WCS log analysis.

Association request received from a client has an invalid RSN IE.(One reason could be mismatch in WPA2 algorithm).

Anyone have ideas on what the issue is?

kcnajaf · ‎09-18-2013

Hi Mike,

Could you get the output of "show wlan where in wlan id is the problem ssid id?

Regards

Najaf

Mike Clites · ‎09-19-2013

Najaf,

here is the output of the "show wlan 7".

Also keep in mind that this wlan works at this location for other clients & at other locations around the continental USA (same primary controller for all, we use H-REAP for local vlan handoff).

Status........................................... Enabled
MAC Filtering.................................... Disabled
Broadcast SSID................................... Enabled
AAA Policy Override.............................. Disabled
Network Admission Control

Radius-NAC State............................... Disabled
SNMP-NAC State................................. Disabled
Quarantine VLAN................................ 0
Maximum number of Associated Clients............. 0
Number of Active Clients......................... 42
Exclusionlist.................................... Disabled
Session Timeout.................................. 28800 seconds
CHD per WLAN..................................... Enabled
Webauth DHCP exclusion........................... Disabled
Interface........................................ whq_58
Multicast Interface.............................. Not Configured
WLAN ACL......................................... unconfigured
DHCP Server...................................... Default
DHCP Address Assignment Required................. Enabled
Static IP client tunneling....................... Disabled
Quality of Service............................... Gold (video)
Scan Defer Priority.............................. 4,5,6
Scan Defer Time.................................. 100 milliseconds
WMM.............................................. Allowed
WMM UAPSD Compliant Client Support............... Disabled
Media Stream Multicast-direct.................... Disabled
CCX - AironetIe Support.......................... Disabled
CCX - Gratuitous ProbeResponse (GPR)............. Disabled
CCX - Diagnostics Channel Capability............. Disabled
Dot11-Phone Mode (7920).......................... Disabled
Wired Protocol................................... 802.1P (Tag=5)
IPv6 Support..................................... Disabled
Passive Client Feature........................... Disabled
Peer-to-Peer Blocking Action..................... Disabled
Radio Policy..................................... All
DTIM period for 802.11a radio.................... 2
DTIM period for 802.11b radio.................... 2
Radius Servers
   Authentication................................ 172.16.1.47 1812
   Authentication................................ 172.16.1.46 1812
   Accounting.................................... 172.16.1.47 1813
   Accounting.................................... 172.16.1.46 1813
   Dynamic Interface............................. Disabled
Local EAP Authentication......................... Disabled
Security

   802.11 Authentication:........................ Open System
   Static WEP Keys............................... Disabled
   802.1X........................................ Disabled
   Wi-Fi Protected Access (WPA/WPA2)............. Enabled
      WPA (SSN IE)............................... Disabled
      WPA2 (RSN IE).............................. Enabled
         TKIP Cipher............................. Disabled
         AES Cipher.............................. Enabled
                                                               Auth Key Management
         802.1x.................................. Enabled
         PSK..................................... Disabled
         CCKM.................................... Disabled
         FT(802.11r)............................. Disabled
         FT-PSK(802.11r)......................... Disabled
FT Reassociation Timeout......................... 20
FT Over-The-Air mode............................. Enabled
FT Over-The-Ds mode.............................. Enabled
CCKM tsf Tolerance............................... 1000
   CKIP ......................................... Disabled
   Web Based Authentication...................... Disabled
   Web-Passthrough............................... Disabled
   Conditional Web Redirect...................... Disabled
   Splash-Page Web Redirect...................... Disabled
   Auto Anchor................................... Disabled
   H-REAP Local Switching........................ Enabled
   H-REAP Local Authentication................... Disabled
   H-REAP Learn IP Address....................... Enabled
   Client MFP.................................... Optional
   Tkip MIC Countermeasure Hold-down Timer....... 60
Call Snooping.................................... Disabled
Roamed Call Re-Anchor Policy..................... Disabled
SIP CAC Fail Send-486-Busy Policy................ Enabled
SIP CAC Fail Send Dis-Association Policy......... Disabled
Band Select...................................... Disabled
Load Balancing................................... Disabled

Mobility Anchor List
WLAN ID IP Address Status
------- --------------- ------

maldehne · ‎09-18-2013

Please check the following:

check if the gateway address confifured on the interface matching the ip address of the default router in the dhcp pool configured for the dynamin interface vlan.

Make sure that DHCP proxy is enabled and the primary dhcp server from which the clients should get ip address is defined in the dynamic interface config on the controller.

the debugs are saying that the server is sending the offer but the client is not sending the DHCP request to acquire the ip in the offer.

attach the debug client < >

debug dhcp message

show dhcp proxy

show interface detailed < the name of the interface mapped to the wlan profile >

show wlan < >

share the pool config for this particular vlan on the dhcp server

-----------------------------------------------------------------------------

Please make sure to rate correct answers

Mike Clites · ‎09-19-2013

(Cisco Controller) >show dhcp proxy

DHCP Proxy Behaviour: disabled
Bootp-Broadcast:disabled

-------------------------------------------------------------------------

show wlan 7

Status........................................... Enabled
MAC Filtering.................................... Disabled
Broadcast SSID................................... Enabled
AAA Policy Override.............................. Disabled
Network Admission Control

Radius-NAC State............................... Disabled
SNMP-NAC State................................. Disabled
Quarantine VLAN................................ 0
Maximum number of Associated Clients............. 0
Number of Active Clients......................... 44
Exclusionlist.................................... Disabled
Session Timeout.................................. 28800 seconds
CHD per WLAN..................................... Enabled
Webauth DHCP exclusion........................... Disabled
Interface........................................ whq_58
Multicast Interface.............................. Not Configured
WLAN ACL......................................... unconfigured
DHCP Server...................................... Default
DHCP Address Assignment Required................. Enabled
Static IP client tunneling....................... Disabled
Quality of Service............................... Gold (video)
Scan Defer Priority.............................. 4,5,6
Scan Defer Time.................................. 100 milliseconds
WMM.............................................. Allowed
WMM UAPSD Compliant Client Support............... Disabled
Media Stream Multicast-direct.................... Disabled
CCX - AironetIe Support.......................... Disabled
CCX - Gratuitous ProbeResponse (GPR)............. Disabled
CCX - Diagnostics Channel Capability............. Disabled
Dot11-Phone Mode (7920).......................... Disabled
Wired Protocol................................... 802.1P (Tag=5)
IPv6 Support..................................... Disabled
Passive Client Feature........................... Disabled
Peer-to-Peer Blocking Action..................... Disabled
Radio Policy..................................... All
DTIM period for 802.11a radio.................... 2
DTIM period for 802.11b radio.................... 2
Radius Servers
   Authentication................................ 172.16.1.47 1812
   Authentication................................ 172.16.1.46 1812
   Accounting.................................... 172.16.1.47 1813
   Accounting.................................... 172.16.1.46 1813
   Dynamic Interface............................. Disabled
Local EAP Authentication......................... Disabled
Security

   802.11 Authentication:........................ Open System
   Static WEP Keys............................... Disabled
   802.1X........................................ Disabled
   Wi-Fi Protected Access (WPA/WPA2)............. Enabled
      WPA (SSN IE)............................... Disabled
      WPA2 (RSN IE).............................. Enabled
         TKIP Cipher............................. Disabled
         AES Cipher.............................. Enabled
                                                               Auth Key Management
         802.1x.................................. Enabled
         PSK..................................... Disabled
         CCKM.................................... Disabled
         FT(802.11r)............................. Disabled
         FT-PSK(802.11r)......................... Disabled
FT Reassociation Timeout......................... 20
FT Over-The-Air mode............................. Enabled
FT Over-The-Ds mode.............................. Enabled
CCKM tsf Tolerance............................... 1000
   CKIP ......................................... Disabled
   Web Based Authentication...................... Disabled
   Web-Passthrough............................... Disabled
   Conditional Web Redirect...................... Disabled
   Splash-Page Web Redirect...................... Disabled
   Auto Anchor................................... Disabled
   H-REAP Local Switching........................ Enabled
   H-REAP Local Authentication................... Disabled
   H-REAP Learn IP Address....................... Enabled
   Client MFP.................................... Optional
   Tkip MIC Countermeasure Hold-down Timer....... 60
Call Snooping.................................... Disabled
Roamed Call Re-Anchor Policy..................... Disabled
SIP CAC Fail Send-486-Busy Policy................ Enabled
SIP CAC Fail Send Dis-Association Policy......... Disabled
Band Select...................................... Disabled
Load Balancing................................... Disabled

Mobility Anchor List
WLAN ID IP Address Status
------- --------------- ------

--------------------------------------------------------------------------------------------------

DHCP server is windows server 2003. Standard config (corperate wide config on servers) no special flags on the pool. server is on same vlan as client @ the same location.

-----------------------------------------------------------------------------------------------------

I also have a tac case open for this & the engineer is seeing the same issue; the client is NOT sending a dhcp request. The tacacs portion is fine. He is suggesting taking off the "dhcp required" security feature on the ssid. I am hesitant because we specifically require dhcp for security reasons. That will allow the client to work but it wont explain where the issue lay. Again, we have the vast majority of our clients connecting fine. I believe this to be isolated to the client/drivers/configuration but have not been able to have a desk-side guy check into the client.

--------------------------------------------------------------------------------------------------------------------------------------------------

debug client 08:11:96:22:78:b0

(Cisco Controller) >*spamApTask6: Sep 18 14:26:12.435: 08:11:96:22:78:b0 Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:26:cb:aa:81:20, slot 0. STA connecting AP: 20:37:06:7c:0d:f0, slot 1
*apfReceiveTask: Sep 18 14:29:55.892: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP request 0 from client
*apfReceiveTask: Sep 18 14:29:55.892: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Sep 18 14:29:55.892: 08:11:96:22:78:b0 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 apfMsDeleteByMscb Scheduling mobile for deletion with deleteReason 4, reasonCode 4

*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 Scheduling deletion of Mobile Station: (callerId: 30) in 1 seconds
*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 CCKM: Sending cache delete
*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 PMK: Sending cache delete
*spamApTask6: Sep 18 14:29:58.869: 08:11:96:22:78:b0 Removing PMK cache entry for station 08:11:96:22:78:b0
*osapiBsnTimer: Sep 18 14:29:59.691: 08:11:96:22:78:b0 apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!
*apfReceiveTask: Sep 18 14:29:59.692: 08:11:96:22:78:b0 apfMsExpireMobileStation (apf_ms.c:5021) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Associated to Disassociated

*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 Sent Deauthenticate to mobile on BSSID 00:26:cb:aa:81:20 slot 0(caller apf_ms.c:5113)
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 apfMsAssoStateDec
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 apfMsExpireMobileStation (apf_ms.c:5151) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Disassociated to Idle

*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Deleted mobile LWAPP rule on AP [00:26:cb:aa:81:20]
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 Username entry deleted for mobile
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 apfMs1xStateDec
*apfReceiveTask: Sep 18 14:29:59.694: 08:11:96:22:78:b0 Deleting mobile on AP 00:26:cb:aa:81:20(0)
*pemReceiveTask: Sep 18 14:29:59.695: 08:11:96:22:78:b0 0.0.0.0 Removed NPU entry.
*spamApTask6: Sep 18 14:29:59.898: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Adding mobile on LWAPP AP 00:26:cb:aa:81:20(0)
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Association received from mobile on AP 00:26:cb:aa:81:20
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 0.0.0.0 START (0) Changing ACL 'Pre-Auth-for-External-Web-Server' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Applying site-specific IPv6 override for station 08:11:96:22:78:b0 - vapId 7, site '1441_NY', interface 'management'
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Applying IPv6 Interface Policy for station 08:11:96:22:78:b0 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Applying site-specific override for station 08:11:96:22:78:b0 - vapId 7, site '1441_NY', interface 'management'
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 STA - rates (8): 2 4 11 22 12 18 152 36 0 0 0 0 0 0 0 0
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 STA - rates (12): 2 4 11 22 12 18 152 36 48 72 96 108 0 0 0 0
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Processing RSN IE type 48, length 38 for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.033: 08:11:96:22:78:b0 Received RSN IE with 1 PMKIDs from mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.033: Received PMKID: (16)

*apfMsConnTask_6: Sep 18 14:30:00.034: [0000] f2 1f d6 8c c0 f5 c7 94 77 87 45 cf f6 5f d1 56

*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Searching for PMKID in MSCB PMKID cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 No valid PMKID found in the MSCB PMKID cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Trying to compute a PMKID from MSCB PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: CCKM: Find PMK in cache: BSSID = (6)

*apfMsConnTask_6: Sep 18 14:30:00.034: [0000] 00 26 cb aa 81 20

*apfMsConnTask_6: Sep 18 14:30:00.034: CCKM: Find PMK in cache: realAA = (6)

*apfMsConnTask_6: Sep 18 14:30:00.034: [0000] 00 26 cb aa 81 24

*apfMsConnTask_6: Sep 18 14:30:00.034: CCKM: Find PMK in cache: PMKID = (16)

*apfMsConnTask_6: Sep 18 14:30:00.034: [0000] f2 1f d6 8c c0 f5 c7 94 77 87 45 cf f6 5f d1 56

*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Unable to compute a valid PMKID from MSCB PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Searching for PMK in global PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Unable to compute a valid PMKID from global PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)

*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:26:cb:aa:81:20 vapId 7 apVapId 5for this client
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:26:cb:aa:81:20 vapId 7 apVapId 5
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 apfMsAssoStateInc
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Idle to Associated

*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 Sending Assoc Response to station on BSSID 00:26:cb:aa:81:20 (status 0) ApVapId 5 Slot 0
*apfMsConnTask_6: Sep 18 14:30:00.034: 08:11:96:22:78:b0 apfProcessAssocReq (apf_80211.c:5276) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Associated to Associated

*apfMsConnTask_6: Sep 18 14:30:00.066: 08:11:96:22:78:b0 Updating AID for REAP AP Client 00:26:cb:aa:81:20 - AID ===> 6
*dot1xMsgTask: Sep 18 14:30:00.068: 08:11:96:22:78:b0 Station 08:11:96:22:78:b0 setting dot1x reauth timeout = 28800
*dot1xMsgTask: Sep 18 14:30:00.068: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Connecting state
*dot1xMsgTask: Sep 18 14:30:00.068: 08:11:96:22:78:b0 Sending EAP-Request/Identity to mobile 08:11:96:22:78:b0 (EAP Id 1)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.104: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.104: 08:11:96:22:78:b0 Received Identity Response (count=1) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.104: 08:11:96:22:78:b0 EAP State update from Connecting to Authenticating for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.104: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Authenticating state
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.104: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.113: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.113: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=2) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.113: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 2)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.142: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.142: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 2, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.142: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.144: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.144: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=3) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.145: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 3)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.179: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.179: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 3, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.179: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.186: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.186: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=6) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.186: 08:11:96:22:78:b0 WARNING: updated EAP-Identifier 3 ===> 6 for STA 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.186: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 6)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.220: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.220: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 6, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.220: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Processing Access-Accept for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Resetting web acl from 255 to 255

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Setting re-auth timeout to 28800 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Station 08:11:96:22:78:b0 setting dot1x reauth timeout = 28800
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Username entry (host/DS7M4R1.kwd.ad.kellwood.com) created for mobile, length = 253
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.225: 08:11:96:22:78:b0 Username entry (host/DS7M4R1.kwd.ad.kellwood.com) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Creating a PKC PMKID Cache entry for station 08:11:96:22:78:b0 (RSN 2)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Adding BSSID 00:26:cb:aa:81:24 to PMKID cache for station 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: [0000] af c8 54 cf 2f 16 ca 2e cb 36 0b 86 59 ac 8f 62

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 PMK sent to mobility group
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Sending EAP-Success to mobile 08:11:96:22:78:b0 (EAP Id 6)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: [0000] af c8 54 cf 2f 16 ca 2e cb 36 0b 86 59 ac 8f 62

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Starting key exchange to mobile 08:11:96:22:78:b0, data packets will be dropped
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Sending EAPOL-Key Message to mobile 08:11:96:22:78:b0
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Entering Backend Auth Success state (id=6) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.227: 08:11:96:22:78:b0 Received Auth Success while in Authenticating state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.228: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Authenticated state
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.265: 08:11:96:22:78:b0 Received EAPOL-Key from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.265: 08:11:96:22:78:b0 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.265: 08:11:96:22:78:b0 Received EAPOL-key in PTK_START state (message 2) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.266: 08:11:96:22:78:b0 PMK: Sending cache add
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.266: 08:11:96:22:78:b0 Stopping retransmission timer for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.266: 08:11:96:22:78:b0 Sending EAPOL-Key Message to mobile 08:11:96:22:78:b0
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.297: 08:11:96:22:78:b0 Received EAPOL-Key from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.297: 08:11:96:22:78:b0 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.297: 08:11:96:22:78:b0 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.297: 08:11:96:22:78:b0 apfMs1xStateInc
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) DHCP Not required on AP 00:26:cb:aa:81:20 vapId 7 apVapId 5for this client
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:26:cb:aa:81:20 vapId 7 apVapId 5
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state DHCP_REQD (7)

*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4838, Adding TMP rule
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP 00:26:cb:aa:81:20, slot 0, interface = 1, QOS = 1
ACL Id = 255, Jumbo Fr
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 5, DSCP = 0, TokenID = 7006 IPv6 Vlan = 0, IPv6 intf id = 0
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)
*Dot1x_NW_MsgTask_0: Sep 18 14:30:00.298: 08:11:96:22:78:b0 Stopping retransmission timer for mobile 08:11:96:22:78:b0
*pemReceiveTask: Sep 18 14:30:00.299: 08:11:96:22:78:b0 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*apfReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED
*apfReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4499, Adding TMP rule
*apfReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
type = Airespace AP - Learn IP address
on AP 00:26:cb:aa:81:20, slot 0, interface = 1, QOS = 1
ACL Id = 255, Jumbo
*apfReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 5, DSCP = 0, TokenID = 7006 IPv6 Vlan = 0, IPv6 intf id = 0
*apfReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)
*pemReceiveTask: Sep 18 14:30:03.292: 08:11:96:22:78:b0 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*apfReceiveTask: Sep 18 14:32:00.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP request 0 from client
*apfReceiveTask: Sep 18 14:32:00.292: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Sep 18 14:32:00.292: 08:11:96:22:78:b0 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
*spamApTask6: Sep 18 14:32:03.409: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*spamApTask6: Sep 18 14:32:03.409: 08:11:96:22:78:b0 apfMsDeleteByMscb Scheduling mobile for deletion with deleteReason 4, reasonCode 4

*spamApTask6: Sep 18 14:32:03.409: 08:11:96:22:78:b0 Scheduling deletion of Mobile Station: (callerId: 30) in 1 seconds
*spamApTask6: Sep 18 14:32:03.409: 08:11:96:22:78:b0 CCKM: Sending cache delete
*spamApTask6: Sep 18 14:32:03.410: 08:11:96:22:78:b0 PMK: Sending cache delete
*spamApTask6: Sep 18 14:32:03.410: 08:11:96:22:78:b0 Removing PMK cache entry for station 08:11:96:22:78:b0
*osapiBsnTimer: Sep 18 14:32:04.291: 08:11:96:22:78:b0 apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!
*apfReceiveTask: Sep 18 14:32:04.292: 08:11:96:22:78:b0 apfMsExpireMobileStation (apf_ms.c:5021) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Associated to Disassociated

*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 Sent Deauthenticate to mobile on BSSID 00:26:cb:aa:81:20 slot 0(caller apf_ms.c:5113)
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 apfMsAssoStateDec
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 apfMsExpireMobileStation (apf_ms.c:5151) Changing state for mobile 08:11:96:22:78:b0 on AP 00:26:cb:aa:81:20 from Disassociated to Idle

*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Deleted mobile LWAPP rule on AP [00:26:cb:aa:81:20]
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 Username entry deleted for mobile
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 apfMs1xStateDec
*apfReceiveTask: Sep 18 14:32:04.294: 08:11:96:22:78:b0 Deleting mobile on AP 00:26:cb:aa:81:20(0)
*pemReceiveTask: Sep 18 14:32:04.295: 08:11:96:22:78:b0 0.0.0.0 Removed NPU entry.
*spamApTask6: Sep 18 14:32:04.437: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.569: 08:11:96:22:78:b0 Adding mobile on LWAPP AP 20:37:06:7c:0d:f0(1)
*apfMsConnTask_0: Sep 18 14:32:04.569: 08:11:96:22:78:b0 Association received from mobile on AP 20:37:06:7c:0d:f0
*apfMsConnTask_0: Sep 18 14:32:04.569: 08:11:96:22:78:b0 0.0.0.0 START (0) Changing ACL 'Pre-Auth-for-External-Web-Server' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Applying site-specific IPv6 override for station 08:11:96:22:78:b0 - vapId 7, site '1441_NY', interface 'management'
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Applying IPv6 Interface Policy for station 08:11:96:22:78:b0 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Applying site-specific override for station 08:11:96:22:78:b0 - vapId 7, site '1441_NY', interface 'management'
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 STA - rates (6): 152 36 176 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Processing RSN IE type 48, length 38 for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Received RSN IE with 1 PMKIDs from mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: Received PMKID: (16)

*apfMsConnTask_0: Sep 18 14:32:04.570: [0000] 04 5f c4 aa 88 39 bb ad 70 80 d1 a4 93 33 fc 54

*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Searching for PMKID in MSCB PMKID cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 No valid PMKID found in the MSCB PMKID cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Trying to compute a PMKID from MSCB PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: CCKM: Find PMK in cache: BSSID = (6)

*apfMsConnTask_0: Sep 18 14:32:04.570: [0000] 20 37 06 7c 0d f0

*apfMsConnTask_0: Sep 18 14:32:04.570: CCKM: Find PMK in cache: realAA = (6)

*apfMsConnTask_0: Sep 18 14:32:04.570: [0000] 20 37 06 7c 0d fb

*apfMsConnTask_0: Sep 18 14:32:04.570: CCKM: Find PMK in cache: PMKID = (16)

*apfMsConnTask_0: Sep 18 14:32:04.570: [0000] 04 5f c4 aa 88 39 bb ad 70 80 d1 a4 93 33 fc 54

*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Unable to compute a valid PMKID from MSCB PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Searching for PMK in global PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Unable to compute a valid PMKID from global PMK cache for mobile 08:11:96:22:78:b0
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)

*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 20:37:06:7c:0d:f0 vapId 7 apVapId 5for this client
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 20:37:06:7c:0d:f0 vapId 7 apVapId 5
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 apfMsAssoStateInc
*apfMsConnTask_0: Sep 18 14:32:04.570: 08:11:96:22:78:b0 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 08:11:96:22:78:b0 on AP 20:37:06:7c:0d:f0 from Idle to Associated

*apfMsConnTask_0: Sep 18 14:32:04.571: 08:11:96:22:78:b0 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_0: Sep 18 14:32:04.571: 08:11:96:22:78:b0 Sending Assoc Response to station on BSSID 20:37:06:7c:0d:f0 (status 0) ApVapId 5 Slot 1
*apfMsConnTask_0: Sep 18 14:32:04.571: 08:11:96:22:78:b0 apfProcessAssocReq (apf_80211.c:5276) Changing state for mobile 08:11:96:22:78:b0 on AP 20:37:06:7c:0d:f0 from Associated to Associated

*apfMsConnTask_0: Sep 18 14:32:04.596: 08:11:96:22:78:b0 Updating AID for REAP AP Client 20:37:06:7c:0d:f0 - AID ===> 2
*dot1xMsgTask: Sep 18 14:32:04.598: 08:11:96:22:78:b0 Station 08:11:96:22:78:b0 setting dot1x reauth timeout = 28800
*dot1xMsgTask: Sep 18 14:32:04.598: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Connecting state
*dot1xMsgTask: Sep 18 14:32:04.598: 08:11:96:22:78:b0 Sending EAP-Request/Identity to mobile 08:11:96:22:78:b0 (EAP Id 1)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.627: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.627: 08:11:96:22:78:b0 Received Identity Response (count=1) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.627: 08:11:96:22:78:b0 EAP State update from Connecting to Authenticating for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.627: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Authenticating state
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.627: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.644: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.644: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=2) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.644: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 2)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.672: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.672: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 2, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.672: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.674: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.674: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=3) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.674: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 3)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.705: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.705: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 3, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.705: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.708: 08:11:96:22:78:b0 Processing Access-Challenge for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.708: 08:11:96:22:78:b0 Entering Backend Auth Req state (id=6) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.708: 08:11:96:22:78:b0 WARNING: updated EAP-Identifier 3 ===> 6 for STA 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.708: 08:11:96:22:78:b0 Sending EAP Request from AAA to mobile 08:11:96:22:78:b0 (EAP Id 6)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.743: 08:11:96:22:78:b0 Received EAPOL EAPPKT from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.743: 08:11:96:22:78:b0 Received EAP Response from mobile 08:11:96:22:78:b0 (EAP Id 6, EAP Type 25)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.743: 08:11:96:22:78:b0 Entering Backend Auth Response state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Processing Access-Accept for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Resetting web acl from 255 to 255

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Setting re-auth timeout to 28800 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Station 08:11:96:22:78:b0 setting dot1x reauth timeout = 28800
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Username entry (host/DS7M4R1.kwd.ad.kellwood.com) created for mobile, length = 253
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.745: 08:11:96:22:78:b0 Username entry (host/DS7M4R1.kwd.ad.kellwood.com) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: 08:11:96:22:78:b0 Creating a PKC PMKID Cache entry for station 08:11:96:22:78:b0 (RSN 2)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: 08:11:96:22:78:b0 Adding BSSID 20:37:06:7c:0d:fb to PMKID cache for station 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: [0000] f6 95 c1 bf c3 18 01 9a 82 3d 87 99 d6 5c b6 57

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: 08:11:96:22:78:b0 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: 08:11:96:22:78:b0 PMK sent to mobility group
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.747: 08:11:96:22:78:b0 Sending EAP-Success to mobile 08:11:96:22:78:b0 (EAP Id 6)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: [0000] f6 95 c1 bf c3 18 01 9a 82 3d 87 99 d6 5c b6 57

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: 08:11:96:22:78:b0 Starting key exchange to mobile 08:11:96:22:78:b0, data packets will be dropped
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: 08:11:96:22:78:b0 Sending EAPOL-Key Message to mobile 08:11:96:22:78:b0
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: 08:11:96:22:78:b0 Entering Backend Auth Success state (id=6) for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: 08:11:96:22:78:b0 Received Auth Success while in Authenticating state for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.748: 08:11:96:22:78:b0 dot1x - moving mobile 08:11:96:22:78:b0 into Authenticated state
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 Received EAPOL-Key from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 Received EAPOL-key in PTK_START state (message 2) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 PMK: Sending cache add
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 Stopping retransmission timer for mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.782: 08:11:96:22:78:b0 Sending EAPOL-Key Message to mobile 08:11:96:22:78:b0
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 Received EAPOL-Key from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 08:11:96:22:78:b0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 apfMs1xStateInc
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) DHCP Not required on AP 20:37:06:7c:0d:f0 vapId 7 apVapId 5for this client
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 20:37:06:7c:0d:f0 vapId 7 apVapId 5
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state DHCP_REQD (7)

*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4838, Adding TMP rule
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP 20:37:06:7c:0d:f0, slot 1, interface = 1, QOS = 1
ACL Id = 255, Jumbo Fr
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 5, DSCP = 0, TokenID = 7006 IPv6 Vlan = 0, IPv6 intf id = 0
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)
*Dot1x_NW_MsgTask_0: Sep 18 14:32:04.811: 08:11:96:22:78:b0 Stopping retransmission timer for mobile 08:11:96:22:78:b0
*pemReceiveTask: Sep 18 14:32:04.812: 08:11:96:22:78:b0 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*spamApTask6: Sep 18 14:32:05.467: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*spamApTask6: Sep 18 14:32:05.468: 08:11:96:22:78:b0 Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:26:cb:aa:81:20, slot 0. STA connecting AP: 20:37:06:7c:0d:f0, slot 1
*spamApTask6: Sep 18 14:32:06.496: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*spamApTask6: Sep 18 14:32:06.496: 08:11:96:22:78:b0 Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:26:cb:aa:81:20, slot 0. STA connecting AP: 20:37:06:7c:0d:f0, slot 1
*spamApTask6: Sep 18 14:32:07.525: 08:11:96:22:78:b0 Received Idle-Timeout from AP 00:26:cb:aa:81:20, slot 0 for STA 08:11:96:22:78:b0
*spamApTask6: Sep 18 14:32:07.525: 08:11:96:22:78:b0 Warning, ignore the DELETE_MOBILE_PAYLOAD from AP: 00:26:cb:aa:81:20, slot 0. STA connecting AP: 20:37:06:7c:0d:f0, slot 1
*apfReceiveTask: Sep 18 14:32:07.692: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED
*apfReceiveTask: Sep 18 14:32:07.692: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4499, Adding TMP rule
*apfReceiveTask: Sep 18 14:32:07.692: 08:11:96:22:78:b0 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
type = Airespace AP - Learn IP address
on AP 20:37:06:7c:0d:f0, slot 1, interface = 1, QOS = 1
ACL Id = 255, Jumbo

maldehne · ‎09-19-2013

the client is connecting on a locally switched WLAN on HREAP AP.

to which valn have you mapped the WLAN on the HREAP AP?

can you send me show run int < interface to which the AP is connected>

You should make sure that the HREAP AP is connected to trunk port and the vlan mapped to the WLAN on that AP is allowed on the trunk port. You should also make sure that the DHCP server is accessbile from the AP on the remote site.

Mike Clites · ‎09-19-2013

Yes the client is connecting on a locally switched WLAN via H-REAP. vlan 96

The switch port is trunked. Native to the vlan of the ssid in question.

The local server(dhcp) is also natively on the same vlan & yes is accessable from the AP. (i have verified via ping).

For us, this type of H-REAP configuration is very common in our environment.

interface FastEthernet0/34

switchport trunk encapsulation dot1q

switchport trunk native vlan 96

switchport mode trunk

switchport voice vlan 196

srr-queue bandwidth shape 10 0 0 0

mls qos trust device cisco-phone

mls qos trust cos

spanning-tree portfast

end

maldehne · ‎09-19-2013

If it is on the same subnet , and still the client is not getting ip address, i would capture traces and see exactly what is happenning.

Mike Clites · ‎09-19-2013

That is a bit of an issue since it is a remote (1/2 way across the country for me) location and the issue appears limited to 1 client.

The client debugs, it appears the client is NOT sending out dhcp requests. Thats how i am reading it at least.

I beleive I am going to have to have a desk-side guy make time to locate the client, check the devices wireless configuration out & possibly delete/re-establish it.