瞭解無線LAN控制器(WLC)上的偵錯使用者端

下載選項

PDF (572.8 KB)
在多種裝置上使用 Adobe Reader 檢視
ePub (226.7 KB)
在 iPhone、iPad、Android、Sony Reader 或 Windows Phone 上的各種應用程式中檢視
Mobi (Kindle) (256.3 KB)
在 Kindle 裝置或多部裝置的 Kindle 應用程式上檢視

已更新: 2023 年 5 月 4 日

文件 ID:100260

無偏見用語

本產品的文件集力求使用無偏見用語。針對本文件集的目的，無偏見係定義為未根據年齡、身心障礙、性別、種族身分、民族身分、性別傾向、社會經濟地位及交織性表示歧視的用語。由於本產品軟體使用者介面中硬式編碼的語言、根據 RFP 文件使用的語言，或引用第三方產品的語言，因此本文件中可能會出現例外狀況。深入瞭解思科如何使用包容性用語。

關於此翻譯

思科已使用電腦和人工技術翻譯本文件，讓全世界的使用者能夠以自己的語言理解支援內容。請注意，即使是最佳機器翻譯，也不如專業譯者翻譯的內容準確。Cisco Systems, Inc. 對這些翻譯的準確度概不負責，並建議一律查看原始英文文件（提供連結）。

簡介

本文檔介紹有關 debug client 無線LAN控制器(WLC)上的命令輸出。

必要條件

需求

本檔案介紹以下主題：

無線客戶端的處理方式
如何解決基本關聯和身份驗證問題

要分析的輸出包括WPA預共用金鑰(WPA-PSK)網路的場景。

思科建議您瞭解以下主題：

如何設定WLC和輕量型存取點(LAP)以達成基本操作
輕量型存取點通訊協定(LWAPP)和無線安全方法
802.11身份驗證和關聯過程的工作原理

採用元件

本文中的資訊係根據以下軟體和硬體版本：

執行韌體8.5或8.10的Cisco AireOS WLC(8540、5520、vWLC)。
基於CAPWAP的接入點。

本文中的資訊是根據特定實驗室環境內的裝置所建立。文中使用到的所有裝置皆從已清除（預設）的組態來啟動。如果您的網路運作中，請確保您瞭解任何指令可能造成的影響。

慣例

如需文件慣例的詳細資訊，請參閱思科技術提示慣例。

調試客戶端

指令 debug client 是一個啟用八個debug命令的宏，外加一個針對所提供的MAC地址的篩選器，因此僅顯示包含指定MAC地址的消息。八個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 命令足以獲取所需資訊。但是，有兩種重要情況需要額外的偵錯：

行動化（控制器之間的客戶端漫遊）
排除EAP身份驗證故障

行動化

在這種情況下，需要在 debug client 已引入命令可取得有關控制器之間行動通訊協定互動的額外資訊。

註：有關此輸出的詳細資訊將在其它文檔中介紹。

要啟用移動調試，請使用 debug client 命令，然後使用 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 命令並可根據需要與其他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節

探測，查詢要關聯的有效接入點。
身份驗證：可以開啟（空）或共用。通常情況下，會選擇「開啟」。
關聯：向AP請求資料服務。

L2策略部分

無；根據配置進行PSK或EAP身份驗證。
如果選擇了加密方法，則金鑰協商。

L3策略部分

地址學習。
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狀態子集：

START — 新客戶端條目的初始狀態。
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策略）
運行 — 客戶端已成功完成所需的L2和L3策略，現在可以傳輸流量到網路。

此圖顯示一個簡化的PEM狀態機，使用者端會轉換到執行(RUN)狀態，此時使用者端可以將流量傳送到網路：

注意：此圖未涵蓋所有可能的過渡和狀態。為清楚起見，刪除了一些中間步驟。

客戶端流量轉發

在START狀態與最終RUN狀態之前，客戶端流量不會轉發到網路，而是會傳遞到控制器上的主CPU進行分析。轉發的資訊取決於狀態和現有的策略；例如，如果已啟用802.1x，則EAPOL流量將轉發到CPU。另一個範例是如果使用Web Auth，則CPU會允許和攔截HTTP和DNS以執行Web重新導向並獲得使用者端驗證憑證。

當客戶端達到RUN狀態時，會向NPU傳送客戶端資訊以啟用FastPath交換，該交換會執行以線纜速率將使用者流量轉發到客戶端VLAN並釋放使用者資料轉發任務的中央CPU。

轉發的流量取決於應用於NPU的客戶端型別。下表描述了最相關的型別：

類型	說明
1	正常客戶端流量轉發。
9	IP學習狀態。此使用者端的一個封包會傳送到CPU，以便瞭解使用的IP位址。
2	ACL傳輸。當WLAN是配置為通知NPU的ACL時使用。

存取點功能(APF)

此進程通過802.11機器狀態處理客戶端的狀態，並與移動代碼互動，以驗證不同的漫遊方案。本文檔不包括移動性詳細資訊或其狀態。

下表顯示當使用者端與控制器相關聯時可能會出現的更相關使用者端狀態：

名稱	說明
空閒	某些情況下新的客戶端或臨時狀態。
AAA吊墜	客戶端等待MAC地址身份驗證。
已驗證	在某些情況下，開放式身份驗證成功或處於中間狀態。
關聯	使用者端成功通過MAC驗證和開放驗證程式。
已取消關聯	客戶端已傳送取消關聯/取消身份驗證或關聯計時器已過期。
刪除	標籤為刪除的客戶端（通常在排除計時器過期後）。
探測	已收到新客戶端的探測請求。
已排除/已列出阻止	客戶端已標籤為已排除。通常與WPS策略相關。
無效	客戶端狀態出錯。

此影象表示狀態機轉換，並且只顯示最相關的狀態和轉換：

802.1x身份驗證(Dot1x)

Dot1x進程負責客戶端的802.1x身份驗證和金鑰管理。這意味著，即使在沒有需要802.1x的EAP策略的WLAN上，dot1x也會參與處理與客戶端的金鑰建立和協商以及快取的金鑰處理（PMK或CCKM）。

此狀態機顯示完整的802.1x轉換：

調試客戶端分析

本節顯示使用者端連線到WLAN時記錄中的完整程式。


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 that depend 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: x.x.x.x  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: x.x.x.x

!--- 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: x.x.x.x  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 block listed

 
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Block listing (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