Cisco LAP – troubleshooting notes

This post contains notes related to troubleshooting Cisco LAPs and wireless clients.

The tests where conducted for LAP in local mode. In H-REAP (or flexonnect) mode most of the same logs  are generated (especially for client association/authentication).

Log configuration

There are two different types of logs generated byWLC:

  1. SNMP traps
  2. System and message logs

SNMP traps

Most useful log information related to clients is sent vis SNMP traps. You can configure what events to log – for example the following picture shows how to enable all client related events.

configure system logs

System and message logs

System logging – used by WLC to log its system events up to three remote syslog servers. Message logging allows system messages to be logged to the controller buffer and/or console. The following picture shows the configuration page.

configure system logs

Sometimes you will enable debug command on WLC (via Console). If you want the console debug output to be sent on syslog server you must configure the debug logging level for it:

debug-syslog

However you must also execute the following command:

(Cisco Controller) >config logging debug syslog enable

Association and authentication

The picture below shows the SNMP traps from the following three events:

  1. Client connects to the WLAN (configured with WPA2)
  2. Shortly (less than 5 minuts) clients disconnects from network (disconnect from network option on Windows 7 OS). This event is not logged
  3. Shortly the same client connects again.
  4. The client disconnects from the network (disconnect from network option on Windows 7 OS). After 5 minutes there is the trap which informs that WLC deauthenticate this client (because it was idle for 5 minutes).

client association and authentication

Notice that it is not possible to determine when exactly the client lost the connection. Also there are no system and message logs.

Invalid WPA2 password

The following screen shows traps generated by client with invalid WPA2 password. The client tries to authenticate several times and finally it is put into exclusion list.invalid-wpa2-password

This time there are system/message logs generated. You can also verify exclusion list.

*dot1xMsgTask: Feb 28 21:59:31.623: %DOT1X-3-MAX_EAPOL_KEY_RETRANS: 1x_ptsm.c:444 Max EAPOL-key M1 retransmissions exceeded for client 5c:93:a2:d0:54:14
*dot1xMsgTask: Feb 28 21:59:31.625: %APF-6-MOBILE_EXCLUDED: apf_ms.c:4338 Excluded the mobile 5c:93:a2:d0:54:14.
*dot1xMsgTask: Feb 28 21:59:31.625: %DOT1X-3-PSK_CONFIG_ERR: 1x_ptsm.c:606 Client 5c:93:a2:d0:54:14 may be using an incorrect PSK

(Cisco Controller) >show exclusionlist

No manually disabled clients.

Dynamically Disabled Clients
----------------------------
  MAC Address             Exclusion Reason        Time Remaining (in secs)
  -----------             ----------------        ------------------------

5c:93:a2:d0:54:14         802.1X Failure                28

Invalid WEP password

The following screen shows traps generated by client with invalid WEP password.

wep-invalid-password

There are no system/message logs generated. The following screen shows valid WEP connection.

wep-valid

Duplicate IP address

The picture below shows the association attempt by client with the ip address used by another station. The connection is refused (the old station is still connected; the new station is not allowed to connect to the WLAN).

duplicate-ip

There are system/message logs generated. You can also verify exclusion list.

(Cisco Controller) >
(Cisco Controller) >*dtlArpTask: Feb 28 22:34:17.531: %APF-4-REGISTER_IPADD_ON_MSCB_FAILED: apf_foreignap.c:1512 Could not Register IP Add on MSCB. Identity theft alert for IP address. Address:20:68:9d:19:52:7d
*dtlArpTask: Feb 28 22:34:17.533: %APF-6-MOBILE_EXCLUDED: apf_ms.c:4338 Excluded the mobile 20:68:9d:19:52:7d.

(Cisco Controller) >show exclusionlist

No manually disabled clients.

Dynamically Disabled Clients
----------------------------
  MAC Address             Exclusion Reason        Time Remaining (in secs)
  -----------             ----------------        ------------------------

20:68:9d:19:52:7d         Identity Theft                50


Linktest

You can perform linktest from WLC (the Linktest button is available in client details page on WLC). Here is an example.

WLC - linktest

Verify mobility role

If mobility role is set to Local it means that the client is connected directly to this controller. If role is shown as Anchor the client has undergone Layer 3 roam.
Before a controller will permit a client to fully associate with a basic service set (BSS), the client must progress through a sequence of states. The RUN state means that the client successfully associated and can pass traffic.

Monitor client from WLC

Debugging a Client from WLC

Note – to disable debugging use debug disable-all command.

Example 1

Here is an exemplary debug sessions enabled on WLC. A client with mac 5c:93:a2:d0:54:14 successfully associates with AP (client configured for WPA2 and dhcp). In the following example there are three entries bolded:

  1. the apf task begin/end (Access Point Functions APF: this process handles the state of the client through the 802.11 machine state)
  2. authentication (WPA2) success
  3. the begin of dhcp process
(Cisco Controller) >debug client 5c:93:a2:d0:54:14

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 Association received from mobile on AP 00:1c:0e:27:f3:30
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 Applying site-specific IPv6 override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 Applying IPv6 Interface Policy for station 5c:93:a2:d0:54:14 - vlan 0, interface id 0, interface 'management'
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 Applying site-specific override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 STA - rates (8): 140 18 152 36 176 72 96 108 0 0 0 0 0 0 0 0
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 Processing RSN IE type 48, length 20 for mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 apfMsRunStateDec
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 apfMs1xStateDec
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Change state to START (0) last state RUN (20)

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Initializing policy
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Change state to AUTHCHECK (2) last state RUN (20)

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.363: 5c:93:a2:d0:54:14 192.168.0.103 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) DHCP required on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1for this client
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 Not Using WMM Compliance code qosCap 00
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 Sending Assoc Response to station on BSSID 00:1c:0e:27:f3:30 (status 0) ApVapId 1 Slot 1
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *apfMsConnTask_0: Feb 28 23:24:06.364: 5c:93:a2:d0:54:14 apfProcessAssocReq (apf_80211.c:5284) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *spamReceiveTask: Feb 28 23:24:06.367: 5c:93:a2:d0:54:14 Sent 1x initiate message to multi thread task for mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.371: 5c:93:a2:d0:54:14 Creating a PKC PMKID Cache entry for station 5c:93:a2:d0:54:14 (RSN 2)
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.380: 5c:93:a2:d0:54:14 Adding BSSID 00:1c:0e:27:f3:3f to PMKID cache for station 5c:93:a2:d0:54:14
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.380: New PMKID: (16)

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.380:      [0000] a4 80 03 9f c0 67 05 b0 50 fe fb 22 6a de f0 24

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.380: 5c:93:a2:d0:54:14 Initiating RSN PSK to mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.380: 5c:93:a2:d0:54:14 dot1x - moving mobile 5c:93:a2:d0:54:14 into Force Auth state
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.381: 5c:93:a2:d0:54:14 Skipping EAP-Success to mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.381: Including PMKID in M1  (16)

Mon Feb 29 00:24:04 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.381:      [0000] a4 80 03 9f c0 67 05 b0 50 fe fb 22 6a de f0 24

Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.381: 5c:93:a2:d0:54:14 Starting key exchange to mobile 5c:93:a2:d0:54:14, data packets will be dropped
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.381: 5c:93:a2:d0:54:14 Sending EAPOL-Key Message to mobile 5c:93:a2:d0:54:14
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *pemReceiveTask: Feb 28 23:24:06.385: 5c:93:a2:d0:54:14 192.168.0.103 Removed NPU entry.
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.385: 5c:93:a2:d0:54:14 Received EAPOL-Key from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.385: 5c:93:a2:d0:54:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.385: 5c:93:a2:d0:54:14 Received EAPOL-key in PTK_START state (message 2) from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.386: 5c:93:a2:d0:54:14 Stopping retransmission timer for mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.386: 5c:93:a2:d0:54:14 Sending EAPOL-Key Message to mobile 5c:93:a2:d0:54:14
   state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.387: 5c:93:a2:d0:54:14 Received EAPOL-Key from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.387: 5c:93:a2:d0:54:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.387: 5c:93:a2:d0:54:14 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.387: 5c:93:a2:d0:54:14 apfMs1xStateInc
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)

Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) DHCP required on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1for this client
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 Not Using WMM Compliance code qosCap 00
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 apfMsRunStateInc
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.388: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)

Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.390: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Reached PLUMBFASTPATH: from line 4947
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.390: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Adding Fast Path rule
  type = Airespace AP Client
  on AP 00:1c:0e:27:f3:30, slot 1, interface = 1, QOS = 0
  ACL Id = 255, Jumbo Frames = NO
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.390: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 1506  IPv6 Vlan = 0, IPv6 intf id = 0
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.390: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Successfully plumbed mobile rule (ACL ID 255)
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *Dot1x_NW_MsgTask_0: Feb 28 23:24:06.390: 5c:93:a2:d0:54:14 Stopping retransmission timer for mobile 5c:93:a2:d0:54:14
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *pemReceiveTask: Feb 28 23:24:06.404: 5c:93:a2:d0:54:14 192.168.0.103 Added NPU entry of type 1, dtlFlags 0x0
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *DHCP Socket Task: Feb 28 23:24:06.415: 5c:93:a2:d0:54:14 DHCP selecting relay 1 - control block settings:
Mon Feb 29 00:24:08 2016;192.168.0.201; Cisco_93:ad:00: *DHCP Socket Task: Feb 28 23:24:06.414: 5c:93:a2:d0:54:14 DHCP received op BOOTREQUEST (1) (len 321,vlan 0, port 1, encap 0xec03)

