Excluded client problem - "Attempted to use IP Address assigned to another device" / "Identity Theft"

[Thomas Obbekaer Thomsen]

Hi all

Problem:

Client gets excluded caused by "Identity Theft" (when looking in the controller) and "Attempted to use IP Address assigned to another device" (when looking in the WCS).

Setup:

Centrally placed WLAN Controller - The SSID and AP is in H-REAP mode, and the DHCP server locally is a ASA5505.

Client:

Samsung Galaxy Tap 10.1

Other clients on the same site do not apeer to have this problem.

The problem is peoridic.

Other info:

We have recently upgraded to 7.0.230 because the same type of client would get excluded with reason "unknown", and not be removed from the exclusion list - this apears to have been a bug in the WLC software.

Now we have the reason, and the client will get removed from the exlusion list after the default 60 seconds, but then get excluded again.

When doing a troupleshoot client from the WCS the following shows up:

04/16/2012 12:10:32 CEST INFO 10.1.33.13 DHCP offer received,dhcp server set. 

04/16/2012 12:10:32 CEST ERROR 10.1.33.13 Received DHCP ACK, could not update client state. 

04/16/2012 12:10:32 CEST INFO 10.1.33.13 Received DHCP request, error processing packet.

04/16/2012 12:10:42 CEST ERROR 10.1.33.13 De-authentication sent to client. slot 0 (claller apf_ms.c:5113)

The question right now is:

The "could not update client state" - is this the WLC not being able to update the client or is it the DHCP server ?

[Stephen Rodriguez]

That is the WLC not being able to update the MSCB entry for the client.

Steve

Sent from Cisco Technical Support iPhone App

[Thomas Obbekaer Thomsen]

Stephen:

Thank you for your reply.

I'll just go debug the client "for real" and see what actually happens.

I suspect that i might be the ASA firewall that does something "wrong", but it is just a suspicion.

.

[Amjad Abdullah]

Thomas:

Can different clients on different sites be given same IP address at same moment? can this happen?

If yes try to manage this and make sure IP subnets are independent and have no intersection for all sites.

If no, give it a try to change the DHCP server for one or more locations as a test. Usually if the firewall is the DHCP then the DHCP process will not be done correctly if the DHCP proxy is enabled on the WLC. If your DHCP is a firewall you need probably to disable DHCP proxy on your DHCP and, if your DHCP server is on a different subnet, need to fix ip helper address in your internal wired network.

HTH

Amjad

[Thomas Obbekaer Thomsen]

Amajad:

This could happen before we updated. But because I checked the with the "bug tool kit", I changed every site to use different subnets.

I thought that DHCP proxy was only a problem with Centralised trafic not H-REAP trafic.

The DHCP server (it is a ASA5505) is on the same subnet as the client (it is the default gateway for the subnet / vlan).

[Amjad Abdullah]

Thomas:

Do you have local switching? or centralized switching for your remote site APs?

if you use local switching then and DHCP on same vlan as clients then no need to reach WLC and hence you can use firewall as a DHCP.

The problem with putting DHCP server as firewall is when you have DHCP proxy enabled the WLC sends DHCP request for clients with its own IP address and the firewall ignores that when it seems the requester (the client) does not have the same information as the sender (WLC).

If I were in your shoes I'll try to test another DHCP and/or disable DHCP proxy (if it is enabled) just to eliminate possibilities.

Good luck.

Amjad

[Thomas Obbekaer Thomsen]

As i tried to explain before, we have local switching at the remote site, not centralized for this SSID.

And the DHCP server is on the same local VLAN.

It works fine, but all of a sudden a client will get "stuck" in this error.

If anyone wants to look, I have this debug output from the WLC.

The debug starts from right after I have removed the client from the exclusion list.

I can see in the ASA that the clients lease time in the DHCP server will get renewed duing this process to the default 3600 seconds.

The clients MAC is :8c:77:12:ac:8c:3b

The ASA inside interface is: 192.168.2.1 /24

Any suggestions will be greatly appreciated.

(WiSM-slot2-1) >*emWeb: Apr 17 10:09:31.613: 8c:77:12:ac:8c:3b apfMsDeleteByMscb Scheduling mobile for deletion with deleteReason 6, reasonCode 1

*emWeb: Apr 17 10:09:31.613: 8c:77:12:ac:8c:3b Scheduling deletion of Mobile Station:  (callerId: 30) in 1 seconds

*osapiBsnTimer: Apr 17 10:09:32.612: 8c:77:12:ac:8c:3b apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!

*apfReceiveTask: Apr 17 10:09:32.622: 8c:77:12:ac:8c:3b apfMsAssoStateDec

*apfReceiveTask: Apr 17 10:09:32.622: 8c:77:12:ac:8c:3b apfMs1xStateDec

