Re: WLC 5520 8.3.143.0 - Clients receiving Incorrect IP Address but correct VLAN Tag

Colton · ‎08-17-2020

Good Afternoon,

I currently have a Cisco WLC 5520 that is servicing a variety of Wireless Access Points (AIR-AP2802I-A-K9 / AIR-CAP3602I-A-K9 / AIR-AP1810W-A-K9)

We have been running into a problem where a client will connect to an SSID and receive an IP Address from an entirely different subnet.

Example: Client Connects to SSID and gets tagged with VLAN5 but the client has a VLAN45 IP. (The VLAN45 IP is actually the Native VLAN ID programmed on the Cisco Access Points. The Switching is configured as Trunk Ports with Native Vlan 45 Configured)

When I inspect the Client it will display the VLAN ID and Flex VLAN ID as the proper VLAN despite the improper IP Address. (It would make more sense if the client was untagged to then get a VLAN45 IP) - see attached PNG for example of Client. They should have a 10.165.5.X as an example, 3rd Octect in this scenario matches the VLAN IDs)

Thank you

Client Example: Debug from Cisco WLC

(Cisco Controller) >debug client 0c:84:dc:8e:7f:5f

(Cisco Controller) >*emWeb: Aug 17 14:59:55.707: 0c:84:dc:8e:7f:5f Succesfully freed AID 1, slot 0 on AP 00:08:32:8b:4d:e0, #client on this slot 0
*osapiBsnTimer: Aug 17 14:59:56.542: 0c:84:dc:8e:7f:5f apfMsExpireCallback (apf_ms.c:639) Expiring Mobile!
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f apfMsExpireMobileStation (apf_ms.c:7688) Changing state for mobile 0c:84:dc:8e:7f:5f on AP 00:08:32:8b:4d:e0 from Associated to Disassociated

*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Client already in disassociated state, not sending disassociation
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Setting active key cache index 0 ---> 8
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Deleting the PMK cache when de-authenticating the client.
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Global PMK Cache deletion failed.
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Sent Deauthenticate to mobile on BSSID 00:08:32:8b:4d:e2 slot 0(caller apf_ms.c:7780)
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f apfMsAssoStateDec
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f apfMsWepPskStateDec
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f apfMsExpireMobileStation (apf_ms.c:7821) Changing state for mobile 0c:84:dc:8e:7f:5f on AP 00:08:32:8b:4d:e0 from Disassociated to Idle

*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f 10.165.45.28 START (0) Deleted mobile LWAPP rule on AP [00:08:32:8b:4d:e0]
*apfReceiveTask: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Deleting mobile on AP 00:08:32:8b:4d:e0(0)
*spamApTask4: Aug 17 14:59:56.543: 0c:84:dc:8e:7f:5f Delete Mobile request on slot 0 sent to the AP 00:08:32:8b:4d:e0 IP: 10.165.45.18:5264

