无线 : 思科 2500 系列无线控制器

了解在无线局域网控制器(WLC)上的调试客户端

2015 年 8 月 28 日 - 机器翻译
其他版本: PDFpdf | 英语 (2015 年 4 月 22 日) | 反馈


目录


简介

本文档提供了有关无线 LAN 控制器上的 debug client 命令输出的详细信息。

本文档涉及以下主题:

  • 如何处理无线客户端

  • 基本关联和认证问题故障排除

所分析的输出涉及 WPA 预共享密钥 (WPA-PSK) 网络方案。

先决条件

要求

Cisco 建议您了解以下主题:

  • 如何针对基本运行来配置无线 LAN 控制器 (WLC) 和轻量接入点 (LAP)

  • 轻量接入点协议 (LWAPP) 和无线安全方法

  • 802.11 认证和关联过程的工作方式

使用的组件

本文档中的信息基于以下软件和硬件版本:

  • 运行固件 4.1 或 4.2 的 Cisco 2000/2100/4400 系列 WLC

  • 基于 LWAPP 的接入点

本文档中的信息都是基于特定实验室环境中的设备编写的。本文档中使用的所有设备最初均采用原始(默认)配置。如果您使用的是真实网络,请确保您已经了解所有命令的潜在影响。

规则

有关文档规则的详细信息,请参阅 Cisco 技术提示规则

Debug Client

命令 debug client <MACADDRESS> 是一个可启用 8 个 debug 命令的宏,此外还提供了一个 MAC 地址过滤器,以便仅显示包含指定 MAC 地址的消息。8 个 debug 命令显示了关于客户端关联和认证的最重要详细信息。在有多个无线客户端的情况下,该过滤器十分有用。例如,如果未使用该过滤器,在启用调试后可能会生成过多输出或使控制器超载。

所收集的信息涉及关于客户端关联和认证的重要详细信息(有两个例外情况,本文后面会进行介绍)。

已启用的命令显示在以下输出中:

(Cisco Controller) >show debug
 
MAC address ................................ 00:00:00:00:00:00
 
Debug Flags Enabled:
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled.
  dot1x events enabled.
  dot1x states enabled.
  pem events enabled.
  pem state enabled.

这些命令涉及地址协商、802.11 客户端状态机、802.1x 认证、策略执行模块 (PEM) 和地址协商 (DHCP)。

Debug Client 的变化形式

对于大多数情况,使用 debug client <MACAddress> 便足以获取所需信息。不过,有两种需要其他调试的重要情况:

移动性

在这种情况下,需要在引入 debug client <MACAddress> 命令之后启用移动调试,以便获取有关控制器之间的移动协议交互的附加信息。

注意: 以后会有文档介绍此输出的详细信息。

为了启用移动调试,可使用 debug client <MACAddress>,然后使用 debug mobility handoff enable 命令:

(Cisco Controller) >debug client 00:00:00:00:00:00
 
(Cisco Controller) >debug mobility handoff enable 

(Cisco Controller) >show debug

MAC address ................................ 00:00:00:00:00:00

Debug Flags Enabled:
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled
  dot1x events enabled.
  dot1x states enabled.
  mobility handoff enabled.
  pem events enabled.
  pem state enabled.

EAP 认证故障排除

为了对 WLC 与认证服务器(外部 RADIUS 或内部 EAP 服务器)之间的交互进行故障排除,可使用命令 debug AAA all enable,此命令将显示所需的详细信息。此命令应在 debug client <MACAddress> 命令的后面使用,并且可根据需要与其他 debug 命令(例如,handoff)结合使用。

(Cisco Controller) >debug client 00:00:00:00:00:00
(Cisco Controller) >debug aaa all enable 
(Cisco Controller) >show debug
MAC address ................................ 00:00:00:00:00:00
Debug Flags Enabled:
  aaa detail enabled.
  aaa events enabled.
  aaa packet enabled.
  aaa packet enabled.
  aaa ldap enabled.
  aaa local-auth db enabled.
  aaa local-auth eap framework errors enabled.
  aaa local-auth eap framework events enabled.
  aaa local-auth eap framework packets enabled.
  aaa local-auth eap framework state machine enabled.
  aaa local-auth eap method errors enabled.
  aaa local-auth eap method events enabled.
  aaa local-auth eap method packets enabled.
  aaa local-auth eap method state machine enabled.
  aaa local-auth shim enabled.
  aaa tacacs enabled.
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled
  dot1x events enabled
  dot1x states enabled.
  mobility handoff enabled.
  pem events enabled.
  pem state enabled.

