“debug client” の解析方法 : 無線 LAN トラブルシューティング

Hideyuki Osaki · ‎2016-01-21

はじめに

　CUWN の無線クライアントが接続できない、通信不可といった問題が起きたときのトラブルシューティングに便利なツールが WLC の “debug client” というコマンドです。この記事ではその使い方と出力の代表的な読み取り方説明をします。よりベーシックな内容については次の記事も参照してください。

無線クライアントが接続できないときに取得する基本ログと対応指針

クライアントが無事IP 通信できるようになるまでの流れ

　一般的にクライアントが WI-Fi を使って IP 通信が可能になるまでには、次のシーケンス図のように各機器の間でのメッセージのやりとりが必要です。

　このやりとりの中のどこかで失敗していると、通信ができません。このやりとりを詳細に追跡することができるコマンドが “debug client” です。

debug client の使い方

コマンドの文法:

debug client {クライアント 1 の MAC アドレス}  {クライアント 2 の MAC アドレス}  {クライアント 3 の MAC アドレス} ….  {クライアント 10 の MAC アドレス}

<使用例>
(CT5508) >debug client 11:22:33:44:55:66 abcd.efde.abcd abcd1234efab
 (CT5508) >show debug
 MAC Addr 1.................................. 11:22:33:44:55:66
 MAC Addr 2.................................. AB:CD:EF:DE:AB:CD
 MAC Addr 3.................................. AB:CD:12:34:EF:AB
Debug Flags Enabled:
   dhcp packet enabled.
   dot11 mobile enabled.
   dot11 state enabled
   dot1x events enabled.
   dot1x states enabled.
   mobility client handoff enabled.
   pem events enabled.
   pem state enabled.
   802.11r event debug enabled.
   802.11w event debug enabled.
   CCKM client debug enabled.

　この debug コマンドは WLC や AP にはほとんど負荷を与えませんので、サービス運用中でも問題なく使用できます。

　このコマンドは、指定した MAC アドレスを持つクライアントから Association Request を受信したときや、EAP 認証に失敗したときなど、なんらかのイベントが発生したときにのみ出力されます。正常に通信ができている場合は何も出力されません。したがってクライアントが接続する前に仕掛けておき、問題が起きるまで、あるいは問題が起きて復旧するまでの間、継続して出力を取得しておく必要があります。

debug client 出力からわかること

Association (レイヤ 2 関連) パート

Association received from mobile on AP 00:26:cb:94:44:c0
0.0.0.0 START (0) Changing ACL 'none' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1621)
Applying site-specific IPv6 override for station 00:16:ea:b2:04:36 - vapId 1, site 'default-group', interface ‘student'
Applying IPv6 Interface Policy for station 00:16:ea:b2:04:36 - vlan 3, interface id 8, interface ’student'

Association received : Association Request をクライアントから受信

Association なので、ローミングではない（Reassociation ではない)ことがわかります。

Radio MAC が 00:26:cb:94:44:c0 の AP に Association Request を送信したことを意味します。

vapId 1, site 'default-group', interface ‘student‘

vapId : WLAN ID 番号 (Wlan ID 1)

site : AP グループ (default-group)

Interface : インターフェイス名 (student)

vlan 3

vlan : インターフェイスに関連付けられた VLAN ID

STA - rates (12): 130 132 139 150 12 18 24 36 48 72 96 108 0 0 0 0
Processing RSN IE type 48, length 22 for mobile 00:16:ea:b2:04:36

STA - rates : データレート

Madatory レートは128以上で表示されます : 128 を減じた後に 2 で割ると本当の値がわかります。

Supported レートは 128未満で表示されます: 2 で割ると本当の値がわかります。

->1m,2m,5.5m,11m,6s,9s,12s,18s,24s,36s,48s,54s

Processing RSN IE type 48 ：暗号化方式

WPA2-AES は type 48 と表示されます。

Processing WPA IE type 221

WPA-TKIP は type 221 と表示されます。

PMK キャッシュと Mobility の確認パート

0.0.0.0 START (0) Initializing policy
 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)
 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)
 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 00:26:cb:94:44:c0 vapId 1 apVapId 1for this client
 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:26:cb:94:44:c0 vapId 1 apVapId 1
 apfMsAssoStateInc
 apfPemAddUser2 Changing state for mobile 00:16:ea:b2:04:36 on AP 00:26:cb:94:44:c0 from Idle to Associated
 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds

0.0.0.0 START

0.0.0.0 = 既に WLC のクライアントデータベースに情報がある場合、IP アドレスを表示します。0.0.0.0 なので IP アドレス情報は残っておらず、おそらく新規接続であることがわかります。

