9800 の Trace ログを動作検証しながらモニタする

Kunitaka Matsumura · ‎2023-01-27

概要
動作例

概要

Cisco Catalyst 9800 シリーズの Wireless Controller (C9800)において、クライアントの無線接続不良の調査にはまずは Trace ログ(debugログ)の取得をし処理の詳細解析を行います。

Catalyst 9800 シリーズクライアントの接続問題の調査のためにまず取得するデバックログ

https://community.cisco.com/t5/-/-/ta-p/3948047

C9800 : RA Trace ログ取得時に複数の Mac アドレスを指定する方法

https://community.cisco.com/t5/-/-/ta-p/4661075

この Trace ログを確認するには、予めデバックコマンドなどを設定した状態で、問題事象確認後に 'show logging' コマンドで確認をしたりフラッシュ内部に保存されたファイルを回収するのが一般的です。一方で、検証をしながら出力されるログを確認したい場合もあるかと思います。

本ドキュメントでは、'show logging' と同等の出力内容を検証をしながらリアルタイムで確認できる'monitor logging' コマンドについて紹介しています。

なおこのドキュメントは以下のバージョンで確認を行った動作例となりますので、予めご了承下さい。

Hardware model : 9800-L

Software version : 17.6.4

動作例

まず、'debug platform condition feature wireless' で調査対象機器の MAC アドレスに対して Debug を設定します

9800L#debug platform condition feature wireless mac 7403.bdeb.10af

'debug platform condition start' コマンドで debug 出力を開始します

9800L#debug platform condition start

'monitor logging' コマンドでログ出力のモニタを開始します。

今回は設定している無線クライアントの Mac アドレスをフィルタに指定しています。

9800L#monitor logging profile wireless filter mac 7403.bdeb.10af

'show logging' コマンドと同じようにプロセス指定やフィルタなど様々オプションがあります。

9800L#monitor logging ?

filter specify filter for logs

level select logs above specific level

metadata CLI to display metadata for every log message

process show logs for specific processes

process-helper show logs for known process

profile show logs for specific profile

Mac アドレスを登録したクライアントが接続した際には、以下のように 'show logging' 出力と同等の結果がリアルタイムで確認できます。この間は他のコマンドの入力などはできません。

9800L#monitor logging profile wireless filter mac 7403.bdeb.10af

Displaying traces starting from 2023/01/27 05:33:49.000000. If no traces are present, the command will wait until one is.

2023/01/27 05:34:24.037436 {wncd_x_R0-0}{2}: [dot11] [17657]: (info): Failed to dot11 map external to internal ie type. Unsupported IE received, skip decode . IE Type :199

2023/01/27 05:34:24.037446 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (note): MAC: 7403.bdeb.10af Association received. BSSID 04eb.409f.68ef, old BSSID 04eb.409f.68ef, WLAN kumatsum-D_Global_NF_81739f62, Slot 1 AP 04eb.409f.68e0, AP04EB.409E.2050

2023/01/27 05:34:24.037504 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af Received Dot11 association request. Processing started,SSID: kumatsum-DNAC, Policy profile: kumatsum-D_Global_NF_81739f62, AP Name: AP04EB.409E.2050, Ap Mac Address: 04eb.409f.68e0BSSID MAC04eb.409f.68efwlan ID: 18RSSI: -36, SNR: 61

2023/01/27 05:34:24.037653 {wncd_x_R0-0}{2}: [aaa-attr-inf] [17657]: (info): [ Applied attribute :bsn-vlan-interface-name 0 "178" ]

2023/01/27 05:34:24.037655 {wncd_x_R0-0}{2}: [aaa-attr-inf] [17657]: (info): [ Applied attribute : timeout 0 1800 (0x708) ]

2023/01/27 05:34:24.037663 {wncd_x_R0-0}{2}: [auth-mgr] [17657]: (info): [0000.0000.0000:unknown] Reauth not required, ignore

2023/01/27 05:34:24.037669 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Client QoS run state handler

2023/01/27 05:34:24.037705 {wncd_x_R0-0}{2}: [rog-proxy-capwap] [17657]: (debug): Managed client RUN state notification: 7403.bdeb.10af