客户端连接

在本文档中,客户端连接 就是无线客户端完成以下步骤的过程:

802.11 部分

  1. 探测以发现要关联的有效 AP。

  2. 验证:可以是 Open (null) 或 Shared。通常选择 Open。

  3. 关联:向 AP 请求数据服务。

L2 策略部分

  1. 无;根据具体配置,进行 PSK 或 EAP 认证。

  2. 密钥协商,如果选择了加密方法。

L3 策略部分

  1. 地址识别。

  2. Web 认证,如果已选择。

注意: 这些步骤代表完整过程的一个子集或摘要。本文档介绍了一个涉及 802.11 和 L2 策略并使用 WPA-PSK 和地址识别的简化情况。未使用外部 AAA 或 L3 认证策略。

控制器进程

在每个部分中,控制器都使用多个分隔的进程,以便跟踪客户端在每个时刻的状态。各个进程相互进行交互,以确保将客户端添加到连接表中(根据配置的安全策略)。为了了解客户端到控制器的连接步骤,下面提供了最相关过程的简短摘要:

  • 策略执行模块 (PEM) — 控制客户端状态,并强制客户端根据 WLAN 配置执行每个安全策略。

  • 接入点功能 (APF) — 基本上是 802.11 状态机。

  • Dot1x — 实现 802.1x 的状态机、PSK 认证和无线客户端的密钥处理。

  • 移动性 — 跟踪与同一移动组中其他控制器的交互。

  • 数据转换层 (DTL) — 位于软件组件与网络硬件加速 (NPU) 之间;控制 ARP 信息。

策略执行模块 (PEM)

基于 WLAN 配置,客户端执行一系列步骤。PEM 确保按顺序执行这一过程,以便符合必需的 L2 和 L3 安全策略。

下面是与客户端调试分析相关的 PEM 状态的一个子集:

  • 开始—新的客户端条目的最初的状态。

  • AUTHCHECK — WLAN 具有要强制执行的 L2 认证策略。

  • 8021X_REQD —客户端必须完成802.1x验证。

  • L2AUTHCOMPLETE —客户端顺利地完成L2策略。该进程现在可继续执行 L3 策略(地址识别、Web 认证等)。此时,控制器发送移动声明以从其他控制器获得 L3 信息(如果这是位于同一移动组中的漫游客户端)。

  • WEP_REQD —客户端必须完成WEP身份验证。

  • DHCP_REQD —控制器需要了解从客户端的L3地址,由ARP请求完成, DHCP请求或由从在移动组的其他控制器了解的信息更新,或者。如果 WLAN 上标记有 DHCP Required,则仅使用 DHCP 或移动信息。

  • WEBAUTH_REQD —客户端必须完成Web验证。(L3 策略)

  • RAN —客户端顺利地完成需要的L2和L3策略,并且能当前传输流量到网络。

下图显示了一个简化的 PEM 状态机,它带有客户端转换,直到达到 RUN 状态,在此状态下,客户端可向网络发送流量:

http://www.cisco.com/c/dam/en/us/support/docs/wireless/aironet-1200-series/100260-wlc-debug-client004.gif

注意: 此图未包括所有可能的转换和状态。为清楚起见,某些中间步骤已删除。

客户端流量转发

在 START 状态和最终 RUN 状态之间,客户端流量不会转发到网络,而是传递到控制器上的主 CPU 以进行分析。所转发的信息取决于状态和现有策略;例如,如果启用了 802.1x,则将 EAPOL 流量转发到 CPU。另一个例子是,如果使用了 Web 认证,则 HTTP 和 DNS 将被允许,并由 CPU 拦截以执行 Web 重定向并获取客户端认证凭证。

当客户端达到 RUN 状态时,客户端信息将发送到 NPU,以便启用 FastPath 交换,这会将用户流量以线速转发到客户端 VLAN,并解除中央 CPU 的用户数据转发任务。

所转发的流量取决于应用于 NPU 的客户端类型。下表描述了最相关的类型:

类型 说明
1 正常客户端流量转发。
9 IP 识别状态。为了识别所使用的 IP 地址,将从此客户端向 CPU 发送一个数据包。
2 ACL 直通。当 WLAN 是一个已配置为通知 NPU 的 ACL 时使用。