Change state to 8021X_REQD

802.11 の Association フェーズは通過し、次の段階 8021X_REQD に移ったことがわかります。

Scheduling deletion of Mobile Station

このクライアント (Mobile Station: MS) の WLAN セッションタイマーをセット (1800秒)したことがわかります。

Sending Assoc Response to station on BSSID 00:26:cb:94:44:c0 (status 0) ApVapId 1 Slot 0

Slot 0 : 802.11bgn(2.4GHz) Radio インターフェイス

なお Slot 1 は 802.11anac(5GHz) Radio インターフェイスを意味します。

Sending Assoc Response Status 0 = Success

Status 0 は 802.11 Association の成功を意味します。0 以外の値だと問題が発生しています。

Assoc Response Failures コードの一例:

コード	意味
1	Unknown Reason : 定義済みのコード以外の理由で失敗。 SSID の指定が Request 時になされていない等。
11	Reassociation 時に前回の Association 情報が見当たらない。
17	クライアント数が多過ぎる (Load Balancing)
18	クライアントが使っているデータレートと AP の間でミスマッチ
35	WLAN で WMM 必須となっているが、クライアントが WMM を非サポート
201	QoS Platinum ではない WLAN に Voice 端末が接続しようとしている
202	帯域不足のため CAC により新規音声通話を拒否

Association および Authentication 失敗時のコード表はこちらもご参照ください。

(英語)802.11 Association Status, 802.11 Deauth Reason codes

EAP / RADIUS 認証パート

Sending Assoc Response to station on BSSID 00:26:cb:94:44:c0 (status 0) ApVapId 1 Slot 0
Station 00:16:ea:b2:04:36 setting dot1x reauth timeout = 1800
 dot1x - moving mobile 00:16:ea:b2:04:36 into Connecting state
 Sending EAP-Request/Identity to mobile 00:16:ea:b2:04:36 (EAP Id 1) <<< AP が EAP Identity 送信
 Received EAPOL EAPPKT from mobile 00:16:ea:b2:04:36
 Username entry (cisco) created for mobile 
 Received Identity Response (count=1) from mobile 00:16:ea:b2:04:36 <<< クライアントから EAP Identity 受信
 EAP State update from Connecting to Authenticating for mobile 00:16:ea:b2:04:36
 dot1x - moving mobile 00:16:ea:b2:04:36 into Authenticating state
Entering Backend Auth Req state (id=3) for mobile 00:16:ea:b2:04:36 <<< “Backend Auth” は RADIUS のこと
 Sending EAP Request from AAA to mobile 00:16:ea:b2:04:36 (EAP Id 3) <<< RAIDUS サーバから EAP Request 受信
 Received EAPOL EAPPKT from mobile 00:16:ea:b2:04:36
 Received EAP Response from mobile 00:16:ea:b2:04:36 (EAP Id 3, EAP Type 25)　<<< クライアントから PEAP の EAP Response 受信
Received EAP Response from mobile 00:16:ea:b2:04:36 (EAP Id 10, EAP Type 25)
 Entering Backend Auth Response state for mobile 00:16:ea:b2:04:36
 Processing Access-Challenge for mobile 00:16:ea:b2:04:36
 Entering Backend Auth Req state (id=11) for mobile 00:16:ea:b2:04:36
 Sending EAP Request from AAA to mobile 00:16:ea:b2:04:36 (EAP Id 11)
 Received EAPOL EAPPKT from mobile 00:16:ea:b2:04:36
 Received EAP Response from mobile 00:16:ea:b2:04:36 (EAP Id 11, EAP Type 25)
 Entering Backend Auth Response state for mobile 00:16:ea:b2:04:36
 Processing Access-Accept for mobile 00:16:ea:b2:04:36 <<< RAIDUS サーバから Access Accept, 認証成功応答を受信
もしくは
 Processing Access-Reject for mobile 00:16:ea:b2:04:36 <<< RAIDUS サーバから Access Reject, 認証失敗応答を受信

EAP Type の番号対応表

EAP Type 番号	EAP Type
1	Identity
2	Notification
3	NAK
4	MD5
5	OTP
6	Generic Token
13	EAP-TLS
17	LEAP
18	EAP-SIM
21	EAP-TTLS
25	PEAP
43	EAP-FAST

EAPoL 4-way handshake 成功時 (PSK)

Sending Assoc Response to station on BSSID 00:26:cb:94:44:c0 (status 0) ApVapId 1 Slot 0
Creating a PKC PMKID Cache entry for station 00:16:ea:b2:04:36 (RSN 2)
Adding BSSID 00:26:cb:94:44:c0 to PMKID cache for station 00:16:ea:b2:04:36
New PMKID: (16)
            [0000] 31 d5 5b 0b 64 28 2b be c5 8d d5 4c 03 30 c7 cd