*spamApTask4: Aug 17 14:59:56.566: 0c:84:dc:8e:7f:5f apfUpdateDeleteAckInMscb (apf_api.c:51702) Expiring Mobile!
*apfOpenDtlSocket: Aug 17 14:59:57.371: 0c:84:dc:8e:7f:5f Recevied management frame REASSOCIATION REQUEST on BSSID 00:08:32:8b:4d:e2 destination addr 00:08:32:8b:4d:e2
*apfMsConnTask_4: Aug 17 14:59:57.371: 0c:84:dc:8e:7f:5f Processing assoc-req station:0c:84:dc:8e:7f:5f AP:00:08:32:8b:4d:e0-00 ssid : NCDSB_Edison thread:1c4e5420
*apfMsConnTask_4: Aug 17 14:59:57.371: 0c:84:dc:8e:7f:5f Created Acct-Session-ID (5f3ad3ad/0c:84:dc:8e:7f:5f/627983) for the mobile
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Adding mobile on LWAPP AP 00:08:32:8b:4d:e0(0)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Reassociation received from mobile on BSSID 00:08:32:8b:4d:ec AP SPCO.OUTSIDE.RM102.RM103
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Station: 0C:84:DC:8E:7F:5F 11v BSS Transition not enabled on the AP 00:08:32:8B:4D:E0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Rf profile 200 Clients are allowed to AP radio

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Max Client Trap Threshold: 12 cur: 0

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f override for default ap group, marking intgrp NULL
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Applying Interface(vlan-5) policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Not re-applying interface policy for local switching Client

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f In processSsidIE:6609 setting Central switched to FALSE
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Set Clinet MSCB as Central Association Disabled
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Applying site-specific Local Bridging override for station 0c:84:dc:8e:7f:5f - vapId 13, site 'SPCO', interface 'vlan-5'
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Applying Local Bridging Interface Policy for station 0c:84:dc:8e:7f:5f - vlan 5, interface id 11, interface 'vlan-5'
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f override from ap group, removing intf group from mscb
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Applying site-specific override for station 0c:84:dc:8e:7f:5f - vapId 13, site 'SPCO', interface 'vlan-5'
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Applying Interface(vlan-5) policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Not re-applying interface policy for local switching Client

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Set Clinet Non AP specific Flexgroup apfMsAccessVlan = 5
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Cleared localSwitchingVlan, may be assigned later based on AAA override
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f STA - rates (7): 18 152 36 48 72 96 108 0 0 0 0 0 0 0 0 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Process P2P IE And Update CB on BSSID 00:08:32:8b:4d:e0 slot 0
*apfMsConnTask_4: Aug 17 14:59:57.372: RSNIE in Assoc. Req.: (20)