2023/01/27 05:34:24.037871 {wncd_x_R0-0}{2}: [dot11-validate] [17657]: (info): MAC: 7403.bdeb.10af Dot11 ie validate ext/supp rates. Validation Passed for Supported rates radio_type 2

2023/01/27 05:34:24.037872 {wncd_x_R0-0}{2}: [dot11-validate] [17657]: (ERR): MAC: 7403.bdeb.10af Failed to dot11 ie validate aironet ipaddr. Aironet ipaddr IE is not present in Assoc Request

2023/01/27 05:34:24.037876 {wncd_x_R0-0}{2}: [dot11-validate] [17657]: (info): MAC: 7403.bdeb.10af WiFi direct: Dot11 validate P2P IE. P2P IE not present.

2023/01/27 05:34:24.038163 {wncd_x_R0-0}{2}: [dot11] [17657]: (debug): MAC: 7403.bdeb.10af dot11 send association response. Framing association response with resp_status_code: 0

2023/01/27 05:34:24.038163 {wncd_x_R0-0}{2}: [dot11] [17657]: (info): MAC: 7403.bdeb.10af Dot11 capability privacy bit set TRUE

2023/01/27 05:34:24.038167 {wncd_x_R0-0}{2}: [dot11] [17657]: (debug): MAC: 7403.bdeb.10af Dot11 Capability info byte1 11, byte2: 11

2023/01/27 05:34:24.038191 {wncd_x_R0-0}{2}: [dot11-frame] [17657]: (info): MAC: 7403.bdeb.10af WiFi direct: skip build Assoc Resp with P2P IE: Wifi direct policy disabled

2023/01/27 05:34:24.038297 {wncd_x_R0-0}{2}: [dot11] [17657]: (info): MAC: 7403.bdeb.10af dot11 send association response. Sending assoc response of length: 130 with resp_status_code: 0, DOT11_STATUS: DOT11_STATUS_SUCCESS

2023/01/27 05:34:24.038307 {wncd_x_R0-0}{2}: [dot11] [17657]: (note): MAC: 7403.bdeb.10af Association success. AID 1, Roaming = False, WGB = False, 11r = False, 11w = False Fast roam = False

2023/01/27 05:34:24.038322 {wncd_x_R0-0}{2}: [dot11] [17657]: (info): MAC: 7403.bdeb.10af DOT11 state transition: S_DOT11_ASSOCIATED -> S_DOT11_ASSOCIATED

2023/01/27 05:34:24.038373 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af Station Dot11 association is successful.

2023/01/27 05:34:24.038643 {wncd_x_R0-0}{2}: [rog-proxy-capwap] [17657]: (debug): Managed client state notification: client left run state: 7403.bdeb.10af

2023/01/27 05:34:24.038649 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af Starting L2 authentication. Bssid in state machine:04eb.409f.68ef Bssid in request is:04eb.409f.68ef

2023/01/27 05:34:24.038669 {wncd_x_R0-0}{2}: [client-orch-state] [17657]: (note): MAC: 7403.bdeb.10af Client state transition: S_CO_RUN -> S_CO_L2_AUTH_IN_PROGRESS

2023/01/27 05:34:24.038956 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Client QoS add mobile cb

2023/01/27 05:34:24.038994 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af No QoS PM Name or QoS Level received from SANet for pm_dir:0. Check client is fastlane, otherwise set pm name to none

2023/01/27 05:34:24.039005 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af No QoS PM Name or QoS Level received from SANet for pm_dir:1. Check client is fastlane, otherwise set pm name to none

2023/01/27 05:34:24.039044 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Build AAA QoS Params for addMobile: aaa_avgdtus:0, aaa_avgrtdtus:0, aaa_bstdtus:0, aaa_bstrtdtus:0, aaa_avgdtds:0, aaa_avgrtdtds:0, aaa_bstdtds:0, aaa_bstrtdtds:0, aaa_sig:1431655765

2023/01/27 05:34:24.039046 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Qos rate-limit parameters encoded successfully in addMobile payload from qos addMobile callback

2023/01/27 05:34:24.039073 {wncd_x_R0-0}{2}: [client-auth] [17657]: (note): MAC: 7403.bdeb.10af ADD MOBILE sent. Client state flags: 0x71 BSSID: MAC: 04eb.409f.68ef capwap IFID: 0x90000008

