- Cisco Community
- Technology and Support
- Wireless - Mobility
- Wireless
- Hi Viten;Unfortunatley that
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-12-2015 07:24 AM - edited 07-05-2021 02:15 AM
Hello;
I was tempted to raise a TAC case but thought I'd post here first, I've been experiencing this issue on and off for a few months but eventually managed to replicate and capture some logs today.
When a user roams between APs on the same WLC, they will very intermittently become stuck in a state of DHCP_REQ, this has only started happening after the deployment of 3700s.
The user does have an IP address but the WLC doesn't seem to recognize this and keeps them in a state of DHCP_REQ. The only way to come out of this loop is to reset the NIC or renew the IP address.
I am running of software release 7.6.130 and moved to this from 7.6.120 due to the bug.
Thanks;
John
Solved! Go to Solution.
- Labels:
-
Aironet Access Points
Accepted Solutions
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 06:40 PM
John, your issue is the 'DHCP required' flag on your WLAN advanced page. either you need to disable that or else you ll keep running into this issue. this particular client is not doing dhcp unfortunately during roaming.
it sends an orphan packet informing the WLC that it wants to use ip address 'x', but the WLC is expecting the client to do a full dhcp exchange (WLC needs to see a wlc ack back from dhcp server) to let the client go in RUN state but the client is not doing the dhcp exchange.
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP Discover 0, DHCP Request 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 Interface Group was NULL.Number of DHCP Discovery 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Jan 12 07:44:29.942: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 01:18 PM
Hi John,
the 2 APs between which the client is roaming between, are they in the same AP group?
can you paste output of this debug command
wlc debug
> debug client <mac address>
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 01:26 PM
Hi Viten;
Yes I am experiencing this issue at 2 sites, one of these sites doesn't have any AP groups and at the other the issue occurs without roaming but I am yet to capture the debugs at the site without roaming.
Here is the output - I have changed the IP to xx.xxx.xxx.xxx - This was a real address a 10.x address not a generic 169 - so the controller see's the client has an address.
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.917: 84:3a:4b:d1:80:14 Username entry (xxxxxxxxxx@xxxx.com) created for mobile, length = 253
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.917: 84:3a:4b:d1:80:14 Username entry (xxxxxxxxx4@xxxx.com) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Station 84:3a:4b:d1:80:14 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Stopping reauth timeout for 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Creating a PKC PMKID Cache entry for station 84:3a:4b:d1:80:14 (RSN 2)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Resetting MSCB PMK Cache Entry 0 for station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Adding BSSID f4:4e:05:15:91:8f to PMKID cache at index 0 for station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: New PMKID: (16)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: [0000] 61 1d 7d 81 c7 cf 06 82 e1 c5 63 c2 30 6f 27 e0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 PMK sent to mobility group
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAP-Success to mobile 84:3a:4b:d1:80:14 (EAP Id 11)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 EAPOL Header:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 00000000: 02 03 00 5f ..._
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Found an cache entry for BSSID f4:4e:05:15:91:8f in PMKID cache at index 0 of station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Found an cache entry for BSSID f4:4e:05:15:91:8f in PMKID cache at index 0 of station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: Including PMKID in M1 (16)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: [0000] 61 1d 7d 81 c7 cf 06 82 e1 c5 63 c2 30 6f 27 e0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Starting key exchange to mobile 84:3a:4b:d1:80:14, data packets will be dropped
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Reusing allocated memory for EAP Pkt for retransmission to mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Entering Backend Auth Success state (id=11) for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Received Auth Success while in Authenticating state for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.920: 84:3a:4b:d1:80:14 dot1x - moving mobile 84:3a:4b:d1:80:14 into Authenticated state
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Received EAPOL-Key from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Received EAPOL-key in PTK_START state (message 2) from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 PMK: Sending cache add
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Stopping retransmission timer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 EAPOL Header:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 00000000: 02 03 00 5f ..._
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 Reusing allocated memory for EAP Pkt for retransmission to mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Received EAPOL-Key from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Stopping retransmission timer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Freeing EAP Retransmit Bufer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 apfMs1xStateInc
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Central switch is TRUE
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP f4:4e:05:15:91:80 vapId 1 apVapId 1 flex-acl-name:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6178, Adding TMP rule
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP f4:4e:05:15:91:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255, IP
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 70, Local Bridging intf id = 12
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 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: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 5773, Adding TMP rule
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
type = Airespace AP - Learn IP address
on AP f4:4e:05:15:91:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255,
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 70, Local Bridging intf id = 12
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*pemReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 Sent an XID frame
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP Discover 0, DHCP Request 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 Interface Group was NULL.Number of DHCP Discovery 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Jan 12 07:44:29.942: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
*osapiBsnTimer: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 apfMsExpireCallback (apf_ms.c:626) Expiring Mobile!
*apfReceiveTask: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 apfMsExpireMobileStation (apf_ms.c:6655) Changing state for mobile 84:3a:4b:d1:80:14 on AP f4:4e:05:15:91:80 from Associated to Disassociated
*apfReceiveTask: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.917: 84:3a:4b:d1:80:14 Username entry (xxxxxjf@xxxx.com) created for mobile, length = 253
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.917: 84:3a:4b:d1:80:14 Username entry (xxxxxjf@xxxx.com) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting re-auth timeout to 0 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Station 84:3a:4b:d1:80:14 setting dot1x reauth timeout = 0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Stopping reauth timeout for 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Creating a PKC PMKID Cache entry for station 84:3a:4b:d1:80:14 (RSN 2)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Resetting MSCB PMK Cache Entry 0 for station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Adding BSSID f4:4e:05:15:91:8f to PMKID cache at index 0 for station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: New PMKID: (16)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: [0000] 61 1d 7d 81 c7 cf 06 82 e1 c5 63 c2 30 6f 27 e0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.918: 84:3a:4b:d1:80:14 PMK sent to mobility group
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAP-Success to mobile 84:3a:4b:d1:80:14 (EAP Id 11)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Freeing AAACB from Dot1xCB as AAA auth is done for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 EAPOL Header:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 00000000: 02 03 00 5f ..._
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Found an cache entry for BSSID f4:4e:05:15:91:8f in PMKID cache at index 0 of station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Found an cache entry for BSSID f4:4e:05:15:91:8f in PMKID cache at index 0 of station 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: Including PMKID in M1 (16)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: [0000] 61 1d 7d 81 c7 cf 06 82 e1 c5 63 c2 30 6f 27 e0
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Starting key exchange to mobile 84:3a:4b:d1:80:14, data packets will be dropped
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Reusing allocated memory for EAP Pkt for retransmission to mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Entering Backend Auth Success state (id=11) for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.919: 84:3a:4b:d1:80:14 Received Auth Success while in Authenticating state for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.920: 84:3a:4b:d1:80:14 dot1x - moving mobile 84:3a:4b:d1:80:14 into Authenticated state
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Received EAPOL-Key from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Received EAPOL-key in PTK_START state (message 2) from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 PMK: Sending cache add
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Stopping retransmission timer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 EAPOL Header:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 00000000: 02 03 00 5f ..._
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.942: 84:3a:4b:d1:80:14 Sending EAPOL-Key Message to mobile 84:3a:4b:d1:80:14
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 Reusing allocated memory for EAP Pkt for retransmission to mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsLwappLradNhMac = 00:00:0c:07:ac:02 mscb->apfMsLradSlotId = 1 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 13
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsBssid = f4:4e:05:15:91:80 mscb->apfMsAddress = 84:3a:4b:d1:80:14 mscb->apfMsApVapId = 1
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 2 mscb->apfMsLwappMwarInet.ipv4.addr = 181116868
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.943: 84:3a:4b:d1:80:14 mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 181116858 mscb->apfMsLwappLradPort = 11500
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Received EAPOL-Key from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.946: 84:3a:4b:d1:80:14 Stopping retransmission timer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Freeing EAP Retransmit Bufer for mobile 84:3a:4b:d1:80:14
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 apfMs1xStateInc
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Central switch is TRUE
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP f4:4e:05:15:91:80 vapId 1 apVapId 1 flex-acl-name:
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6178, Adding TMP rule
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP f4:4e:05:15:91:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255, IP
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 70, Local Bridging intf id = 12
*Dot1x_NW_MsgTask_4: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Jan 12 07:42:29.947: 84:3a:4b:d1:80:14 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:30.064: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 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: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 5773, Adding TMP rule
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
type = Airespace AP - Learn IP address
on AP f4:4e:05:15:91:80, slot 1, interface = 13, QOS = 2
IPv4 ACL ID = 255,
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 70, Local Bridging intf id = 12
*apfReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*pemReceiveTask: Jan 12 07:42:32.942: 84:3a:4b:d1:80:14 Sent an XID frame
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP Discover 0, DHCP Request 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 Interface Group was NULL.Number of DHCP Discovery 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Jan 12 07:44:29.942: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
*osapiBsnTimer: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 apfMsExpireCallback (apf_ms.c:626) Expiring Mobile!
*apfReceiveTask: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 apfMsExpireMobileStation (apf_ms.c:6655) Changing state for mobile 84:3a:4b:d1:80:14 on AP f4:4e:05:15:91:80 from Associated to Disassociated
*apfReceiveTask: Jan 12 07:44:39.941: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 01:39 PM
Is the WLC acting as the DHCP server? I hope not.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 01:40 PM
No, external DHCP server.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 02:26 PM
Good. Now what is the DHCP lease time?
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 06:40 PM
John, your issue is the 'DHCP required' flag on your WLAN advanced page. either you need to disable that or else you ll keep running into this issue. this particular client is not doing dhcp unfortunately during roaming.
it sends an orphan packet informing the WLC that it wants to use ip address 'x', but the WLC is expecting the client to do a full dhcp exchange (WLC needs to see a wlc ack back from dhcp server) to let the client go in RUN state but the client is not doing the dhcp exchange.
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Orphan Packet from STA - IP 1x.xxx.xxx.xxx
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 Invalid MSCB state, regType=2, Dhcp required!
*apfOrphanSocketTask: Jan 12 07:42:33.056: 84:3a:4b:d1:80:14 IPv4 Addr: xx:xxx:xxxx:xxx
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP Discover 0, DHCP Request 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 Interface Group was NULL.Number of DHCP Discovery 0 from client
*apfReceiveTask: Jan 12 07:44:29.941: 84:3a:4b:d1:80:14 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Jan 12 07:44:29.942: 84:3a:4b:d1:80:14 Scheduling deletion of Mobile Station: (callerId: 12) in 10 seconds
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-14-2015 11:16 PM
Hi Viten;
Thanks for the response - I suspected that this may be the cause and as a test/workaround I removed this setting from one of the sites that was experiencing it, I will monitor.
I am wondering why it seems to affect certain clients more than others, do you have any ideas? Apart from removing the DHCP_REQ command, is there anything on the client side I could look at to stop this?
Thanks;
John
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-15-2015 06:18 AM
Hi John,
it is completely dependent on the client. some client like mobile handheld devices tend to hold on to their ip addresses. disabling the dhcp required option is not a bad thing in such cases.
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-16-2015 07:53 AM
Hi Viten;
Unfortunatley that didn't resolve the issue and it still occurs albeit very intermittently.
I will try and run some more tests next week and post my findings.
Thanks;
John
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
01-16-2015 08:01 AM
sure do that. do send the debugs when the issue happens
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide
