TCSのログ解析

Yusuke Yoshinaga · ‎2014-05-01

本ドキュメントではCisco TelePresence Content Server(TCS)のトラブルシューティング時のログ解析方法について記述します。

TCSのログ取得手順については、以下の記事をご参照ください。

TCSのログ取得手順

https://supportforums.cisco.com/t5/-/-/ta-p/3137804

概要

TCSは複数の独立したログファイルを生成します。このドキュメントではトラブルシューティング時の各ログの使用方法について記述します。

ログファイル

TCSは6種類の独立したログファイルを生成します。以下に各ログに記録される情報について説明します。すべてのログはTCSを実行しているWindows ServerのE:\Logs\フォルダ内に保存されます。

1. Content Engine

Content Engineログには以下の情報が記録されます:

GatekeeperおよびSIPサーバへの登録状態
呼の詳細
ライブストリーミングおよびライブトランスコードの出力生成

Content Engineログはファイルサイズが10MBを超えるかContent Engineサービスが再起動すると新しくファイルを生成します。

2. Transcode Engine

Transcode Engineログには以下の情報が記録されます:

オフライントランスコード生成
Transcode Engineログには生キャプチャデータ(.ogg)からオフライントランスコードメディアを生成する処理の詳細が記録されます。

Transcode Engineログはファイルサイズが10MBを超えるかTranscode Engineサービスが再起動すると新しくファイルを生成します。

3. Content Library

Content Libraryログには以下の情報が記録されます:
PHPエラー
インタフェースに関連する問題
LDAP
API

このログにはメッセージが記録されるべきではありません。通常は空となるべきです。Content Libraryログはファイルサイズが5MBを超えると新しくファイルを生成します。

4. Helper

Helperログには以下の情報が記録されます:

トランスコード済の出力を保存先に移動する処理
ダンプファイルを保存先に移動する処理
トランスコード済の出力をFTPで転送する処理
ファイルの削除

Helperログはファイルサイズが10MBを超えるかHelperサービスが再起動すると新しくファイルを生成します。

5. Setup Utility

Setup Utilityログには以下の情報が記録されます:

リペア処理の出力

TCSでリペアを実行する毎にSetup Utilityログが新規生成されます。このログにはリペア処理中のチェック、警告およびエラーが記録されます。

6. Install

Installログには以下の情報が記録されます:

インストールの詳細、エラーおよび警告

インストーラが実行される毎に、インストーラツールからの出力がこのログに追加されます。

***注意: Content Engine、Transcode Engine、Content LibraryおよびHelperログがTCSのWebUIから取得可能です。他のログはTCSを実行しているWindows ServerのE:\Logs\フォルダから直接取得してください。

ログ解析

メディアの問題

録画中に音声またはビデオが記録されない等の問題が発生した際にはContent Engineログを調査します。まず最初に問題が発生した録画の会議IDを確認してください。会議IDはTCSのWebUIにadminユーザでログインし、Management > Recordings > Edit Recordingsから、調査する録画にて"Edit Recording"を選択すると確認できます。

このページに"Share Link"と表示される箇所があります。ここに記載されるリンクに会議IDが含まれています。会議IDはhttps://<TCSのIPアドレス>/tcs/?id=<会議ID>です。下図に会議IDの表示箇所を示します。

この会議ID文字列をコピーし、録画実施時刻の情報を含むContent Engineログを開いてください。録画実施時刻は上図の"Edit Recording"ページ内の"Date"フィールドで確認できます。
適切なContent Engineログファイルを確認してテキストエディタで開き、会議IDで文字列検索してください。検索結果の中から最初に現れた箇所が録画開始時の記録です。録画開始時の行から下方を確認し、同会議IDに関してメディアロスを示すエラーまたは警告を調査してください。
また、同会議に関するRTP統計情報を確認することも可能です。パケットドロップが発生していないかを調査してください。以下にRTP統計情報の出力例を示します。ログメッセージ中に会議IDが含まれることに注意してください。

382460 2013-12-08T23:52:07-05:00 Diagnostic: RTP statistics report, Packet drop rate exceeded 0.1% threshold [conference_id = 03F16BAA-323F-4A3B-A287-31A14F0A7707, log_tag = 17, recording_id = 71CF7C5B-26F0-442C-8AA0-BD389A077290, audio_packet_count = 0]

トランスコードの問題

録画が正常に終了したにも関わらず、トランスコードが正常に行われていないまたはトランスコードが実行されていない等の問題が発生した場合、Transcode Engineログを調査します。

Transcode Engineログから録画が実行された時刻の情報を含む箇所を確認してください。ライブトランスコードの問題の場合には該当の呼が開始した時刻から確認します。オフライントランスコードの問題の場合には該当の呼が終了した時刻から確認します。前述のように会議IDを用いて該当する呼を検索することができます。Transcode Engineログ内の該当の会議IDを含むメッセージからは、該当の録画がトランスコードテンプレートを使用したものであるか、録画の名前、レイアウト、録画の秒数、解像度、アスペクト比およびその他の情報を確認することができます。以下のログ出力例に確認できる情報を赤字で示します:

Info: Finding job information [job_id = 95BC8EBF-17CE-4563-9A40-1B02C1C0B22C, template = <transcode conference_id="989390f6-f0e8-46f9-99f0-39dd284e2ca6" thumbnail_path="E:\data\www\slides\989390f6-f0e8-46f9-99f0-39dd284e2ca6\thumbnails\"><clips action="transcode"><input filename="E:\livedata\RTP131114150320_1.ogg.tmp" points="0" hasvideo="True" framerate="0"/></clips><metadata name="Default OnDemand only 14 Nov 13 3:03 PM" date="1384459401"/><writer source="pipnopip"><template codec="windowsMedia" delivery="DELIVERY_ON_DEMAND" qualitybitrateK="800" layout="pipnopip" piplocation="top/left" quality="Medium"/><output type="file" guid="7c667cd6-d7bd-4411-8388-e6855d59abc4" directory="E:\data\media\"/></writer><callinfo bitrateK="4000" hasaudio="false" hasextended="false" hasvideo="true" videoFrames="6746" extendedFrames="0" duration="236" mainres="1280x720" maindar="16:9"/></transcode>]

これらの情報はトランスコーダがどのようにビデオデータを変換したのかを示します。期待したとおりのトランスコードでない場合、該当の呼にどの録画エイリアスが使用されたのかを確認し、録画エイリアスにはどの録画テンプレートが関連付けられているのかを確認してください。調査対象の呼で使用された録画テンプレートは録画エイリアスから確認可能です。録画テンプレートにはトランスコードエンジンが変換したビデオをどのように出力するのかが設定されています。下図に録画エイリアスに関連付けられた録画テンプレートの例を示します。下図の例では"Windows Media Single Live and On Demand"と呼ばれるテンプレートが選択されています。このテンプレートはライブストリーム出力にスイッチングレイアウト・Windows Mediaフォーマット・中サイズを使用しています。また、オンデマンド出力にはスイッチングレイアウト・Windows Mediaフォーマット・中サイズを使用しています。

ライブトランスコードの問題を調査する場合、Transcode Engineログから該当の会議IDを含むエラー・警告メッセージを検索してください。以下にデコードエラーが発生した場合のメッセージを示します:

Warning: Decoding video, Decoder reported error [session_id = 0, error_message = Still waiting on keyframe] - Sending FPU request

このようなデコードエラーは通常、呼の実行中にパケットロスが発生してTCSが接続先にビデオのキーフレーム送信を要求している場合に発生します。

Content Engineが開始しない

TCSで何らかの問題が発生し、Content Engineサービスが開始に失敗したりアクティブでない状態となることがあります。このようなContent Engineサービスの問題が発生した場合、TCSのWebUIにadminログインし、Management > Diagnostics > Server Overviewの"Content Engine Status"を確認してください。下図にContent Engineに問題が生じたTCSのWebUI表示例を示します。

TCSがこのような状態になった場合、直近に生成されたContent Engineログファイルを調査してください。TCSのWebUIにadminログインし、Management > Diagnostics > Server Logsから取得することが可能です。同ログはTCSを動作しているWindows ServerのE:\Logs\フォルダから取得することも可能です。

Content Engineサービスがアクティブでない状態や停止しているときには、TCSを動作しているWindows ServerにリモートデスクトップログインしてWindowsのサービスアプリケーションでTCS Content Engineサービスの状態を確認してください。下図はTCS Content Engineサービスが開始していないときの表示例です。

TCS Content Engineサービスを開始したにも関わらず、サービスが開始しない場合やWebUIにエラー表示される場合には、直近に生成されたContent Engineログファイルを再度確認してください。SQLデータベース/NASとの接続に失敗していることが原因となっている可能性が考えられます。

呼情報の探し方

Content Engineログをキーワード"call_id"で文字列検索すると、呼に関する記録を抽出できます。

着信時の例

2014-01-23T11:53:35+09:00 Info: Incoming call [address = 123456, address_type = CALLADDRESS_E164_ALIAS, call_id = 1, protocol = H323, rate = 4096]
2014-01-23T11:53:35+09:00 Info: Getting conference binding [booking_address = 123456] - No binding found, proceeding with ad hoc call
2014-01-23T11:53:35+09:00 Info: Checking recording start time [conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, log_tag = 0, recording_id = , record_delay = on]
2014-01-23T11:53:35+09:00 Info: Creating recording [conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, log_tag = 0, recording_id = ]
2014-01-23T11:53:35+09:00 Info: Creating call [call_id = 1, conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, direction = incoming, log_tag = 0, protocol = H323, speed = 4096, remote_address = 4510]

切断時の例

2014-01-23T12:13:00+09:00 Info: [call_id = 1] - Received a disconnect indication
2014-01-23T12:13:00+09:00 Info: Ending call [call_id = 1, conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, direction = incoming, log_tag = 0, protocol = H323, speed = 4096, ended_by = remote]
2014-01-23T12:13:00+09:00 Info: ~Recording :: Ending recording Start [conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, log_tag = 0, recording_id = 49000558-DEFB-442B-B617-22A333BCD444]
2014-01-23T12:13:00+09:00 Info: Ending recording [conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, log_tag = 0, recording_id = 49000558-DEFB-442B-B617-18F517BDB351]
2014-01-23T12:13:00+09:00 Diagnostic: RTP statistics summary, Call RTP packet information [conference_id = 6D2D691F-AF5F-4E58-9103-0A9F1BE82736, log_tag = 0, recording_id = 49000558-DEFB-442B-B617-22A333BCD444, audio_packet_loss = 0 of 58192: 0.00%, video_ext_packet_loss = 0 of 0: 0.00%, video_packet_loss = 0 of 189032: 0.00%]
2014-01-23T12:13:01+09:00 Info: Ending call [call_id = 1] - Call finished