本連載では第一線のPerlハッカーが回替わりで執筆していきます。今回のハッカーはkazeburoさんこと長野雅広さんで、テーマは「ログでアプリケーションの改善プロセスを回す」です。

オペレーションエンジニアの仕事

小林篤さんから連載のバトンを受け取りました、長野雅広です。普段はNHN Japan（⁠株⁠）にてオペレーションエンジニアとして働いています。livedoor blogやポータルサービスなど自社Webサービスの運用に携わっており、cloudforecast（Perlで作られたリソース監視ツール）を使ったメトリクス収集をはじめ、アプリケーション設計のアドバイス、ミドルウェアの設定、障害対応のフォローなど、Webアプリケーションエンジニアにかかる運用の負担を減らすことが主な業務です。

ログはDevとOpsのコミュニケーション手段

監視サーバからのアラートメールが届いたり、リソース監視ツールのグラフに急激な変化を見つけると、オペレーションエンジニアはサーバにログインしてその原因を探り、問題の解消のために動きます。その際、サーバ上に適切なログが残っていることで、オペレーションエンジニアが問題の原因を特定しやすくなり、ミドルウェアの設定を変更したり、アプリケーションエンジニアと相談のうえアプリケーションに手を入れるなど、Webアプリケーション改善のサイクルを回していくことができます。ログが残っていなければアプリケーションエンジニアとソースコード全体から不具合となりそうな個所を探し出したり、再び同じ障害が起きるまで監視し、tcpdump、GDB（GNU Project Debugger⁠）⁠、straceといったツールを駆使して不具合個所を探さなければなりません。このようにログはアプリケーションエンジニア（Dev）とオペレーションエンジニア（Ops）の重要な媒体であり、コミュニケーション手段となります。

読者の中には、DevもOpsも両方担当しているのでコミュニケーションなどあまり関係がないと考える人もいると思います。しかし、多くのエンジニアにとって開発したアプリケーションの構造をすべて記憶するのは難しいので、開発時にログを出し、トラブルが起きた際にはそのログからすばやくソースコードを追えるようにすることで、全体を常に把握していなくても障害への対応がスムーズになり、開発に集中できるでしょう。ログがタスクの切り替え時の媒介となります。

Webアプリケーションのログの種類

ひとくちにログと言っても、いくつかの種類があります。Webアプリケーションの開発・運用の現場でよく扱うログには、アクセスログ、エラーログ、アプリケーションログの3つがあります。

アクセスログ

アクセスログはWebアプリケーションにアクセスがあった際に記録されるログです。ApacheなどWebサーバによって記録されることが多いと思われます。リスト1はApacheのcombinedフォーマットで記録されたログのサンプルです。リクエスト元のIPアドレス、時間、対象URI、レスポンスのステータスとサイズ、リクエストのリファラ、ユーザエージェントなどが記録されます。

202.x.xx.xx - - [04/Aug/2011:17:08:39 +0900] "GET /archives/000239.html HTTP/1.0" 200 3008 "http://www.google.co.jp/
search?..." "Mozilla/5.0 (Windows NT 5.1; rv:5.0) Gecko/20100101 Firefox/5.0"
202.x.xx.xx - - [04/Aug/2011:17:08:39 +0900] "GET /styles-site.css HTTP/1.0" 200 2376 "http://blog.nomadscafe.jp/
archives/000239.html" "Mozilla/5.0 (Windows NT 5.1; rv:5.0) Gecko/20100101 Firefox/5.0"
202.x.xx.xx - - [04/Aug/2011:17:08:39 +0900] "GET /mt-site.js HTTP/1.0" 200 1866 "http://blog.nomadscafe.jp/archives/
000239.html" "Mozilla/5.0 (Windows NT 5.1; rv:5.0) Gecko/20100101 Firefox/5.0"

エラーログ

アプリケーションで何かしら例外が発生したり、ユーザからのリクエストに不正があった場合はエラーログに記録されます。リスト2はApacheのエラーログのサンプルです。1行目はユーザからリクエストされたrobots.txtのファイルが見つからなかったことを示し、2行目はアプリケーション中で未定義の値が使われたというメッセージ、3行目はアプリケーションが例外により停止したことを示しています。

[Thu Aug 04 17:25:42 2011] [error] [client 65.x.x.x] File does not exist: /var/www/html/robots.txt
[Thu Aug 04 17:27:08 2011] [error] [client 203.x.x.x] Use of uninitialized value $ENV{"DEBUG"} in string eq at /var/www/
html/sample.cgi line 10.
[Thu Aug 04 17:28:38 2011] [error] [client 113.x.x.x] Died at /var/www/html/sample.cgi line 12.

アプリケーションログ

アプリケーションの例外とは別に、「⁠サービスへの登録を受け付けた」「⁠フォーラムへ投稿があった」などのアプリケーション独自の記録を残すことがあります。エラーログとは異なり、アプリケーションログはアプリケーションが問題なく動作していても記録を残します。残されたログは、あとから正常に動作をしていたことを確認したり、ユーザからの問い合わせ対応などにも利用されるので、すぐに参照ができるよう保持しておくことが重要です。多くのWebアプリケーションではエラーログのファイルにアプリケーションログも記録していると思います。

ログに必要な情報

わかりやすい文章を書くコツとして5W1H（Who,What, When, Where, Why, How）などと言われることがありますが、コミュニケーション手段としてログを活用する場合でも、情報（ログ）を発信する側から受け取る側にわかりやすく必要な物事が伝わるように、ログに含む情報をあらかじめ決めておくことが重要です。

時間

そのログがいつ記録されたものなのかは、あとから調査する際に必須となる情報です。日付・時間の形式は数多くありますが、統一されていれば多くの場合問題ありません。

[04/Aug/2011:17:08:39 +0900]
2011-08-04T16:28:23

1行目はApacheのアクセスログで使われるフォーマットです。2行目はISO 8601フォーマットで、日付と時間のセパレータ文字として「T」を利用しています。時間の形式は文字列ができるだけ短く、grepしやすいよう固定長であるものがお勧めです。

ログレベル

Apacheのエラーログ（リスト2）などで、[error]、[notice]、[info]といった文字列を見たことがあると思います。これはエラーの重要さのレベルを表しています。

レベルを選択する際の基準

ログを書き出すときにどのレベルを選択すべきか悩んでしまうことがあると思います。その際はログを誰が見るのか、そしてログを見た人に何をしてほしいかを基準にして選びます。表1は、後述するPerlモジュールLog::Minimalがサポートしている4つのログレベルをどのように選択するのがよいのかのをまとめたものです。参考になれば幸いです。

追加情報／環境

アクセスログ（リスト1）におけるリモートホスト、ユーザエージェント、リファラのように、そのログが出力されたときの環境もログに記録されていると、障害やエラー調査の際に参考情報として役立ちます。

ログの呼び出し元とスタックトレース

問題の調査を行いやすくするためにログがプログラム中のどこから出力されているか、そのファイル名や行数がログに含まれているとよいでしょう。ある関数内でログを出した場合、その関数を呼び出した元、その呼び出し元を呼び出した元というようにスタックトレースがあると、より問題が追いやすくなります。

しかし、大量にログが吐かれている場合にすべてのログにスタックトレースを付加してしまうと肝心のメッセージが読みづらくなります。スタックトレースを出力する際は目的と出す場所を絞るのがお勧めです。