Initiating RSN PSK to mobile 00:16:ea:b2:04:36
dot1x - moving mobile 00:16:ea:b2:04:36 into Force Auth state
Skipping EAP-Success to mobile 00:16:ea:b2:04:36
Including PMKID in M1  (16)    
            [0000] 31 d5 5b 0b 64 28 2b be c5 8d d5 4c 03 30 c7 cd
Starting key exchange to mobile 00:16:ea:b2:04:36, data packets will be dropped
Sending EAPOL-Key Message to mobile 00:16:ea:b2:04:36   <<< AP がクライアントに EAPoL-Key Message 1 送信
            state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Received EAPOL-Key from mobile 00:16:ea:b2:04:36
Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:16:ea:b2:04:36
Received EAPOL-key in PTK_START state (message 2) from mobile 00:16:ea:b2:04:36 <<< クライアントから EAPoL-Key Message 2 受信
Stopping retransmission timer for mobile 00:16:ea:b2:04:36
Sending EAPOL-Key Message to mobile 00:16:ea:b2:04:36   <<< AP がクライアントに EAPoL-Key Message 3 送信
            state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
Received EAPOL-Key from mobile 00:16:ea:b2:04:36
Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:16:ea:b2:04:36
Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:16:ea:b2:04:36 <<< クライアントから EAPoL-Key Message 4 受信
apfMs1xStateInc
0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

EAPoL 4-way handshake 失敗時

Starting key exchange to mobile 00:1e:8c:0f:a4:57, data packets will be dropped
Sending EAPOL-Key Message to mobile 00:1e:8c:0f:a4:57
                              state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Received EAPOL-Key from mobile 00:1e:8c:0f:a4:57
Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:1e:8c:0f:a4:57
Received EAPOL-key in PTK_START state (message 2) from mobile 00:1e:8c:0f:a4:57
Received EAPOL-key M2 with invalid MIC from mobile 00:1e:8c:0f:a4:57
802.1x 'timeoutEvt' Timer expired for station 00:1e:8c:0f:a4:57
Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 00:1e:8c:0f:a4:57
Received EAPOL-Key from mobile 00:1e:8c:0f:a4:57
Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:1e:8c:0f:a4:57
Received EAPOL-key in PTK_START state (message 2) from mobile 00:1e:8c:0f:a4:57
Received EAPOL-key M2 with invalid MIC from mobile 00:1e:8c:0f:a4:57
802.1x 'timeoutEvt' Timer expired for station 00:1e:8c:0f:a4:57
Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 00:1e:8c:0f:a4:57
…………………
802.1x 'timeoutEvt' Timer expired for station 00:1e:8c:0f:a4:57
Retransmit failure for EAPOL-Key M1 to mobile 00:1e:8c:0f:a4:57, 
            retransmit count 3, mscb deauth count 3
Blacklisting (if enabled) mobile 00:1e:8c:0f:a4:57
apfBlacklistMobileStationEntry2 (apf_ms.c:4192) Changing state for mobile 00:1e:8c:0f:a4:57 on 
            AP 00:16:9c:4b:c4:c0          from Associated to Exclusion-list (1)

debug client の出力から想定できる原因の例

802.11 の問題

データレートが AP とクライアントでミスマッチしている。
Voice トラフィックの場合、帯域が不足していて CAC で拒否されている。
PMF (IEEE 802.11w) 設定がなされていて、相互接続性に問題がある。
IEEE 802.11k 設定がなされていて、相互接続性に問題がある。
IEEE 802.11r 設定がなされていて、相互接続性に問題がある。

L2 認証の問題

RADIUS による認証が失敗して Access Reject を受信している。あるいは RADIUS サーバが応答していない。
クライアントの暗号化の実装状態に不具合がある (4-way handshake で再送が多発)。
802.1X タイムアウト多発により Exclusion list に登録されてしまっている。
クライアントが PMKID を送信していない等、PMK キャッシング動作に問題がありローミングに失敗している。

DHCP の問題

DHCP DISCOVER/REQUEST をクライアントが送信していない。
DHCP OFFER/ACK を DHCP サーバから受信していない。

IP レイヤの問題

IP アドレスが重複している。
リンクローカルアドレス 169.254.x.x からクライアントが復帰してこない。

L3 認証の問題

クライアントがユーザ名とパスワードを Web 認証画面で入力するまでに時間がかかり過ぎている。

参考資料

CUWN トラブルシューティング, Webcast, July, 2014.

無線クライアントが接続できないときに取得する基本ログと対応指針