プログラミングを始めてまず最初に覚えるデバッグ方法の1つは、変数の値をコンソールに出力することでしょう。これはプログラムがどのように進行しているのかを知る良い手掛かりになります。次第にプログラムが複雑になってくると、ある時点を境に自分の頭の中だけでは全てのプログラムの動作を把握するのが困難になってきます。このような状況下でプログラムが意図しない動きをする場合などは特に、ある時点におけるある変数の値を確認する必要が生じます。実行中のプログラムの何地点かでの出力値を確認することで、迅速にバグが発生している箇所を特定し修正することが可能になります。

コードはすぐさま print 文でいっぱいになるでしょうが、プロダクション環境にデプロイするまではそれでも全然問題ありません。しかしコードを、サーバー上で、自分のマシン上でのスケジュールジョブとして、もしくは、クライアントのコンピューター上のスタンドアロンプログラムとして実行するようになると、何か問題が発生した場合でもコンソール出力に頼ることはできなくなります。何が上手くいっていないのかを知る手立ても、その問題を再現する手立てもなくなってしまうわけです。こうなると、デバッグは「科学の領域」からただの「ギャンブル」へと移行してしまいます。

この問題に対する最も簡単な解決策は、コンソールに出力するのではなくファイルに出力するためのコマンドで print 文を置き換えることです:

これで、動作が期待通りではない場合に、プログラム内で何が起こっているのかを確認できます。ログファイルは飛行機におけるブラックボックスのようなものです: プログラムの実行過程を記録します。プログラムがクラッシュした際ブラックボックスを開いて、クラッシュに至るまでに何が起こったのか、どこからバグを探し始めればよいのか、を確認することができます。常に２行のコードを記述するよりは１行で済んだ方がいいでしょう。ファイルを開き、書き込むための関数を用意しましょう:

後々の検証のためにプログラムの状態を記録したい場所に、print 文を記述する代わりにこの関数を呼び出すコードを記述します:

log_message() 関数は、ファイルを開き、引数として渡されたメッセージをファイルに追記します。これが DRY (Don't Repeat Yourself) 原則の実践です。最も初歩的なことを言えば、プログラム記述中に コピー&ペースト の誘惑に駆られたら、常に頭の中で「警報音」が鳴り響かなければいけません。このような場合は、その コピー&ペースト の誘惑にかられた部分のコードを再利用できるように１つのパッケージとして抜き出す習慣をつけるべきです。

ちゃんと動作しているコードをどうしてわざわざ1つのパッケージとしてまとめるような「手間」をかけなければいけないのでしょうか？ただコピーして値をちょこっと変更すれば済むのではないでしょうか？コードが1カ所だけで使われているのであれば、何か変更を加える必要がある場合でも「その場所」を変更するだけで済みます。しかし、例えば、ログを取るためのコードがプログラム内のあちこちに散乱している状況で、もしログファイル名を変更する必要が生じた場合はどうでしょう？1つ1つのコードに記述しているファイル名をすべて変更しなければなりません。これは「悲惨」だ、ということは一目瞭然です。もし1カ所でもファイル名の変更をし忘れたら、その部分のログは「消滅」してしまいます。プログラミングにおいて、「ミス」が生じる最大の原因は「人間」そのものです。何千行、いや、何百万行にも及ぶコードで構成されているプロジェクトにおいて上記のような「ファイル名変更」というような更新作業をしなければいけなくなった場合、プログラム内のそこかしこで見落としが生じるのは明らかです。ですから日頃から、このようなヒューマンエラーに結びつく行為を可能な限り少なくする習慣をつけておく必要があるのです。

良いプログラマー (good programmers) はソリッドコード (solid code: 堅牢でバグのない高品質なコード) を記述します。卓越したプログラマー (great programmers) は、平均的なプログラマーがソリッドコードを作成できるようにするコードを記述します。

コードをよりユーザーフレンドリーにする方法の1つは、ログ機能に特化した関数だけを記述したファイルをプロジェクトに含めることです。こうすることで、プロジェクトの全てのファイルでログ関数をインポートできるようになりますし、ログ機能に関する変更はこのファイルだけを対象にすれば済むようになります。

新しいファイル logger.py を作成し、以下のコードを記述します:

あとはこのファイルをプロジェクト内の他のファイルでインポートしログを記録するだけです:

/var/log/filename.log ファイルを開いて、ログメッセージが書き込まれていることを確認してください。

書き込むログメッセージの数が増えてくると、それらを分類する方法が必要になってくるかもしれません。最も効果的な分類方法の1つは、メッセージの重要度を示す「単語」を付加することでしょう。

私たちは以下のように分類することにします:

幸い、更新すべきファイルは1つだけです (ねっ、ログ機能を1つのファイルにまとめておいてよかったでしょう？)

ログファイルに記録するメッセージには、上記のログレベルを表す用語を先頭に付加することになります。そうしておけば、特定のレベルに属するメッセージだけを簡単に選択、取り出すことが可能になります。特定のコマンドラインツールで grep といったコマンドを利用して簡単に実現できます。

更新後のログ関数は次のようなものになるでしょう:

import 文に変更はありません。ただ該当するログレベル関数を呼び出すだけです:

このコードを実行した後のログファイルには、ログレベル文字列が先頭に付加されたメッセージが書き込まれています:

我々のログ機能はかなり実用的になってきました。しかし、この logger.py の実装に関しては「警報音」が頭の中で鳴り響いているはずです:

それぞれのログレベルに対応している各関数では、ファイルを開き、そのファイルにメッセージを書き込む、という操作が重複しています。異なっているのは、それぞれのログレベルを表す為に追加する文字列だけです。ここでもしっかり DRY 精神を発揮する必要があります。

次のステップではこの重複している機能を別関数として実装します。しかしあくまでも「内部的」に変更を加えるだけで、外部からの各関数の呼び出し方法は一切変わりません:

かなりスッキリしましたね。各ログレベル関数はレベル文字列とメッセージを引数として write_log() 関数を呼び出しているだけです。

ただこの実装で気に食わないのは、ログファイル名をハードコードしている、という点です。もしこの小さなロガープログラムが気に入って、他のプロジェクトでも使用したい、となったらどうでしょう？このままでは、どのプロジェクトのログもたった1つの固定されたファイルに出力されてしまいます。

それを回避するために、ログメッセージを渡す際に同時に出力するファイル名も引数として渡すようにしましょう。

さて、この実装の問題点は何でしょう？ログファイル名は書き出すごとにコロコロと変わるものではありません。それを毎回々々渡さなければならなくなっています。１回ログファイルを設定した以降は、それを変更する必要が生じるまで、そのことを気にせずにログを出力できるようにすべきです。