WLC2504 日志Attempted to use IP Address assigned to another device

xinyuan2099 · ‎07-23-2014

Hi，各位。
公司有两个WLC：2504和4402，这两个WLC的除了一些基本的配置如IP、名称外，其他的配置都一样，如wifi配置。但两个WLC控制的AP都相距很远，不会存在干扰和冲突。
故障：部分用户无法获取到IP，WLC web上的报错如下，我debug了其中一个mac地址，拓扑图及日志和debug详细见下面。

Wed Jul 23 10:54:52 2014

Client Excluded: MACAddress:8c:70:5a:2d:21:f0 Base Radio MAC :00:24:97:b7:9f:d0 Slot: 0 User Name: CQ\ychen2 Ip Address: unknown Reason:Attempted to use IP Address assigned to another device. ReasonCode: 3

拓扑图

日志

debug日志：
debug client a4:4e:31:c7:b2:68
show debug
MAC Addr 1.................................. A4:4E:31:C7:B2:68
Debug Flags Enabled:
dhcp packet enabled.
dot11 mobile enabled.
dot11 state enabled
dot1x events enabled.
dot1x states enabled.
pem events enabled.
pem state enabled.
CCKM client debug enabled.

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Adding mobile on LWAPP AP 00:24:14:31:d1:30(0)

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Association received from mobile on BSSID 00:24:14:31:d1:32

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Global 200 Clients are allowed to AP radio

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Max Client Trap Threshold: 0 cur: 4

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Rf profile 200 Clients are allowed to AP wlan

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Re-applying interface policy for client

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2018)

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2246)

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 In processSsidIE:4202 setting Central switched to TRUE

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 In processSsidIE:4205 apVapId = 3 and Split Acl Id = 65535

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Applying site-specific Local Bridging override for station a4:4e:31:c7:b2:68 - vapId 3, site 'default-group', interface 'sfh-wifi'

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 Applying Local Bridging Interface Policy for station a4:4e:31:c7:b2:68 - vlan 190, interface id 14, interface 'sfh-wifi'

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 processSsidIE statusCode is 0 and status is 0

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 processSsidIE ssid_done_flag is 0 finish_flag is 0

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 STA - rates (8): 130 132 139 150 12 18 24 36 0 0 0 0 0 0 0 0

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 suppRates statusCode is 0 and gotSuppRatesElement is 1

*apfMsConnTask_0: Jul 23 10:59:05.127: a4:4e:31:c7:b2:68 STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Processing RSN IE type 48, length 22 for mobile a4:4e:31:c7:b2:68

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Received RSN IE with 0 PMKIDs from mobile a4:4e:31:c7:b2:68

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Setting active key cache index 8 ---> 8

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 unsetting PmkIdValidatedByAp

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 0.0.0.0 START (0) Initializing policy

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Not Using WMM Compliance code qosCap 00

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:24:14:31:d1:30 vapId 3 apVapId 3 flex-acl-name:

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 apfMsAssoStateInc

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 apfPemAddUser2 (apf_policy.c:276) Changing state for mobile a4:4e:31:c7:b2:68 on AP 00:24:14:31:d1:30 from Idle to Associated

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 apfPemAddUser2:session timeout forstation a4:4e:31:c7:b2:68 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Stopping deletion of Mobile Station: (callerId: 48)

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 Sending Assoc Response to station on BSSID 00:24:14:31:d1:32 (status 0) ApVapId 3 Slot 0

*apfMsConnTask_0: Jul 23 10:59:05.128: a4:4e:31:c7:b2:68 apfProcessAssocReq (apf_80211.c:7391) Changing state for mobile a4:4e:31:c7:b2:68 on AP 00:24:14:31:d1:30 from Associated to Associated

*dot1xMsgTask: Jul 23 10:59:05.131: a4:4e:31:c7:b2:68 Disable re-auth, use PMK lifetime.

*dot1xMsgTask: Jul 23 10:59:05.132: a4:4e:31:c7:b2:68 Station a4:4e:31:c7:b2:68 setting dot1x reauth timeout = 1800

*dot1xMsgTask: Jul 23 10:59:05.132: a4:4e:31:c7:b2:68 dot1x - moving mobile a4:4e:31:c7:b2:68 into Connecting state