2023/01/27 05:34:24.039172 {wncd_x_R0-0}{2}: [client-auth] [17657]: (info): MAC: 7403.bdeb.10af Client auth-interface state transition: S_AUTHIF_PSK_AUTH_DONE -> S_AUTHIF_ADD_MOBILE_ACK_WAIT_KM

2023/01/27 05:34:24.042959 {wncd_x_R0-0}{2}: [client-auth] [17657]: (info): MAC: 7403.bdeb.10af Client auth-interface state transition: S_AUTHIF_ADD_MOBILE_ACK_WAIT_KM -> S_AUTHIF_PSK_AUTH_KEY_XCHNG_PENDING

2023/01/27 05:34:24.043060 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af EAP key M1 Sent successfully

2023/01/27 05:34:24.043129 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af Client key-mgmt state transition: S_PTKINITDONE -> S_PTK_START

2023/01/27 05:34:24.049096 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af M2 Status: EAP key M2 validation success

2023/01/27 05:34:24.049258 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af EAP key M3 Sent successfully

2023/01/27 05:34:24.049259 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af Client key-mgmt state transition: S_PTK_START -> S_PTKINITNEGOTIATING

2023/01/27 05:34:24.054238 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af M4 Status: EAP key M4 validation is successful

2023/01/27 05:34:24.054258 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (note): MAC: 7403.bdeb.10af EAP Key management successful. AKM:PSK Cipher:CCMP WPA Version: WPA2

2023/01/27 05:34:24.054270 {wncd_x_R0-0}{2}: [client-keymgmt] [17657]: (info): MAC: 7403.bdeb.10af Client key-mgmt state transition: S_PTKINITNEGOTIATING -> S_PTKINITDONE

2023/01/27 05:34:24.054415 {wncd_x_R0-0}{2}: [client-auth] [17657]: (note): MAC: 7403.bdeb.10af L2 PSK Authentication Success. EAP type: NA, Resolved VLAN: 178, Audit Session id: 000000000000002DF1B17AB7

2023/01/27 05:34:24.054440 {wncd_x_R0-0}{2}: [client-auth] [17657]: (info): MAC: 7403.bdeb.10af Client auth-interface state transition: S_AUTHIF_PSK_AUTH_KEY_XCHNG_PENDING -> S_AUTHIF_PSK_AUTH_DONE

2023/01/27 05:34:24.054457 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af L2 Authentication of station is successful., L3 Authentication : 0

2023/01/27 05:34:24.054851 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (note): MAC: 7403.bdeb.10af Mobility discovery triggered. Client mode: Local

2023/01/27 05:34:24.054854 {wncd_x_R0-0}{2}: [client-orch-state] [17657]: (note): MAC: 7403.bdeb.10af Client state transition: S_CO_L2_AUTH_IN_PROGRESS -> S_CO_MOBILITY_DISCOVERY_IN_PROGRESS

2023/01/27 05:34:24.055054 {wncd_x_R0-0}{2}: [mm-transition] [17657]: (info): MAC: 7403.bdeb.10af MMIF FSM transition: S_MA_LOCAL -> S_MA_LOCAL on E_MA_MOBILITY_DISCOVERY

2023/01/27 05:34:24.055055 {wncd_x_R0-0}{2}: [mm-client] [17657]: (debug): MAC: 7403.bdeb.10af Mobility Role is known. Responding to CO with mobility complete

2023/01/27 05:34:24.055056 {wncd_x_R0-0}{2}: [mm-client] [17657]: (info): MAC: 7403.bdeb.10af Mobility role changed - Local -> Local

2023/01/27 05:34:24.055056 {wncd_x_R0-0}{2}: [mm-client] [17657]: (info): MAC: 7403.bdeb.10af Sub Roam type changed - MM_SUB_ROAM_TYPE_INTRA_INSTANCE -> MM_SUB_ROAM_TYPE_INTRA_INSTANCE