*apfMsConnTask_4: Aug 17 14:59:57.372: [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_4: Aug 17 14:59:57.372: [0016] ac 02 88 00

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Processing RSN IE type 48, length 20 for mobile 0c:84:dc:8e:7f:5f
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Received 802.11i PSK key management suite, enabling Authentication
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f RSN Capabilities: 136
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Marking Mobile as non-11w Capable
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Updating AID for REAP AP Client 00:08:32:8b:4d:e0 - AID ===> 1
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfVapSecurity=0x40004000 L2=16384 SkipWeb=0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f AuthenticationRequired = 1
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Encryption policy is set to 0x80000001
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 8021X_REQD (3) DHCP required on AP 00:08:32:8b:4d:e0 vapId 13 apVapId 3for this client
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Not Using WMM Compliance code qosCap 00
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Vlan while overriding the policy = -1
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:08:32:8b:4d:e0 vapId 13 apVapId 3 flex-acl-name:
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfMsAssoStateInc
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfMsWepPskStateInc
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfPemAddUser2 (apf_policy.c:416) Changing state for mobile 0c:84:dc:8e:7f:5f on AP 00:08:32:8b:4d:e0 from Idle to Associated

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfPemAddUser2:session timeout forstation 0c:84:dc:8e:7f:5f - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Sending assoc-resp with status 0 station:0c:84:dc:8e:7f:5f AP:00:08:32:8b:4d:e0-00 on apVapId 3
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f Sending Assoc Response (status: '0') to station on AP SPCO.OUTSIDE.RM102.RM103 on BSSID 00:08:32:8b:4d:e2 ApVapId 3 Slot 0, mobility role 0
*apfMsConnTask_4: Aug 17 14:59:57.372: 0c:84:dc:8e:7f:5f apfProcessAssocReq (apf_80211.c:11039) Changing state for mobile 0c:84:dc:8e:7f:5f on AP 00:08:32:8b:4d:e0 from Associated to Associated

*spamApTask4: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Received ADD_MOBILE ack - Initiating 1x to STA 0c:84:dc:8e:7f:5f (idx 48)
*spamApTask4: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Sent dot1x auth initiate message for mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f reauth_sm state transition 0 ---> 1 for mobile 0c:84:dc:8e:7f:5f at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Creating a PKC PMKID Cache entry for station 0c:84:dc:8e:7f:5f (RSN 2)
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Resetting MSCB PMK Cache Entry @index 0 for station 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Setting active key cache index 8 ---> 8
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Created PMKID PMK Cache for BSSID 00:08:32:8b:4d:e2 at index 0 for station 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: New PMKID: (16)

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: [0000] c2 ae e0 9e 88 30 5c 4a 98 e5 9f ef 1b d5 fd 13

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Initiating RSN PSK to mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f EAP-PARAM Debug - eap-params for Wlan-Id :13 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f dot1x - moving mobile 0c:84:dc:8e:7f:5f into Force Auth state
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Skipping EAP-Success to mobile 0c:84:dc:8e:7f:5f (encryptBit:0)
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f key Desc Version FT - 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Found an cache entry for BSSID 00:08:32:8b:4d:e2 in PMKID cache at index 0 of station 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Found an cache entry for BSSID 00:08:32:8b:4d:e2 in PMKID cache at index 0 of station 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: [0000] c2 ae e0 9e 88 30 5c 4a 98 e5 9f ef 1b d5 fd 13

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: M1 - Key Data: (22)

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: [0000] dd 14 00 0f ac 04 c2 ae e0 9e 88 30 5c 4a 98 e5

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: [0016] 9f ef 1b d5 fd 13

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Starting key exchange to mobile 0c:84:dc:8e:7f:5f, data packets will be dropped
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Sending EAPOL-Key Message to mobile 0c:84:dc:8e:7f:5f
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.396: 0c:84:dc:8e:7f:5f Allocating EAP Pkt for retransmission to mobile 0c:84:dc:8e:7f:5f
*dot1xSocketTask: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Received EAPOL-Key from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f key Desc Version FT - 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Received EAPOL-key in PTK_START state (message 2) from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Compare RSN IE in association and EAPOL-M2 frame(Skip pmkIdLen:0,and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Dumping RSNIE received in Association request:
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 00000000: 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0...............
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 00000010: 00 0f ac 02 88 00 ......
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Dumping RSNIE received in EAPOL M2 :
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 00000010: ac 02 88 00 ....
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Stopping retransmission timer for mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f key Desc Version FT - 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f key Desc Version FT - 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Sending EAPOL-Key Message to mobile 0c:84:dc:8e:7f:5f
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.419: 0c:84:dc:8e:7f:5f Reusing allocated memory for EAP Pkt for retransmission to mobile 0c:84:dc:8e:7f:5f
*dot1xSocketTask: Aug 17 14:59:57.446: 0c:84:dc:8e:7f:5f validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.446: 0c:84:dc:8e:7f:5f Received EAPOL-Key from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.446: 0c:84:dc:8e:7f:5f Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.446: 0c:84:dc:8e:7f:5f key Desc Version FT - 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.446: 0c:84:dc:8e:7f:5f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Stopping retransmission timer for mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Freeing EAP Retransmit Bufer for mobile 0c:84:dc:8e:7f:5f
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f apfMs1xStateInc
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Mobility query, PEM State: L2AUTHCOMPLETE

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 L2AUTHCOMPLETE (4) NO release MSCB
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Building Mobile Announce :

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Building Client Payload:

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Client Ip: 0.0.0.0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Client Vlan Ip: 10.5.160.5, Vlan mask : 255.255.255.0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Client Vap Security: 1073758208

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Virtual Ip: 192.0.3.1

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f ssid: NCDSB_Edison

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Building VlanIpPayload.

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 L2AUTHCOMPLETE (4) DHCP required on AP 00:08:32:8b:4d:e0 vapId 13 apVapId 3for this client
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f sending to spamAddMobile vlanId -1 flex aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:08:32:8b:4d:e0 vapId 13 apVapId 3 flex-acl-name:
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6757, Adding TMP rule
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP 00:08:32:8b:4d:e0, slot 0, interface = 1, QOS = 0
IPv4 ACL ID = 255, IPv
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 64206, IntfId = 11 Local Bridging Vlan = 5, Local Bridging intf id = 11
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 64206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 64206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255)
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) NO release MSCB
*Dot1x_NW_MsgTask_7: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f Successfully Plumbed PTK session Keysfor mobile 0c:84:dc:8e:7f:5f
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local
Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.35.160.250
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 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: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6395, Adding TMP rule
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
type = Airespace AP - Learn IP address
on AP 00:08:32:8b:4d:e0, slot 0, interface = 1, QOS = 0
IPv4 ACL ID = 255,
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 64206, IntfId = 11 Local Bridging Vlan = 5, Local Bridging intf id = 11
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 64206 AverageRate = 0, BurstRate = 0