*apfReceiveTask: Apr 17 10:09:32.622: 8c:77:12:ac:8c:3b Deleting mobile on AP 00:1d:a2:87:02:30(0)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Adding mobile on LWAPP AP 00:1d:a2:87:02:30(0)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Association received from mobile on AP 00:1d:a2:87:02:30

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Applying site-specific IPv6 override for station 8c:77:12:ac:8c:3b - vapId 3, site 'PDA-GST-KNS-MED-ITV', interface 'dummy-itv-105'

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Applying IPv6 Interface Policy for station 8c:77:12:ac:8c:3b - vlan 199, interface id 13, interface 'dummy-itv-105'

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Applying site-specific override for station 8c:77:12:ac:8c:3b - vapId 3, site 'PDA-GST-KNS-MED-ITV', interface 'dummy-itv-105'

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 START (0) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b STA - rates (8): 130 132 139 150 36 48 72 108 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b STA - rates (12): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Processing RSN IE type 48, length 20 for mobile 8c:77:12:ac:8c:3b

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 START (0) Initializing policy

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:1d:a2:87:02:30 vapId 3 apVapId 3for this client

*apfMsConnTask_0: Apr 17 10:09:36.655: 8c:77:12:ac:8c:3b Not Using WMM Compliance code qosCap 00

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1d:a2:87:02:30 vapId 3 apVapId 3

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b apfMsAssoStateInc

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 8c:77:12:ac:8c:3b on AP 00:1d:a2:87:02:30 from Idle to Associated

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b Sending Assoc Response to station on BSSID 00:1d:a2:87:02:30 (status 0) ApVapId 3 Slot 0

*apfMsConnTask_0: Apr 17 10:09:36.656: 8c:77:12:ac:8c:3b apfProcessAssocReq (apf_80211.c:5272) Changing state for mobile 8c:77:12:ac:8c:3b on AP 00:1d:a2:87:02:30 from Associated to Associated

*apfMsConnTask_0: Apr 17 10:09:36.658: 8c:77:12:ac:8c:3b Updating AID for REAP AP Client 00:1d:a2:87:02:30 - AID ===> 2

*dot1xMsgTask: Apr 17 10:09:36.660: 8c:77:12:ac:8c:3b Creating a PKC PMKID Cache entry for station 8c:77:12:ac:8c:3b (RSN 2)

*dot1xMsgTask: Apr 17 10:09:36.660: 8c:77:12:ac:8c:3b Adding BSSID 00:1d:a2:87:02:32 to PMKID cache for station 8c:77:12:ac:8c:3b

*dot1xMsgTask: Apr 17 10:09:36.661: New PMKID: (16)

*dot1xMsgTask: Apr 17 10:09:36.661:      [0000] 1b 92 b6 05 89 09 d5 c7 45 82 72 72 6a f2 b6 7e

*dot1xMsgTask: Apr 17 10:09:36.661: 8c:77:12:ac:8c:3b Initiating RSN PSK to mobile 8c:77:12:ac:8c:3b

*dot1xMsgTask: Apr 17 10:09:36.661: 8c:77:12:ac:8c:3b dot1x - moving mobile 8c:77:12:ac:8c:3b into Force Auth state

*dot1xMsgTask: Apr 17 10:09:36.661: 8c:77:12:ac:8c:3b Skipping EAP-Success to mobile 8c:77:12:ac:8c:3b

*dot1xMsgTask: Apr 17 10:09:36.661: Including PMKID in M1  (16)

*dot1xMsgTask: Apr 17 10:09:36.661:      [0000] 1b 92 b6 05 89 09 d5 c7 45 82 72 72 6a f2 b6 7e

*dot1xMsgTask: Apr 17 10:09:36.661: 8c:77:12:ac:8c:3b Starting key exchange to mobile 8c:77:12:ac:8c:3b, data packets will be dropped