2023/01/27 05:34:24.055074 {wncd_x_R0-0}{2}: [mm-client] [17657]: (note): MAC: 7403.bdeb.10af Mobility Successful. Roam Type None, Sub Roam Type MM_SUB_ROAM_TYPE_INTRA_INSTANCE, Client IFID: 0xa0000001, Client Role: Local PoA: 0x90000008 PoP: 0x0

2023/01/27 05:34:24.055170 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af Processing mobility response from MMIF. Client ifid: 0xa0000001, roam type: None, client role: Local

2023/01/27 05:34:24.055236 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Client QoS add mobile cb

2023/01/27 05:34:24.055277 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af No QoS PM Name or QoS Level received from SANet for pm_dir:0. Check client is fastlane, otherwise set pm name to none

2023/01/27 05:34:24.055287 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af No QoS PM Name or QoS Level received from SANet for pm_dir:1. Check client is fastlane, otherwise set pm name to none

2023/01/27 05:34:24.055324 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Build AAA QoS Params for addMobile: aaa_avgdtus:0, aaa_avgrtdtus:0, aaa_bstdtus:0, aaa_bstrtdtus:0, aaa_avgdtds:0, aaa_avgrtdtds:0, aaa_bstdtds:0, aaa_bstrtdtds:0, aaa_sig:1431655765

2023/01/27 05:34:24.055326 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Qos rate-limit parameters encoded successfully in addMobile payload from qos addMobile callback

2023/01/27 05:34:24.055349 {wncd_x_R0-0}{2}: [client-auth] [17657]: (note): MAC: 7403.bdeb.10af ADD MOBILE sent. Client state flags: 0x72 BSSID: MAC: 04eb.409f.68ef capwap IFID: 0x90000008

2023/01/27 05:34:24.055562 {wncd_x_R0-0}{2}: [client-orch-state] [17657]: (note): MAC: 7403.bdeb.10af Client state transition: S_CO_MOBILITY_DISCOVERY_IN_PROGRESS -> S_CO_DPATH_PLUMB_IN_PROGRESS

2023/01/27 05:34:24.055847 {wncd_x_R0-0}{2}: [client-orch-state] [17657]: (note): MAC: 7403.bdeb.10af Client state transition: S_CO_DPATH_PLUMB_IN_PROGRESS -> S_CO_IP_LEARN_IN_PROGRESS

2023/01/27 05:34:24.056065 {wncd_x_R0-0}{2}: [client-iplearn] [17657]: (info): MAC: 7403.bdeb.10af IP-learn state transition: S_IPLEARN_COMPLETE -> S_IPLEARN_COMPLETE

2023/01/27 05:34:24.056264 {wncd_x_R0-0}{2}: [client-orch-sm] [17657]: (debug): MAC: 7403.bdeb.10af Received ip learn response. method: IPLEARN_METHOD_DHCP

2023/01/27 05:34:24.056548 {wncd_x_R0-0}{2}: [aaa-attr-inf] [17657]: (info): [ Applied attribute :bsn-vlan-interface-name 0 "178" ]

2023/01/27 05:34:24.056550 {wncd_x_R0-0}{2}: [aaa-attr-inf] [17657]: (info): [ Applied attribute : timeout 0 1800 (0x708) ]

2023/01/27 05:34:24.056555 {wncd_x_R0-0}{2}: [auth-mgr] [17657]: (info): [0000.0000.0000:unknown] Reauth not required, ignore

2023/01/27 05:34:24.056564 {wncd_x_R0-0}{2}: [ewlc-qos-client] [17657]: (info): MAC: 7403.bdeb.10af Client QoS run state handler

2023/01/27 05:34:24.056583 {wncd_x_R0-0}{2}: [rog-proxy-capwap] [17657]: (debug): Managed client RUN state notification: 7403.bdeb.10af

2023/01/27 05:34:24.056612 {wncd_x_R0-0}{2}: [client-orch-state] [17657]: (note): MAC: 7403.bdeb.10af Client state transition: S_CO_IP_LEARN_IN_PROGRESS -> S_CO_RUN

Ctrl+c コマンドより、モニタ状態から解除され通常のコマンドプロンプトへ戻ります。

^CUser issued SIGINT

9800L#

最後に、debug の出力を停止し debug の設定の削除も行います

9800L#debug platform condition stop

9800L#clear platform condition all

9800L#undebug all