Example 2

The following example shows the station (WPA2, dhcp) which goes out from the WLAN range and returns back in a moment.
ap-range-out
The following logs are generated on WLC. The logs are generated in the step 2 (when the station goes back into the WLAN range). There are no logs generated when station loses the connection. The logs show reassociation request, assocation success and authentication success (bolded entries).

*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 Reassociation received from mobile on AP 00:1c:0e:27:f3:30
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 Applying site-specific IPv6 override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 Applying IPv6 Interface Policy for station 5c:93:a2:d0:54:14 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 Applying site-specific override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 STA - rates (8): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 STA - rates (12): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 Processing RSN IE type 48, length 20 for mobile 5c:93:a2:d0:54:14
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 apfMsRunStateDec
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 apfMs1xStateDec
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Initializing policy
*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Change state to AUTHCHECK (2) last state RUN (20)

*apfMsConnTask_0: Feb 28 23:51:37.157: 5c:93:a2:d0:54:14 192.168.0.103 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) DHCP required on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1for this client
*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1
*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds
*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 Sending Assoc Response to station on BSSID 00:1c:0e:27:f3:30 (status 0) ApVapId 1 Slot 0
*apfMsConnTask_0: Feb 28 23:51:37.158: 5c:93:a2:d0:54:14 apfProcessAssocReq (apf_80211.c:5284) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

*spamReceiveTask: Feb 28 23:51:37.161: 5c:93:a2:d0:54:14 Sent 1x initiate message to multi thread task for mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.165: 5c:93:a2:d0:54:14 Creating a PKC PMKID Cache entry for station 5c:93:a2:d0:54:14 (RSN 2)
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.174: 5c:93:a2:d0:54:14 Adding BSSID 00:1c:0e:27:f3:30 to PMKID cache for station 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.174: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.174:      [0000] 43 4a 40 6f 4a 1a 11 c6 34 b4 90 2d c9 9e 89 c7

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.174: 5c:93:a2:d0:54:14 Initiating RSN PSK to mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175: 5c:93:a2:d0:54:14 dot1x - moving mobile 5c:93:a2:d0:54:14 into Force Auth state
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175: 5c:93:a2:d0:54:14 Skipping EAP-Success to mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175:      [0000] 43 4a 40 6f 4a 1a 11 c6 34 b4 90 2d c9 9e 89 c7

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175: 5c:93:a2:d0:54:14 Starting key exchange to mobile 5c:93:a2:d0:54:14, data packets will be dropped
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.175: 5c:93:a2:d0:54:14 Sending EAPOL-Key Message to mobile 5c:93:a2:d0:54:14
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*pemReceiveTask: Feb 28 23:51:37.179: 5c:93:a2:d0:54:14 192.168.0.103 Removed NPU entry.
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.240: 5c:93:a2:d0:54:14 Received EAPOL-Key from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.240: 5c:93:a2:d0:54:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.240: 5c:93:a2:d0:54:14 Received EAPOL-key in PTK_START state (message 2) from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.240: 5c:93:a2:d0:54:14 Stopping retransmission timer for mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.240: 5c:93:a2:d0:54:14 Sending EAPOL-Key Message to mobile 5c:93:a2:d0:54:14
   state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.251: 5c:93:a2:d0:54:14 Received EAPOL-Key from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 apfMs1xStateInc
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) DHCP required on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1for this client
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 apfMsRunStateInc
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.252: 5c:93:a2:d0:54:14 192.168.0.103 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)