*dot1xMsgTask: Jul 23 10:59:05.132: a4:4e:31:c7:b2:68 Sending EAP-Request/Identity to mobile a4:4e:31:c7:b2:68 (EAP Id 1)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.146: a4:4e:31:c7:b2:68 Received EAPOL START from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.146: a4:4e:31:c7:b2:68 dot1x - moving mobile a4:4e:31:c7:b2:68 into Connecting state

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.146: a4:4e:31:c7:b2:68 Sending EAP-Request/Identity to mobile a4:4e:31:c7:b2:68 (EAP Id 2)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.239: a4:4e:31:c7:b2:68 Received EAPOL EAPPKT from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.239: a4:4e:31:c7:b2:68 Received EAP Response packet with mismatching id (currentid=2, eapid=1) from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.356: a4:4e:31:c7:b2:68 Received EAPOL EAPPKT from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.356: a4:4e:31:c7:b2:68 Received Identity Response (count=2) from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.356: a4:4e:31:c7:b2:68 EAP State update from Connecting to Authenticating for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.356: a4:4e:31:c7:b2:68 dot1x - moving mobile a4:4e:31:c7:b2:68 into Authenticating state

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.356: a4:4e:31:c7:b2:68 Entering Backend Auth Response state for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.358: a4:4e:31:c7:b2:68 Processing Access-Challenge for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.358: a4:4e:31:c7:b2:68 Entering Backend Auth Req state (id=71) for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.358: a4:4e:31:c7:b2:68 WARNING: updated EAP-Identifier 2 ===> 71 for STA a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.358: a4:4e:31:c7:b2:68 Sending EAP Request from AAA to mobile a4:4e:31:c7:b2:68 (EAP Id 71)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.486: a4:4e:31:c7:b2:68 Received EAPOL EAPPKT from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.486: a4:4e:31:c7:b2:68 Received EAP Response from mobile a4:4e:31:c7:b2:68 (EAP Id 71, EAP Type 17)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.486: a4:4e:31:c7:b2:68 Entering Backend Auth Response state for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.522: a4:4e:31:c7:b2:68 Processing Access-Challenge for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.522: a4:4e:31:c7:b2:68 Entering Backend Auth Req state (id=71) for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.522: a4:4e:31:c7:b2:68 WARNING: updated EAP-Identifier 71 ===> 71 for STA a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.522: a4:4e:31:c7:b2:68 Sending EAP Request from AAA to mobile a4:4e:31:c7:b2:68 (EAP Id 71)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.525: a4:4e:31:c7:b2:68 Received EAPOL EAPPKT from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.525: a4:4e:31:c7:b2:68 Received LEAP EAP Request (type=17, ver=1) from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.525: a4:4e:31:c7:b2:68 Entering Backend Auth Response state for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 Processing Access-Accept for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 Resetting web IPv4 acl from 255 to 255

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 Resetting web IPv4 Flex acl from 65535 to 65535

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 190

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 Re-applying interface policy for client

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 0.0.0.0 8021X_REQD (3) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2018)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.527: a4:4e:31:c7:b2:68 0.0.0.0 8021X_REQD (3) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2246)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Inserting AAA Override struct for mobile

MAC: a4:4e:31:c7:b2:68, source 4

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Setting re-auth timeout to 1800 seconds, got from WLAN config.

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Station a4:4e:31:c7:b2:68 setting dot1x reauth timeout = 1800

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Username entry (CQ\dzhang1) created for mobile, length = 253

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Username entry (CQ\dzhang1) created in mscb for mobile, length = 253

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Creating a PKC PMKID Cache entry for station a4:4e:31:c7:b2:68 (RSN 2)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Resetting MSCB PMK Cache Entry 0 for station a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Setting active key cache index 8 ---> 8

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Setting active key cache index 8 ---> 0

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Adding BSSID 00:24:14:31:d1:32 to PMKID cache at index 0 for station a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: [0000] fa 96 35 7a df fb 88 68 ea 9f 5c 72 c7 37 6f a8

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Disabling re-auth since PMK lifetime can take care of same.

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 unsetting PmkIdValidatedByAp

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 PMK sent to mobility group

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Found an cache entry for BSSID 00:24:14:31:d1:32 in PMKID cache at index 0 of station a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: [0000] fa 96 35 7a df fb 88 68 ea 9f 5c 72 c7 37 6f a8

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Starting key exchange to mobile a4:4e:31:c7:b2:68, data packets will be dropped

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Sending EAPOL-Key Message to mobile a4:4e:31:c7:b2:68
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Entering Backend Auth Success state (id=71) for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.528: a4:4e:31:c7:b2:68 Received Auth Success while in Authenticating state for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.529: a4:4e:31:c7:b2:68 dot1x - moving mobile a4:4e:31:c7:b2:68 into Authenticated state

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 Received EAPOL-Key from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 Received EAPOL-key in PTK_START state (message 2) from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 PMK: Sending cache add

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 Stopping retransmission timer for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.535: a4:4e:31:c7:b2:68 Sending EAPOL-Key Message to mobile a4:4e:31:c7:b2:68
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 Received EAPOL-Key from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 Stopping retransmission timer for mobile a4:4e:31:c7:b2:68

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 apfMs1xStateInc

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 Not Using WMM Compliance code qosCap 00

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:24:14:31:d1:30 vapId 3 apVapId 3 flex-acl-name:

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 5951, Adding TMP rule

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule

type = Airespace AP - Learn IP address

on AP 00:24:14:31:d1:30, slot 0, interface = 13, QOS = 0

IPv4 ACL ID = 255, IP

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 190, Local Bridging intf id = 14

*Dot1x_NW_MsgTask_0: Jul 23 10:59:05.539: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255)

*apfReceiveTask: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 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: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 5575, Adding TMP rule

*apfReceiveTask: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule

type = Airespace AP - Learn IP address

on AP 00:24:14:31:d1:30, slot 0, interface = 13, QOS = 0

IPv4 ACL ID = 255,

*apfReceiveTask: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206 Local Bridging Vlan = 190, Local Bridging intf id = 14

*apfReceiveTask: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255)

*apfReceiveTask: Jul 23 10:59:05.540: a4:4e:31:c7:b2:68 Installing AAA IP address

10.27.33.123

for station

*apfReceiveTask: Jul 23 10:59:05.541: a4:4e:31:c7:b2:68 apfBlacklistMobileStationEntry2 (apf_ms.c:5061) Changing state for mobile a4:4e:31:c7:b2:68 on AP 00:24:14:31:d1:30 from Associated to Exclusion-list (1)

*apfReceiveTask: Jul 23 10:59:05.541: a4:4e:31:c7:b2:68 Scheduling deletion of Mobile Station: (callerId: 44) in 10 seconds

*apfReceiveTask: Jul 23 10:59:05.541: a4:4e:31:c7:b2:68 Unsuccessfully installed IP address

10.27.33.123

for station

*pemReceiveTask: Jul 23 10:59:05.542: a4:4e:31:c7:b2:68 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0

*pemReceiveTask: Jul 23 10:59:05.542: a4:4e:31:c7:b2:68 Sent an XID frame

*pemReceiveTask: Jul 23 10:59:05.542: a4:4e:31:c7:b2:68 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0

*pemReceiveTask: Jul 23 10:59:05.542: a4:4e:31:c7:b2:68 Sent an XID frame

*DHCP Socket Task: Jul 23 10:59:05.614: a4:4e:31:c7:b2:68 DHCP received op BOOTREQUEST (1) (len 308,vlan 2, port 13, encap 0xec03)

*DHCP Socket Task: Jul 23 10:59:05.614: a4:4e:31:c7:b2:68 DHCP dropping packet from STA on exclusion list

*IPv6_Msg_Task: Jul 23 10:59:05.791: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Reached ERROR: from line 5790

*apfOrphanSocketTask: Jul 23 10:59:07.978: a4:4e:31:c7:b2:68 Orphan Packet from STA - IP 169.254.244.119

*apfOrphanSocketTask: Jul 23 10:59:07.978: a4:4e:31:c7:b2:68 Dropping orphan Packet from 169.254.244.119 on mobile(apfMsState=8)

*DHCP Socket Task: Jul 23 10:59:08.879: a4:4e:31:c7:b2:68 DHCP received op BOOTREQUEST (1) (len 308,vlan 2, port 13, encap 0xec03)

*DHCP Socket Task: Jul 23 10:59:08.879: a4:4e:31:c7:b2:68 DHCP dropping packet from STA on exclusion list

*IPv6_Msg_Task: Jul 23 10:59:09.799: a4:4e:31:c7:b2:68 Pushing IPv6: fe80:0000:0000:0000: 9822:3d11:cb70:f477 , and MAC: A4:4E:31:C7:B2:68 , Binding to Data Plane. SUCCESS !!

*IPv6_Msg_Task: Jul 23 10:59:09.799: a4:4e:31:c7:b2:68 Not Advancing pem state, mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_BLACKLISTED

*IPv6_Msg_Task: Jul 23 10:59:09.799: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Reached ERROR: from line 5790

