問題の原因調査のためのログ収集のセオリー

はじめに

クリアコードでは、FirefoxやThunderbirdのサポート業務において、ログファイルを使って原因を調査することがあります。

この記事では、その中でも特に「手元の環境では再現できない問題について、実際に問題が起こっている環境でログを取得してもらい、それを分析して原因を推測する」という調査の進め方について、どのように進めるのか、また、その時はどのような点に気をつける必要があるのか、ということに焦点を当てて紹介します。

ここでは具体例として、「ThunderbirdでIMAPのメールアカウントを使用しているときに、Thunderbirdがフリーズしてしまう」という問題の原因を調査する場合を想定します。全体としてThunderbirdの事情に特化した説明になっていますが、ログの出力が関係するあらゆる場面で適用できる一般的なセオリーとしても参照できるはずなので、そのような視点でも読んでみてください。

Firefox、Thunderbirdでのログの取り方

ログとは、ソフトウェアが実行した処理の内容や、処理の中で起こったエラーなどを出力したものです。通常は画面上には表れない情報や、処理の流れそのものを見ることができるため、障害の原因調査などにおいて大きな助けとなり得ます。FirefoxやThunderbirdの場合、NSPR_LOG_MODULESという環境変数を使って、内部のモジュール単位でログをファイルに出力できます。

参考：HTTP Logging | MDN

例えばWindowsでは、コマンドプロンプトから以下のように操作することでユーザのホーム以下にログファイルを出力できます。

> set NSPR_LOG_MODULES=timestamp,all:5
> set NSPR_LOG_FILE=%Homepath%\nspr.log
> cd "C:\Program Files(86)\Mozilla Thunderbird"
> thunderbird.exe

Linuxでは、GNOME端末などを使って同じことができます。

$ export NSPR_LOG_MODULES=timestamp,all:5
$ export NSPR_LOG_FILE=~/nspr.log
$ thunderbird

OS X（Mac）では、「アプリケーション」→「ユーティリティ」→「ターミナル」を使います。ターミナル上では、FirefoxやThunderbirdのアプリケーションファイルはフォルダ（ディレクトリ）として見えるため、その中にあるバイナリを直接実行することになります。

$ export NSPR_LOG_MODULES=timestamp,all:5
$ export NSPR_LOG_FILE=~/nspr.log
$ cd /Applications/Thunderbird.app/Contents/MacOS
$ ./thunderbird

環境変数「NSPR_LOG_MODULES」には、ログを取得したいモジュール名とログレベルを「:」で繋げたものを、「,」区切りのリストとして指定します。

モジュール名は、例えば「nsHttp（HTTPでの通信処理）」、「nsHostResolver（DNSによるホスト名の名前解決の処理）」「IMAP（IMAPでの通信の処理：Thunderbirdのみ）」などがあります。どのようなモジュールのログを取得できるのかは、Firefoxのソースコード中でログモジュールを定義している箇所（Thunderbirdの場合）を探すとわかります。各モジュールの開発者がバラバラにログモジュールを定義しているため、日本語で参照できる索引のような使い勝手のいいリストは残念ながらありません。全モジュールをまたいでログを出力したい場合は「all」をモジュール名として指定することもできます。

ログレベルは、「1」から「5」までの間の数字で指定します。数字が小さいほど情報量が少ないログ（致命的なエラーに関する重要な情報だけを出力する）に、大きいほど情報量が多いログ（デバッグ用に参考情報のような重要でない情報も含めて何でも出力する）になります。

ログを取る時の注意点

前段の説明を見ると、「モジュールall、ログレベル5」という最も細かいログをまずは取得したくなるかもしれません。でも、ちょっと待ってください。

一口にログといっても、そこからいつでも好きなようにあらゆる情報を引き出せる訳ではありません。詳細すぎるログは情報の濁流のようなもので、手がかりなしに欲しい情報を見つけることは至難の業です。何の説明もなくぽんとファイルを1つ渡されただけでは途方に暮れてしまうこともしばしばです。

また、ログを取得する側においても、闇雲に詳細なログを取ろうとすると、数百メガバイトから下手をしたらギガバイト単位の巨大なログになってしまう可能性があります。そんなに巨大なファイルとなると、送るのも一苦労です。