*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.254: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Reached PLUMBFASTPATH: from line 4947
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.254: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Adding Fast Path rule
  type = Airespace AP Client
  on AP 00:1c:0e:27:f3:30, slot 0, interface = 1, QOS = 0
  ACL Id = 255, Jumbo Frames = NO
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.254: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 1506  IPv6 Vlan = 0, IPv6 intf id = 0
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.255: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Successfully plumbed mobile rule (ACL ID 255)
*Dot1x_NW_MsgTask_0: Feb 28 23:51:37.255: 5c:93:a2:d0:54:14 Stopping retransmission timer for mobile 5c:93:a2:d0:54:14
*pemReceiveTask: Feb 28 23:51:37.268: 5c:93:a2:d0:54:14 192.168.0.103 Added NPU entry of type 1, dtlFlags 0x0

There are traps generated by on WLC. In this case The hole pre-alarm was generated (but this alarm is not always generated when a station leaves the WLAN range).

trap-out-range

Example 3

The following example shows the station (WPA2, dhcp) which goes out from WLAN range. In this case the WLC detects this situation immediately. – The station tries to reassociate in the moment when it loses connection (and this process  was successful). However authentication process fails (too many retransmision) and the station is deauthenticated.

*apfMsConnTask_0: Feb 29 00:14:09.998: 5c:93:a2:d0:54:14 Reassociation received from mobile on AP 00:1c:0e:27:f3:30
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 Applying site-specific IPv6 override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 Applying IPv6 Interface Policy for station 5c:93:a2:d0:54:14 - vlan 0, interface id 0, interface 'management'
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 Applying site-specific override for station 5c:93:a2:d0:54:14 - vapId 1, site 'SchoolGroup', interface 'management'
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1633)
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 STA - rates (8): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 STA - rates (12): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 Processing RSN IE type 48, length 20 for mobile 5c:93:a2:d0:54:14
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 apfMsRunStateDec
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 apfMs1xStateDec
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Initializing policy
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 START (0) Change state to AUTHCHECK (2) last state RUN (20)

*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)

*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) DHCP required on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1for this client
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Feb 29 00:14:09.999: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:1c:0e:27:f3:30 vapId 1 apVapId 1
*apfMsConnTask_0: Feb 29 00:14:10.000: 5c:93:a2:d0:54:14 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

*apfMsConnTask_0: Feb 29 00:14:10.000: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds
*apfMsConnTask_0: Feb 29 00:14:10.000: 5c:93:a2:d0:54:14 Sending Assoc Response to station on BSSID 00:1c:0e:27:f3:30 (status 0) ApVapId 1 Slot 0
*apfMsConnTask_0: Feb 29 00:14:10.000: 5c:93:a2:d0:54:14 apfProcessAssocReq (apf_80211.c:5284) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Associated

*spamReceiveTask: Feb 29 00:14:10.003: 5c:93:a2:d0:54:14 Sent 1x initiate message to multi thread task for mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.007: 5c:93:a2:d0:54:14 Creating a PKC PMKID Cache entry for station 5c:93:a2:d0:54:14 (RSN 2)
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 Adding BSSID 00:1c:0e:27:f3:30 to PMKID cache for station 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010:      [0000] 43 4a 40 6f 4a 1a 11 c6 34 b4 90 2d c9 9e 89 c7

*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 Initiating RSN PSK to mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 dot1x - moving mobile 5c:93:a2:d0:54:14 into Force Auth state
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 Skipping EAP-Success to mobile 5c:93:a2:d0:54:14
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010:      [0000] 43 4a 40 6f 4a 1a 11 c6 34 b4 90 2d c9 9e 89 c7