*IPv6_Msg_Task: Jul 23 10:59:13.794: a4:4e:31:c7:b2:68 Pushing IPv6: fe80:0000:0000:0000: 9822:3d11:cb70:f477 , and MAC: A4:4E:31:C7:B2:68 , Binding to Data Plane. SUCCESS !!

*IPv6_Msg_Task: Jul 23 10:59:13.794: a4:4e:31:c7:b2:68 Not Advancing pem state, mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_BLACKLISTED

*IPv6_Msg_Task: Jul 23 10:59:13.795: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Reached ERROR: from line 5790

*osapiBsnTimer: Jul 23 10:59:15.388: a4:4e:31:c7:b2:68 apfMsExpireCallback (apf_ms.c:614) Expiring Mobile!

*apfReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 Sent Deauthenticate to mobile on BSSID 00:24:14:31:d1:30 slot 0(caller apf_ms.c:5897)

*apfReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 Scheduling deletion of Mobile Station: (callerId: 46) in 60 seconds

*apfReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 apfMsExpireMobileStation (apf_ms.c:5927) Changing state for mobile a4:4e:31:c7:b2:68 on AP 00:24:14:31:d1:30 from Exclusion-list (1) to Exclusion-list (2)

*apfReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.

*apfReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 0.0.0.0 DHCP_REQD (7) Deleted mobile LWAPP rule on AP [00:24:14:31:d1:30]

*pemReceiveTask: Jul 23 10:59:15.389: a4:4e:31:c7:b2:68 0.0.0.0 Removed NPU entry.

*apfMsConnTask_0: Jul 23 10:59:15.390: Stats update: Non Zero value

*apfMsConnTask_2: Jul 23 10:59:15.655: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_2: Jul 23 10:59:16.346: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_2: Jul 23 10:59:17.071: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_2: Jul 23 10:59:17.781: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_2: Jul 23 10:59:18.481: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_2: Jul 23 10:59:19.172: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_0: Jul 23 10:59:19.829: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_0: Jul 23 10:59:20.504: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_0: Jul 23 10:59:21.190: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_0: Jul 23 10:59:21.876: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

*apfMsConnTask_0: Jul 23 10:59:22.563: a4:4e:31:c7:b2:68 Ignoring assoc request due to mobile in exclusion list or marked for deletion

lindawa · ‎07-25-2014

控制器的软件版本是多少？

lindawa · ‎07-25-2014

Wed Jul 23 10:54:52 2014 Client Excluded: MACAddress:8c:70:5a:2d:21:f0 Base Radio MAC :00:24:97:b7:9f:d0 Slot: 0 User Name: CQ\ychen2 Ip Address: unknown Reason:Attempted to use IP Address assigned to another device. ReasonCode: 3
当你看到这条log的时候，说明网络里面存在IP冲突。可能的情况是，当前客户端使用静态的IP，然后控制器发现这个IP其实已经被其它客户端使用了。
你先看看如果客户端不使用静态IP，而是从DHCP获取地址，问题是否还存在。

xinyuan2099 · ‎07-28-2014

lindawa 发表于 2014-7-25 16:54
控制器的软件版本是多少？

Manufacturer's Name.............................. Cisco Systems Inc.
Product Name..................................... Cisco Controller
Product Version.................................. 7.4.100.0
Bootloader Version............................... 1.0.16
Field Recovery Image Version..................... 1.0.0
Firmware Version................................. PIC 16.0

xinyuan2099 · ‎07-28-2014

lindawa 发表于 2014-7-25 17:06
Wed Jul 23 10:54:52 2014 Client Excluded: MACAddress:8c:70:5a:2d:21:f0 Base Radio MAC :00:24:97:b7:9 ...

我测试了一下，并没有发现有静态设置的IP地址。都是使用DHCP获取的IP地址，在DHCP日志中也没有发现冲突。

lindawa · ‎07-29-2014

xinyuan2099 发表于 2014-7-29 14:51
我测试了一下，并没有发现有静态设置的IP地址。都是使用DHCP获取的IP地址，在DHCP日志中也没有发现冲突。

你看看WLAN的高级菜单中，以下选项有没有勾上。如果没有，先把它勾上；
DHCP Addr. Assignment Required
然后若问题仍然存在，请开TAC Case进行排查。

XUXIANDA888 · ‎09-07-2014

:) 学习学习！！

xinyuan2099 · ‎09-09-2014

现在问题还没有解决，正常寻求原厂支持。等待有答案后才来更新。