*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 64206 AverageRate = 0, BurstRate = 0

*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255,URL ACL ID 255)
*apfReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 DHCP_REQD (7) NO release MSCB
*pemReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*pemReceiveTask: Aug 17 14:59:57.447: 0c:84:dc:8e:7f:5f 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*dtlArpTask: Aug 17 14:59:58.327: 0c:84:dc:8e:7f:5f Static IP client associated to interface vlan-5 which cannot support client subnet.
*dtlArpTask: Aug 17 14:59:58.327: 0c:84:dc:8e:7f:5f apfMsRunStateInc
*dtlArpTask: Aug 17 14:59:58.327: 0c:84:dc:8e:7f:5f 10.165.45.28 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7)

*dtlArpTask: Aug 17 14:59:58.327: 0c:84:dc:8e:7f:5f 10.165.45.28 RUN (20) NO release MSCB

patoberli · ‎08-18-2020

This message here confuses me a little:
*dtlArpTask: Aug 17 14:59:58.327: 0c:84:dc:8e:7f:5f Static IP client associated to interface vlan-5 which cannot support client subnet.

Can you check your interface configuration on the WLC if the vlan-5 (must be named like this) interface has a DHCP server configured?

Which VLAN is using which IP range? That would make the reading of the log a bit easier.

Colton · ‎08-18-2020

Good Morning,

According to my WLC5520 Configuration -> Interfaces -> VLAN-5 It is currently showing an old DHCP Server actually. This server in question no longer has any scopes to provide. (I guess since the DHCP Servers have been moved to on-site devices vs a central DHCP Server I should remove the DHCP Information in this VLAN Interface on the WLC?)

Clients: VLAN 5 Subnet = 10.X.VLAN.X (10.165.5.X) (2nd Octect is Site Specific)
Access Points: VLAN 45 Subnet = 10.x.VLAN.X (10.165.45.X)

patoberli · ‎08-18-2020

That means the WCL (which acts as a DHCP proxy in most configurations) can't forward the DHCP packet to the vlan-5 configured server. So you need to configure it to the now correct DHCP server which can offer the scope 10.165.5.x.

Colton · ‎08-18-2020

Understandable.

Considering I have the WLC servicing several different sites that all utilize an on-site DHCP Server now would I remove the DHCP Entries from the WLC entriely and leave them empty? Or would I be looking at creating duplicate vlan-5 interfaces that are unique to each site?

patoberli · ‎08-19-2020

Ok, that's where the DHCP Proxy option comes into play. I don't anymore remember 8.3, but on 8.5 you have directly below the DHPC Server address option in the interface configuration to set the DHCP Proxy mode. You should have Global, Enabled and Disabled. If you don't want the WLC to play a proxy (and reduce the need of a DHCP helper address on the router for the DHCP server), set it to disabled for this interface and remove the DHCP Server ip addresses. Then the WLC should ignore the packets and the client should discover the local DHCP server configured on the router or running inside the subnet.

KalinKrumov · ‎04-25-2024

I have the same problem. I use WLC 5520 acting DHCP Proxy mode=Global (this is equal to disable). Behind WLC I have Fortigate FW acting as router and there is IP Helper address to local for site DHCP server. The DHCP is in another Vlan on the same Fortigate FW/Rtr.

I have clients which get proper IP but and new clients which are going to management Vlan where there is range for access point (not native vlan).

From reading here I will check for static IP on the new devices in the wifi network.