接入点功能 (APF)

此进程通过 802.11 状态机来处理客户端的状态,并与移动代码交互以验证不同的漫游方案。本文档不涉及移动性详细情况或其状态。

下表显示了在客户端与控制器关联期间进入的更多相关客户端状态:

名称 说明
空闲 新客户端,或某些情况下的临时状态。
AAA 挂起 客户端正在等待 MAC 地址认证。
已验证 开放式认证成功,或某些情况下的中间状态。
已关联 客户端成功通过 MAC 认证和开放式认证进程。
不相关 客户端发送了解除关联/取消认证,或关联计时器已过期。
删除 已将客户端标记为删除(通常在排除计时器过期之后)。
探测器 已收到新客户端的探测请求。
已排除/列入黑名单 已将客户端标记为排除。通常与 WPS 策略有关。
无效 客户端状态存在错误。

下图表示一个状态机转换,它仅显示出最相关的状态和转换:

http://www.cisco.com/c/dam/en/us/support/docs/wireless/aironet-1200-series/100260-wlc-debug-client002.gif

802.1x 认证 (Dot1x)

Dot1x 进程负责 802.1x 认证以及客户端的密钥管理。这意味着,即使在不具有需要 802.1x 的 EAP 策略的 WLAN 上,Dot1x 也会参与处理密钥创建和与客户端的协商,并且还进行缓存密钥处理(PMK 或 CCKM)。

此状态机显示完整 802.1x 转换:

http://www.cisco.com/c/dam/en/us/support/docs/wireless/aironet-1200-series/100260-wlc-debug-client008.gif

Debug Client 分析


APF Process


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Adding mobile on LWAPP AP 
    00:1c:0j:ca:5f:c0(0) 

!--- A new station is received. After validating type, it is added to the 
!--- AP that received it. This can happen both on processing association 
!--- request or probe requests


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds

!--- Sets an expiration timer for this entry in case it does not progress 
!--- beyond probe status. 5 Seconds corresponds to Probe Timeout. This message 
!--- might appear with other time values since, during client processing,    
!--- other functions might set different timeouts depending on state.


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 apfProcessProbeReq 
    (apf_80211.c:4057) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:0j:ca:5f:c0 from Idle to Probe

!--- APF state machine is updated.


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client. IMPORTANT:  
!--- Access points do not forward all probe requests to the controller; they
!--- summarize per time interval (by default 500 msec). This information is  
!--- used later by location and load balancing processes.


Wed Oct 31 10:46:14 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:14 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Association received from 
    mobile on AP 00:1c:0j:ca:5f:c0

!--- Access point reports an association request from the client. 
!--- When the process reaches this point, the client is not excluded and not  
!--- in mobility intermediate state


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 STA - rates (8): 140 18 152 
    36 176 72 96 108 0 0 0 0 0 0 0 0

!--- Controller saves the client supported rates into its connection table. 
!--- Units are values of 500 kbps, basic (mandatory) rates have the Most Significant bit (MSb) set. 
!--- The above would be 6mbps basic, 9, 12 basic, 18, 24 basic, 36, 48, 54


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Processing WPA IE type 221, 
    length 24 for mobile 00:1b:77:42:07:69

!--- Controller validates the 802.11i security information element.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Deleted mobile 
    LWAPP rule on AP [00:1c:0j:ca:5f:c0]

!--- As the client requests new association, APF requests to PEM to delete the  
!--- client state and remove any traffic forwarding rules that it could have.



APF Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Updated location for station old 
    AP 00:00:00:00:00:00-0, new AP 00:1c:0j:ca:5f:c0-1

!--- APF updates where this client is located. For example, this client is 
!--- a new addition; therefore, no value exists for the old location.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Initializing 
    policy

!--- PEM notifies that this is a new user. Security policies are checked 
!--- for enforcement.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Change state 
    to AUTHCHECK (2) last state AUTHCHECK (2)

!--- PEM marks as authentication check needed.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 AUTHCHECK (2) Change 
    state to 8021X_REQD (3) last state 8021X_REQD 

!--- After the WLAN configuration is checked, the client will need either 
!--- 802.1x or PSK authentication


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Plumbed 
    mobile LWAPP rule on AP 00:1c:0j:ca:5f:c0

!--- PEM notifies the LWAPP component to add the new client on the AP with 
!--- a list of negotiated capabilities, rates, Qos, etc.