どんなログであれば調査の手助けになるのか。ログを取る時にはどんな点に気をつける必要があるのか。基本原則として、ここでは以下の4点を述べます。

原則1：タイムスタンプ付きのログを取得して、実際の操作のメモも残す

タイムスタンプとは、ログの各行が出力された時刻を秒以下の単位で表したものです。FirefoxやThunderbirdのログは、何も指定しないとタイムスタンプが付かない仕様になっています。しかし、タイムスタンプがないと、個々の処理がいつ行われたのか、それぞれの処理にどのくらいの時間がかかったのかがわかりません。特に後者は、「特定の操作でフリーズしてしまう」「処理に異常に長い時間がかかってしまう」といった種類の問題の調査では致命的です。

FirefoxやThunderbirdでタイムスタンプ付きのログを取得するには、「NSPR_LOG_MODULES」で指定するモジュールのリストに「timestamp」を加えます（ログレベルの指定は不要です）。これにより、ログファイルの各行の先頭にタイムスタンプが付くようになります。タイムスタンプはUTC（協定世界時）で出力されるので、日本標準時に直して見るときは表記の時刻に9時間を加える必要があります。

また、タイムスタンプと共に重要な情報として、各操作の実行時や問題発生時の時刻のメモも残しておきましょう。例えば以下の要領です。

X時Y分Z秒頃、Thunderbirdを起動
X時Y分Z秒頃、Thunderbirdの起動が完了（操作できる状態になった）
X時Y分Z秒頃、フォルダを選択
X時Y分Z秒頃、Thunderbirdがフリーズする
X時Y分Z秒頃、Thunderbirdがフリーズから復帰した
X時Y分Z秒頃、Thunderbirdを終了

タイムスタンプと操作時刻のメモを付き合わせることで、ログのどのあたりを重点的に調査すればよいかが分かりやすくなり、調査のための手間を大幅に軽減できます。逆に、このような操作メモが残されていない状態のログ（特に、自分ではない他の誰かが取得したログ）では、最悪の場合は先頭から順に読んで「ここでこんな操作をしたのかな？」と解読していくことになるため、大変な労力が必要となります。

また、そのように付き合わせる都合上、この時の時刻は腕時計や柱時計などではなく、ログを収集している環境の時計（Windowsの時計など）を参照する必要があります。システムの時計と腕時計などとの間で時刻がずれていると、見当違いのログを調べる羽目になってしまいますので、注意してください。

以上の通り、ログのタイムスタンプは非常に重要な情報源となります。ログには必ずタイムスタンプを出力しましょう。

原則2：問題発生時と正常時の両方のログを取得する

問題が再現したりしなかったりして、「問題に再現性はあるが、再現条件が完全には明らかでない」というときは、問題が発生している場合と発生していない場合の両方について、可能な限り同じ手順でログを取得しておきます。問題発生時と正常時の差をログから調べることで、問題の原因究明に繋がる可能性があります。

問題発生時のログだけからでも問題の原因を見つけられるのでは？と思うかもしれませんが、ログに記録されている異常の中には、調査したい対象の問題とは無関係なものが含まれていることがあります。ログに表れている異常を片っ端から「これも怪しい」「ここも怪しい」と精査していると、調査の労力が爆発的に増大してしまいます。特に、手元の環境とは異なる未知の環境で取得されたログの場合、それが問題に関係がある異常かどうかの判断は非常に難しいです。

問題が発生していない時のログが比較対象として存在していれば、問題発生時と正常時の両方のログに表れている異常は、問題とは無関係のものであるとして無視できます。ログは可能な限り、問題発生時と正常時の両方のログを取得しておきましょう。

原則3：最初は問題に関係が深そうな特定のモジュールのログから取得して、後から解像度を上げる

前述した通り、FirefoxやThunderbirdではログの取得対象モジュールとして「all」を指定すると、モジュールを横断してすべてのログを取得することができます。しかし、怪しい箇所の見当も付けられていない状態でいきなりすべてのログを取得しても、どこから見ればよいのかがわからないためお手上げになってしまいかねません。実際、ログモジュールが「all」の状態では、画面描画に関するログやフォントの処理に関するログまで記録されてしまうため、例えばネットワークに関係する機能で起こっている問題に対する調査では、関係ない情報が多すぎて問題の箇所が埋もれて見つけられなくなってしまいます。