*dot1xMsgTask: Apr 17 10:09:36.661: 8c:77:12:ac:8c:3b Sending EAPOL-Key Message to mobile 8c:77:12:ac:8c:3b

                                                                                                              state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.674: 8c:77:12:ac:8c:3b Received EAPOL-Key from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.674: 8c:77:12:ac:8c:3b Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.674: 8c:77:12:ac:8c:3b Received EAPOL-key in PTK_START state (message 2) from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.674: 8c:77:12:ac:8c:3b Stopping retransmission timer for mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.675: 8c:77:12:ac:8c:3b Sending EAPOL-Key Message to mobile 8c:77:12:ac:8c:3b

                                                                                                                    state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.681: 8c:77:12:ac:8c:3b Received EAPOL-Key from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.681: 8c:77:12:ac:8c:3b Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.681: 8c:77:12:ac:8c:3b Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 8c:77:12:ac:8c:3b

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.681: 8c:77:12:ac:8c:3b apfMs1xStateInc

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.681: 8c:77:12:ac:8c:3b 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.682: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.682: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) DHCP Not required on AP 00:1d:a2:87:02:30 vapId 3 apVapId 3for this client

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.682: 8c:77:12:ac:8c:3b Not Using WMM Compliance code qosCap 00

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:1d:a2:87:02:30 vapId 3 apVapId 3

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) pemAdvanceState2 4817, Adding TMP rule

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) Adding Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1d:a2:87:02:30, slot 0, interface = 29, QOS = 0

  ACL Id = 255, Ju

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 5006  IPv6 Vlan = 199, IPv6 intf id = 13

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) Successfully plumbed mobile rule (ACL ID 255)

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state DHCP_REQD (7)

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.683: 8c:77:12:ac:8c:3b 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4833, Adding TMP rule

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.028: 8c:77:12:ac:8c:3b 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1d:a2:87:02:30, slot 0, interface = 29, QOS = 0

  ACL Id = 255, Jumb

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.684: 8c:77:12:ac:8c:3b 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 5006  IPv6 Vlan = 199, IPv6 intf id = 13

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.684: 8c:77:12:ac:8c:3b 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)

*Dot1x_NW_MsgTask_0: Apr 17 10:09:36.684: 8c:77:12:ac:8c:3b Stopping retransmission timer for mobile 8c:77:12:ac:8c:3b

*pemReceiveTask: Apr 17 10:09:36.689: 8c:77:12:ac:8c:3b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0

*pemReceiveTask: Apr 17 10:09:36.695: 8c:77:12:ac:8c:3b 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0

*DHCP Proxy DTL Recv Task: Apr 17 10:09:36.831: 8c:77:12:ac:8c:3b DHCP received op BOOTREPLY (2) (len 325,vlan 0, port 29, encap 0xec03)

*DHCP Proxy DTL Recv Task: Apr 17 10:09:36.831: 8c:77:12:ac:8c:3b DHCP setting server from ACK (server 192.168.2.1, yiaddr 192.168.2.13)

*DHCP Proxy DTL Recv Task: Apr 17 10:09:36.853: 8c:77:12:ac:8c:3b apfBlacklistMobileStationEntry2 (apf_ms.c:4296) Changing state for mobile 8c:77:12:ac:8c:3b on AP 00:1d:a2:87:02:30 from Associated to Exclusion-list (1)

*DHCP Proxy DTL Recv Task: Apr 17 10:09:36.853: 8c:77:12:ac:8c:3b Scheduling deletion of Mobile Station:  (callerId: 44) in 10 seconds

*DHCP Proxy DTL Recv Task: Apr 17 10:09:36.854: 8c:77:12:ac:8c:3b DHCP failed to register IP 192.168.2.13 - dropping ACK

[Thomas Obbekaer Thomsen]

Aparently i was hitting a bug (why does this always happen to me :-) )

After we upgraded the software on the WLCs everything works fine.

[Scott Fella]

Thomas,

Thanks for posting your findings, as it would help other who might run into that same issue. You happen to know the bug id.

Sent from Cisco Technical Support iPad App

[Johan73]

Client 'aa:bb:11:01:02:03 (host/LAP-00123.LOCAL, 0.0.0.0)' which
was associated with interface '802.11a/n' of AP 'AP11' is excluded.
The reason code is '3(Attempted to use IP Address assigned to another
device)'.

In our dhcp scope  LAP-00123 has 192.268.0.251 address instead of 0.0.0.0
192.268.0.251 is the wifi address of the controller it self --> #Identity Theft!

[MARK BAKER]

Thomas,

Do you have the bug ID and/or the version that you upgraded to to fix this issue? I am seeing this same issue on the same version that you were running when you were experiencing it. I am planning to go to 7.0.235.3. I assume you upgraded to a 7.0.235 version as well to fix it, but wanted to check.

Thanks,
Mark

[Thomas Obbekaer Thomsen]

Hi Mark

Yes I upgraded to 7.0.235, as far as i remember, and the problem disappeared.

I tried to figure out what bug I might have hit, by searching the bugdatabase, but nothing turned up.

But the problem disapered after upgrading only the WLC software, so i presume that it was a bug that was fixed somehow.

/Thomas

[MARK BAKER]

Thanks Thomas,

I wanted to add that this issue was seen today on WLC version 7.0.230 with the Iphone 4s version 6.0.1

Thanks,
Mark

[julio.vallejos]

Hello everyone.!
I had the same problem and I solved it temporarily by assigning a fixed ip by mac address to the mobile client, the ip assignment by mac addres, I did it on my edge router (dhcp server) and when the client connected, I already assigned the ip I specified on my edge router then the error on the WLC was not occurring. I hope it serves someone. Good luck greetings