APF Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 apfPemAddUser2 (apf_policy.c:209) 
    Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:0j:ca:5f:c0 from 
    Probe to Associated

!--- APF notifies that client has been moved successfully into associated 
!--- state. 


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Stopping deletion of Mobile 
    Station: (callerId: 48)

!--- The expiration timer for client is removed, as now the session timeout 
!--- is taking place. This is also part of the above notification 
!--- (internal code callerId: 48).


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending Assoc Response to 
    station on BSSID 00:1c:0j:ca:5f:c0 (status 0)

!--- APF builds and sends the association response to client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 apfProcessAssocReq 
    (apf_80211.c:3838) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:0j:ca:5f:c0 from Associated to Associated

!--- The association response was sent successfully; now APF keeps the 
!--- client in associated state and sets the association timestamp on this point.



Dot1x Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Creating a new PMK Cache Entry 
    for station 00:1b:77:42:07:69 (RSN 0)

!--- APF calls Dot1x to allocate a new PMK cached entry for the client.  
!--- RSN is disabled (zero value).


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Initiating WPA PSK to mobile 
    00:1b:77:42:07:69

!--- Dot1x signals a new WPA or WPA2 PSK exchange with mobile.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 dot1x - moving mobile 
    00:1b:77:42:07:69 into 
    Force Auth state

!--- As no EAPOL authentication takes place, the client port is marked as 
!--- forced Auth. Dot1x performs key negotiation with PSK clients only.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Skipping EAP-Success to mobile 
    00:1b:77:42:07:69

!--- For PSK, CCKM or RSN, the EAP success is not sent to client, as there 
!--- was no EAPOL authentication taking place.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 
    00:1b:77:42:07:69

   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

!--- Dot1x starts the exchange to arrive into PTK. PMK is known, as this 
!--- is PSK auth. First message is ANonce.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Message received from client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69

!--- This signals the start of the validation of the second message 
!--- from client (SNonce+MIC). No errors are shown, so process continues. 
!--- Potential errors at this point could be: deflection attack (ACK bit 
!--- not set on key), MIC errors, invalid key type, invalid key length, etc.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Dot1x got an answer for message 1, so retransmission timeout is stopped.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69

   state PTKINITNEGOTIATING (message 3), replay counter 
    00.00.00.00.00.00.00.01

!--- Derive PTK; send GTK + MIC.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Message received from client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-key in 
    PTKINITNEGOTIATING state (message 4) from mobile 00:1b:77:42:07:69

!--- This signals the start of validation of message 4 (MIC), which 
!--- means client installed the keys. Potential errors after this message 
!--- are MIC validation errors, invalid key types, etc.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Change 
    state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

!--- PEM receives notification and signals the state machine to change to L2   
!--- authentication completed.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 L2AUTHCOMPLETE (4) 
    Plumbed mobile LWAPP rule on AP 00:1c:0j:ca:5f:c0

!--- PEM pushes client status and keys to AP through LWAPP component.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 L2AUTHCOMPLETE (4) 
    Change state to DHCP_REQD (7) last state DHCP_REQD (7)

!--- PEM sets the client on address learning status.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    pemAdvanceState2 4238, Adding TMP rule

!--- PEM signals NPU to allow DHCP/ARP traffic to be inspected by controller   
!--- for the address learning.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Adding Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

!--- Entry is built for client and prepared to be forwarded to NPU.   
!--- Type is 9 (see the table in the Client Traffic Forwarding section of 
!--- this document) to allow controller to learn the IP address.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Successfully plumbed mobile rule (ACL ID 255)

!--- A new rule is successfully sent to internal queue to add the client 
!--- to the NPU.



Dot1x Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Dot1x received message from client.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69

   state PTKINITDONE (message 5 - group), replay counter 
    00.00.00.00.00.00.00.02

!--- Group key update prepared for client.



PEM Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 Added NPU entry of type 9

!--- NPU reports that entry of type 9 is added (learning address state).
!--- See the table in the Client Traffic Forwarding section of this document.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent an XID frame

!--- No address known yet, so the controller sends only  XID frame 
!--- (destination broadcast, source client address, control 0xAF).



Dot1x Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent EAPOL-Key M5 for mobile 
    00:1b:77:42:07:69

!--- Key update sent.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Key received.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Received EAPOL-key in 
    REKEYNEGOTIATING state (message 6) from mobile 00:1b:77:42:07:69