問題の内容からある程度の見当が付けられるのであれば、まずは問題に深く関係していそうなモジュールだけに絞ってログを取得しましょう。例えば冒頭で述べた「ThunderbirdでIMAPのメールアカウントを使っていて、Thunderbirdがフリーズする」という問題であれば、少なくとも、HTTPでの通信やPOP3関係の処理は無関係と考えてよいでしょう。逆に、メールフォルダ一般の処理や、IMAP関連で特有の処理は問題と関連していそうだと予想できます。Thunderbirdのソースコードに含まれているログモジュールの定義の中から関係が深そうなモジュールの名前を探して、そのモジュールに限定してログの取得を試みます。

タイムスタンプと操作時刻を付き合わせたり、通常時と問題発生時のログを比較したりして、「ログのこのあたりに異常が現れている」という見当が付いたら、そこで初めて他のモジュールのログも併せて取得するようにしましょう。他のモジュールのログも併せて取得した中から、先程見当を付けたログに対応するものを探し、その周囲を眺めると、モジュール単位のログには表れていなかった、一見すると無関係な別のモジュールの異常が見えてくるかもしれません。

例えば、IMAP関連の処理のログの中でタイムスタンプにギャップが生じている（1行1行の間に数秒以上時間がかかっている）箇所があった場合、他のモジュールのログも含めて出力したものから、異常が現れていたIMAPのログの箇所を見つけ出すこおで、そのギャップの間に何が起こっていたのかが明らかになる可能性があります。

同様のことがログレベルにも言えますが、問題が起こっているときの原因調査という場面では、ログレベルは最初から「5」（デバッグ用、最も詳細）を指定して問題ないでしょう。「1」などの解像度が低いログレベル（エラーのみの出力など）は、運用上のポリシーとして普段から常時ログを取り続けるといった場合に使います。

原則4：ログの取得中は、余計な操作をしない

原則3とも関係していますが、ログの収集中は可能な限り、関係のない操作をしないようにしましょう。

例えば、前述した通り、ログモジュールが「all」の状態では、画面描画やフォントの処理に関するログまで出力されるため、極端な場合、マウスを動かしてツールバーボタンの表示が変わるだけでもそれに対応するログが記録されます。このような無関係なログの出力を控えるため、モジュール「all」でログを取得するときは、マウスやキーボードに必要以上に触れないことが望ましいです。

また、自動アップデートのためにバックグラウンドで行われる通信なども、問題の再現条件に含まれないのであれば、可能な限り無効化しておくことが望ましいです。FirefoxやThunderbirdの詳細設定で機能を無効化できますので、忘れずに確認しておいてください。

Thunderbridではなく、サーバ上で動作するソフトウェアのログを収集する場合は、関係のない処理はなるべく停止しておくということになります。例えば、システムのアップデートやrsyncでのファイル同期、cronjobなどが考えられます。できるならば、サーバをサービスから切り離せる（そのサーバ1台をネットワークから隔離しても、表向きはサービス運用に支障がない）状況を整えておいて、調査時には必要のない処理はすべて停止しておきたいものです。

問題の種類によってはログの取得に時間がかかることがあり、その間、暇つぶしや日常業務として別のことをしたくなるかもしれません。しかし、問題と無関係な情報がログに大量に含まれていると、本当に問題の原因となっている箇所を特定することが難しくなります。ログの収集中は、ログ収集という作業の「本番」と考えて、可能な限りそのことだけに集中することが望ましいです。

まとめ

以上、Thunderbirdでログを収集する場面を例にとって、問題の原因調査のためのログ収集のノウハウ（セオリー）を紹介しました。

問題の原因調査のためのログ収集では、総じて、余計な情報を省いたり、余計な情報を無視しやすくしたりして、核心となる情報に辿り着きやすくすることが大事です。最小限の手間と時間で核心に辿り着けるように、セオリーを守ってログを収集するようにしましょう。

ククログ