*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 Starting key exchange to mobile 5c:93:a2:d0:54:14, data packets will be dropped
*Dot1x_NW_MsgTask_0: Feb 29 00:14:10.010: 5c:93:a2:d0:54:14 Sending EAPOL-Key Message to mobile 5c:93:a2:d0:54:14
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*pemReceiveTask: Feb 29 00:14:10.021: 5c:93:a2:d0:54:14 192.168.0.103 Removed NPU entry.
*osapiBsnTimer: Feb 29 00:14:11.120: 5c:93:a2:d0:54:14 802.1x 'timeoutEvt' Timer expired for station 5c:93:a2:d0:54:14 and for message = M2
*dot1xMsgTask: Feb 29 00:14:11.120: 5c:93:a2:d0:54:14 Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 5c:93:a2:d0:54:14
*osapiBsnTimer: Feb 29 00:14:12.120: 5c:93:a2:d0:54:14 802.1x 'timeoutEvt' Timer expired for station 5c:93:a2:d0:54:14 and for message = M2
*dot1xMsgTask: Feb 29 00:14:12.120: 5c:93:a2:d0:54:14 Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 5c:93:a2:d0:54:14
*osapiBsnTimer: Feb 29 00:14:13.120: 5c:93:a2:d0:54:14 802.1x 'timeoutEvt' Timer expired for station 5c:93:a2:d0:54:14 and for message = M2
*dot1xMsgTask: Feb 29 00:14:13.120: 5c:93:a2:d0:54:14 Retransmit failure for EAPOL-Key M1 to mobile 5c:93:a2:d0:54:14, retransmit count 3, mscb deauth count 0
*dot1xMsgTask: Feb 29 00:14:13.122: 5c:93:a2:d0:54:14 Sent Deauthenticate to mobile on BSSID 00:1c:0e:27:f3:30 slot 0(caller 1x_ptsm.c:534)
*dot1xMsgTask: Feb 29 00:14:13.122: 5c:93:a2:d0:54:14 Deleting the PMK cache when de-authenticating the client.
*dot1xMsgTask: Feb 29 00:14:13.122: 5c:93:a2:d0:54:14 Global PMK Cache deletion failed.
*dot1xMsgTask: Feb 29 00:14:13.122: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 57) in 10 seconds
*emWeb: Feb 29 00:14:10.274: %AAA-5-AAA_AUTH_ADMIN_USER: aaa.c:1383 Authentication succeeded for admin user 'cisco'[...It occurred 2 times/sec!.]

*dot1xMsgTask: Feb 29 00:14:13.120: %DOT1X-3-MAX_EAPOL_KEY_RETRANS: 1x_ptsm.c:444 Max EAPOL-key M1 retransmissions exceeded for client 5c:93:a2:d0:54:14
*emWeb: Feb 29 00:14:19.255: %AAA-5-AAA_AUTH_ADMIN_USER: aaa.c:1383 Authentication succeeded for admin user 'cisco'
*osapiBsnTimer: Feb 29 00:14:23.119: 5c:93:a2:d0:54:14 apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!
*apfReceiveTask: Feb 29 00:14:23.119: 5c:93:a2:d0:54:14 apfMsExpireMobileStation (apf_ms.c:5022) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Disassociated

*apfReceiveTask: Feb 29 00:14:23.119: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds

(Cisco Controller) >*osapiBsnTimer: Feb 29 00:14:33.117: 5c:93:a2:d0:54:14 apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!
*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 Sent Deauthenticate to mobile on BSSID 00:1c:0e:27:f3:30 slot 0(caller apf_ms.c:5114)
*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 Deleting the PMK cache when de-authenticating the client.
*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 Global PMK Cache deletion failed.
*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 apfMsAssoStateDec
*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 apfMsExpireMobileStation (apf_ms.c:5152) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Disassociated to Idle

*apfReceiveTask: Feb 29 00:14:33.119: 5c:93:a2:d0:54:14 Scheduling deletion of Mobile Station:  (callerId: 47) in 10 seconds

*osapiBsnTimer: Feb 29 00:14:43.115: 5c:93:a2:d0:54:14 apfMsExpireCallback (apf_ms.c:609) Expiring Mobile!
*apfReceiveTask: Feb 29 00:14:43.116: 5c:93:a2:d0:54:14 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Feb 29 00:14:43.116: 5c:93:a2:d0:54:14 192.168.0.103 8021X_REQD (3) Deleted mobile LWAPP rule on AP [00:1c:0e:27:f3:30]
*apfReceiveTask: Feb 29 00:14:43.116: 5c:93:a2:d0:54:14 Deleting mobile on AP 00:1c:0e:27:f3:30(0)

The following traps are generated.

out-of-range-deauth

Example 4

When station leaves the WLAN range for the period longer than 5 minutes (by default) it is deauthenticated by WLC

*apfReceiveTask: Feb 29 00:34:45.204: 5c:93:a2:d0:54:14 apfMsExpireMobileStation (apf_ms.c:5022) Changing state for mobile 5c:93:a2:d0:54:14 on AP 00:1c:0e:27:f3:30 from Associated to Disassociated

*apfReceiveTask: Feb 29 00:34:45.205: 5c:93:a2:d0:54:14 Sent Deauthenticate to mobile on BSSID 00:1c:0e:27:f3:30 slot 0(caller apf_ms.c:5114)
*apfReceiveTask: Feb 29 00:34:45.205: 5c:93:a2:d0:54:14 Deleting the PMK cache when de-authenticating the client.

The following trap is generated.
out-of-range-trap-5-min

Sources

1. WLC – understanding debug
2. Logging to syslog

Leave a Reply

Your email address will not be published. Required fields are marked *