「犯人はこの何にいる！！」
マガジンで連載していた、金田一少年の事件簿で、金田一君が6話ぐらいかけて犯人を見つけていましたが、被害者が死ぬ前に、ダイイングメッセージで犯人の名前を残してくれたら、一話かからず事件が解決するでしょう。
プログラミングでも同じ事が言えます。
プログラムが死んだ時(プログラムが死ぬという事はありえてはいけないのですが、今回は比喩でつかいます。)、ダイイングメッセージに値するログを残さなかった場合、犯人(バグ)を見つけるのに大変な苦労がかかります。
プログラムが死ぬ前に最後の力を振り絞って、ログを残してくれれば、調査するのに何日も徹夜せず済むかもしれませんしれません。
プライベートな時間を仕事に削られずにすんだかもしれません。
それが原因で彼女とも別れずに。。。
。。。それほどログは重要なものです。
ということで前置きが長かったですが、今回はログについて書きたいと思います。
私は現地で作業をする機会が多く、その時に他人が作ったプログラムの問題を改修、調査する事があります。まず問題が起きた時にはログを確認するのですが、大半のログは見ただけでは、何が原因で問題が発生したのか解りません。
例えば、「○○処理で異常が発生しました処理を終了します。」と結果だけログに出力してあり、何が原因で問題が発生したかが出力されていない場合や、問題が発生したソースの行数が出力されていているだけで、ソースを解析しないと原因が解らない等、結果調査に時間が掛かってしまいます。
それではどうすれば良いか？
私は、ログを出力する際に下記の事を心がけるようにしています。
１、引数の値をログに出力する
問題が起きる原因として、関数に渡す引数に原因がある事が多いと感じています。
引数がNULLだったり、空文字だったりと原因は多様にありますが、問題が発生した時にログに引数の値が出力しているだけで、原因を調査する時間が格段に短縮されます。
一番良いのは、どの引数が何が原因で問題が発生しているのかがログに出力されていれば一発で調査終了です。当り前のような事で、とて重要な事です。
また、ログを出力するにあたって関数の作り方も私なりのポイントがあるのですが、それはまたの機会に。。。
２、関数の開始、終了をログに出力する
関数の始めと、終りに「○○関数処理を開始します。」「○○関数処理を正常終了します。」とログに出力するようにします。
ここで、重要なのは正常終了した時もログに出力しているという事です。
そうする事によって、問題が発生した事自体ログに出力されていなくても「正常終了」のログがなかった場合、そこで問題が発生した事が解りますし、どこまで処理を行っているかが解りパッチ対応が比較的簡単にできます。
注意しないといけない点として、for文なので1000回呼び出される関数に上記ログを仕込んでしまうと、1000回出力されてしまうので、そういった場合はfor文の前と終了した時に「開始」、「終了」ログを仕込む等の考慮が必要です。
３、問題が起きた時に目印となるものをログに出力する
私は、lessコマンドを使いログをリアルタイムで見て、実際にプログラムが動いている事を実感するのが趣味なのですが、ログの出力が頻繁に起きていると問題が発生しても気づかない事があります。
そこで問題が発生した時に「***************異常発生***************」などの様な、目立つ印を出力しておくと、リアルタイムで見ていても解りやすいです。
また問題を検索する時のキーワードにも使えます。
４、ログの見やすさ
ログをただ単に出力するだけではダメです。
問題が発生した時に調査するのは人の目なわけですから、見やすさも重要です。
多くのシステムでは、一定の処理を繰り返し行う事で成りったっているいると思いますが、その一定の処理が終わった後に空行を入れるだけで、ログが見やすくなります。
たまに、見やすさが考慮されていないログがあり、見ているだけで酔うことがあります。。。
ログをたくさん出力すると、SEの方達は処理速度が落ちないか、ログファイルがサーバのディスク容量を食い尽くさないかと心配しがちですが、最近のサーバのスペックならばログを出力したぐらいで体感的に処理が遅くなる事もありませんし、ディスク容量も、ログを一定期間保持した後に削除する仕組みがあれば問題ありません。
問題なのは、ログに出力する情報を少なくする事により問題を改修する時間が掛かってしまうことです。
と、偉そうな事を書いていますが、プログラマーになりたての頃、問題が多発した事があり、その時に学んだ事なんですがね。。。
