[Secure Endpoint] Debugログ取得時の注意事項

Kenichiro Kato · ‎2018-10-16

はじめに
前提条件
Debugを設定した後で事象再現が必要
端末にDebugが設定されたタイミングからDebugは開始
古いログは上書きされる

はじめに

Connectorのトラブルシューティング時に、Cisco TACからDebugログ付きDiagnosticsの取得を依頼させていただいておりますが、適切にDebugログが取得できずに再度取得を依頼させていただく場合がございます。本記事では、そういった情報の取得漏れを防ぐべく、Debugログ取得時の注意事項について説明いたします。

前提条件

本記事は、Windows Connector 8.1.7にて動作確認しております。
基本的には本記事の内容はConnector 8.0.1以上であれば有効ですが、将来的に予告なく変更される場合がございます。

Debugを設定した後で事象再現が必要

Debugを設定した直後のDiagnosticsを取得しても、以下の通り、過去に発生したお事象のDebugログは取得することが出来ません。

以下のように、Debugが設定された後に、問題となっているお客様再現を発生させ、その後Diagnosticsを取得いただく必要がございます。

Debugログを設定する方法は大きく二つございます。

Connector上（Cisco Secure ClientのGUI画面から[⚙]マークをクリック -> [詳細]タブの画面から[デバッグロギングを有効にする]をクリック）から設定

Policy(ConsoleのManagement -> Policies)から設定。ほとんどの場合"Connector Log Level"のみDebugに設定する必要があります。Connector GUIに関するトラブルの場合のみTray Log LevelをDebugにする必要があります。

端末にDebugが設定されたタイミングからDebugは開始

Connector GUI上での設定は即時反映されますが、Policyから設定する場合、端末に新しいPolicyがダウンロードされるまで設定が反映されません。最大で端末がPolicyを取得するHeartbeat Intervalの時間分（デフォルト15分）を待つ必要があります。Debugが設定されたことを確認してから、事象を再現させ、Diagnosticsを取得してください。

Debugが設定されたかどうかの最も簡単な確認方法はsfc.exe.log (デフォルトではC:\Program Files\Cisco\AMP\<version>配下)を開いた際に、ERRORのレベルのログ以外が出てきていることです。
例えば、以下のようなERROR:の行のみが継続して出力される場合はDebugが設定されていないとほとんどの場合、判断が出来ます。

(31933, +0 ms) Sep 11 12:58:51 [412]: ERROR: _CloudConnectFailed: Connection failed threshold reached
(32822, +889 ms) Sep 11 12:58:52 [1268]: ERROR: Event::HandleExecution[1268]: look up of processname: \\?\C:\Windows\system32\cmd.exe failed
(32916, +94 ms) Sep 11 12:58:52 [1136]: ERROR: Event::HandleExecution[1136]: look up of processname: \\?\C:\Windows\system32\conhost.exe failed
(33072, +156 ms) Sep 11 12:58:52 [1128]: ERROR: Event::HandleExecution[1128]: look up of processname: \\?\C:\Windows\system32\wbem\wmiprvse.exe failed
(33119, +47 ms) Sep 11 12:58:52 [1268]: ERROR: Event::HandleExecution[1268]: look up of processname: \\?\C:\Windows\system32\dllhost.exe failed
(33290, +171 ms) Sep 11 12:58:52 [1136]: ERROR: Event::HandleExecution[1136]: look up of processname: \\?\C:\Windows\system32\SearchIndexer.exe failed
(39655, +6365 ms) Sep 11 12:58:59 [404]: ERROR: QueryAsyncCb: Cloud query failed

Debugが設定されている場合は、以下のようにERROR:が含まれていない行が大量に発生しています。

(601137247, +0 ms) Sep 20 02:31:04 [2680]:  opened file handle: \\?\C:\Program Files\Google\Chrome\Application\chrome.exe, 0xe9c
(601137247, +0 ms) Sep 20 02:31:04 [2680]: ClInterface::GetFileType getfiletype status: 0
(601137247, +0 ms) Sep 20 02:31:04 [2680]:  succeeded to get file type. handle: 0x44c, type: 0x00000000000000000000000400000000
(601137247, +0 ms) Sep 20 02:31:04 [2680]: ClInterface::GetFileType getfiletype status: 0
(601137247, +0 ms) Sep 20 02:31:04 [2680]:  succeeded to get file type. handle: 0xe9c, type: 0x00000000000000000000000000000002
(601137247, +0 ms) Sep 20 02:31:04 [2680]: [2680] checking for ZM string
(601137247, +0 ms) Sep 20 02:31:04 [2680]: [2680] lookup cloud: false, config file type: 0x0000000000000000038011000002c202, type: 0x00000000000000000000000400000000
(601137247, +0 ms) Sep 20 02:31:04 [2680]: ScanFileLocalUsingClPlugin invoked: 0x7ae0378
(601137247, +0 ms) Sep 20 02:31:04 [2680]: ScanFileLocalUsingClPlugin scanning file[Auto-Protect]: \\?\C:\Program Files\Cisco\AMP\tmp\99A775.tmpscan
(601137247, +0 ms) Sep 20 02:31:04 [2680]: ClEngineInterface::ScanFile entered...

また、Connector GUI上で設定した場合、一定時間が経過したりログオフすると、Debugが無効化されます。過去にDebugを有効化していた場合でも、事象再発前に、Debugが設定されているかを改めてご確認ください。

古いログは上書きされる

Connectorのログはサイズが大きくなれば、古いログとしてローテートされ、最終的には削除されます。特にDebugを有効にした場合、ログの消費サイズが大きくなり、Diagnosticsを取得したタイミングで事象発生時のログが消えてしまっているケースが多々あります。従いまして、Diagnosticsを取得するのは事象発生直後であることが好ましいです。

Connectorのログローテートは具体的には以下のような動作となります。

最新のログは常にsfc.exe.logに書き込まれます

sfc.exe.logが50MBになると、sfc.exe_X.log(Xには1から9の数字が入り、数字が大きいほど古いファイル)に保存し、新たにsfc.exe.logを作成します。
(Connectorバージョン8.1.5より前のバージョンでは、sfc.exe_YYYYMMDD_hhmmss.logという形式でログがローテートされ、古いログファイルは10世代まで保存されます。)

sfc.exe_X.logは9世代まで保存されます。それより古くなったログは削除されます。

こちらの世代数やファイルサイズは現時点の仕様としては変更ができません。

端末上での例を示します。

この例では、最も古いログがsfc.exe_9.logであり、ファイル中のログの最も古いタイムスタンプであるMay 08 13:56:38が最も古いログとなります。

(10875109, +0 ms) May 08 13:56:38 [2528]: Event::HandleCreation: Finished. Disposition=3, File=\\?\C:\temp\14574.txt(\\?\C:\Program Files\Cisco\AMP\tmp\F46F5.tmpscan), \\?\C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe
(10875828, +717 ms) May 08 13:56:38 [2100]: History::Execute: END TRANSACTION;
(10875828, +0 ms) May 08 13:56:38 [7624]: imn::GetProcessInfo pid: 4232. status: 0x0

最新のログは前述の通りsfc.exe.logで、5/8 16:30までログが保存されていることになります。お客様事象の再現が5/8 13:56:38以前であった場合は、ログが消えているということになりますため、再度ログ取得を行う必要があります。