!--- Successfully received group key update.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Group key timeout is removed.



DHCP Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST 
    (1) (len 308, port 1, encap 0xec03)

!--- First DHCP message received from client.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 DHCP dropping packet due to 
    ongoing mobility handshake exchange, (siaddr 0.0.0.0,  mobility 
    state = 'apfMsMmQueryRequested'


PEM Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 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 = 192.168.100.11

!--- NPU is notified that this controller is the local anchor, so to 
!--- terminate any previous mobility tunnel. As this is a new client, 
!--- old address is empty.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) State 
    Update from Mobility-Incomplete to Mobility-Complete, mobility 
    role=Local

!--- Role change was successful.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    pemAdvanceState2 3934, Adding TMP rule

!--- Adding temporary rule to NPU for address learning now with new mobility 
!--- role as local controller.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Replacing Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

!--- Entry is built.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7)  
    Successfully plumbed mobile rule (ACL ID 255)

!--- A new rule is successfully sent to internal queue to add the 
!--- client to the NPU.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 Added NPU entry of type 9

!--- Client is on address learning state; see the table in the 
!--- Client Traffic Forwarding section of this document. Now mobility 
!--- has finished.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent an XID frame

!--- No address known yet, so controller sends only XID frame (destination 
!--- broadcast, source client address, control 0xAF).



DHCP Process


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST 
    (1) (len 308, port 1, encap 0xec03)

!--- DHCP request from client.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selecting relay 1 -  
    control block settings:

                    dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0  VLAN: 0

!--- Based on the WLAN configuration, the controller selects the identity to 
!--- use to  relay the DHCP messages.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selected relay 1 -  
    192.168.100.254 (local address 192.168.100.11, gateway 192.168.100.254, 
    VLAN 100, port 1)

!--- Interface selected.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP  
    transmitting DHCP DISCOVER (1)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 1024, flags: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 192.168.100.11

!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP sending REQUEST to  
    192.168.100.254 (len 350, port 1, vlan 100)


!--- DHCP request forwarded.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selecting relay 2 -  
    control block settings:

                    dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selected relay 2 ? NONE

!--- No secondary server configured, so no additional DHCP request are 
!--- prepared (configuration dependant).


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREPLY (2)  
    (len 308, port 1, encap 0xec00)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP setting server from OFFER  
    (server 192.168.100.254, yiaddr 192.168.100.105)

!--- DHCP received for a known server. Controller discards any offer not on 
!--- the DHCP server list for the WLAN/Interface.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP sending REPLY to STA  
    (len 416, port 1, vlan 100)

!--- After building the DHCP reply for client, it is sent to AP for forwarding.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP OFFER (2)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 0, flags: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 192.168.100.105

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 0.0.0.0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    server id: 1.1.1.1  rcvd server id: 192.168.100.254


!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST (1) 
    (len 316, port 1, encap 0xec03)

!--- Client answers


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selecting relay 1 -  
    control block settings:

                    dhcpServer: 192.168.100.254, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selected relay 1 -
    192.168.100.254 (local address 192.168.100.11, gateway 192.168.100.254, 
    VLAN 100, port 1)

!--- DHCP relay selected per WLAN config


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP REQUEST (3)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 1024, flags: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 192.168.100.11

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    requested ip: 192.168.100.105

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    server id: 192.168.100.254  rcvd server id: 1.1.1.1

!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP sending REQUEST to  
    192.168.100.254 (len 358, port 1, vlan 100)

!--- Request sent to server.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selecting relay 2 -  
    control block settings:

                    dhcpServer: 192.168.100.254, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selected relay 2 ? NONE

!--- No other DHCP server configured.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP received op BOOTREPLY  
    (2) (len 308, port 1, encap 0xec00)

!--- Server sends a DHCP reply, most probably an ACK (see below).



PEM Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 DHCP_REQD  
    (7) Change state to RUN (20) last state RUN (20)

!--- DHCP negotiation successful, address is now known, and client  
!--- is moved to RUN status.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Reached PLUMBFASTPATH: from line 4699

!--- No L3 security; client entry is sent to NPU.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Replacing Fast Path rule

  type = Airespace AP Client

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Successfully plumbed mobile rule (ACL ID 255)


DHCP Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 Assigning Address  
    192.168.100.105 to mobile 

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP sending REPLY to STA  
    (len 416, port 1, vlan 100)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP ACK (5)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 0, flags: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 192.168.100.105

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 0.0.0.0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    server id: 1.1.1.1  rcvd server id: 192.168.100.254


PEM Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 Added NPU  
    entry of type 1


!--- Client is now successfully associated to controller.  
!--- Type is 1; see the table in the Client Traffic Forwarding  
!--- section of this document.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 Sending a gratuitous ARP for  
    192.168.100.105, VLAN Id 100

!--- As address is known, gratuitous ARP is sent to notify.

故障排除示例

客户端密码配置错误

此示例显示了一个具有不同 AP 功能的客户端。该客户端正在探测 SSID,但由于探测请求显示了一些不受支持的参数,该客户端不会进入到认证/关联阶段。具体而言,所产生的问题是使用 WPA 的客户端与通告仅支持 WPA2 的 AP 之间存在不匹配:

Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds
Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 apfProcessProbeReq 
    (apf_80211.c:4057) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:b0:ea:5f:c0 from Idle to Probe

!---  Controller adds the new client, moving into probing status

Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:38 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:38 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- AP is reporting probe activity every 500 ms as configured


Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 apfMsExpireCallback (apf_ms.c:433) 
    Expiring Mobile!
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Deleted mobile 
    LWAPP rule on AP [00:1c:b0:ea:5f:c0]
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 Deleting mobile on AP 
    00:1c:b0:ea:5f:c0(0)

!--- After 5 seconds of inactivity, client is deleted, never moved into 
!--- authentication or association phases.

预共享密钥错误

以下输出显示客户端正在尝试通过 WPA-PSK 向基础设施进行认证,但因客户端与控制器之间的预共享密钥不匹配而失败,从而造成将该客户端最终列入黑名单:

Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Adding mobile on LWAPP AP 
    00:1c:b0:ea:5f:c0(0) 
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfProcessProbeReq (apf_80211.c:
    4057) Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 
    from Idle to Probe
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Association received from mobile 
    on AP 00:1c:b0:ea:5f:c0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 STA - rates (8): 130 132 139 150 
    12 18 24 36 0 0 0 0 0 0 0 0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 STA - rates (12): 130 132 139 150 
    12 18 24 36 48 72 96 108 0 0 0 0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Processing WPA IE type 221, 
    length 24 for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) 
    Initializing policy
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Change state to 
    AUTHCHECK (2) last state AUTHCHECK (2)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 AUTHCHECK (2) Change 
    state to 8021X_REQD (3) last state 8021X_REQD (3)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Plumbed 
    mobile LWAPP rule on AP 00:1c:b0:ea:5f:c0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfPemAddUser2 (apf_policy.c:209) 
    Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 from 
    Probe to Associated
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Stopping deletion of Mobile 
    Station: (callerId: 48)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Sending Assoc Response to station 
    on BSSID 00:1c:b0:ea:5f:c0 (status 0)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfProcessAssocReq (apf_80211.c:
    3838) Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 
    from Associated to Associated
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Creating a new PMK Cache Entry 
    for station 00:1b:77:42:07:69 (RSN 0)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Initiating WPA PSK to mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 dot1x - moving mobile 
    00:1b:77:42:07:69 into Force Auth state
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Skipping EAP-Success to mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with 
    invalid MIC from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Retransmit 1 of EAPOL-Key M1 
    (length 99) for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with invalid 
    MIC from mobile 00:1b:77:42:07:69

!--- MIC error due to wrong preshared key


Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Retransmit 2 of EAPOL-Key M1 
    (length 99) for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with invalid 
    MIC from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 Retransmit failure for EAPOL-Key 
    M1 to mobile 00:1b:77:42:07:69, retransmit count 3, mscb deauth count 0
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 Sent Deauthenticate to mobile on 
    BSSID 00:1c:b0:ea:5f:c0 slot 0(caller 1x_ptsm.c:462)

!--- Client is deauthenticated, after three retries



!--- The process is repeated three times, until client is blacklisted

 
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Blacklisting (if enabled) mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 apfBlacklistMobileStationEntry2 
    (apf_ms.c:3560) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:b0:ea:5f:c0 from Associated to Exclusion-list (1)
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 44) in 10 seconds
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Change 
    state to START (0) last state 8021X_REQD (3)
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Reached FAILURE: 
    from line 3522
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 9) in 10 seconds

相关的思科支持社区讨论

思科支持社区是您提问、解答问题、分享建议以及与工作伙伴协作的论坛。


相关信息


Document ID: 100260