Pythonロギング入門：loggingモジュールでデバッグを効率化する方法

アプリケーションを作り終えたのに、思った通りに動かない――そんな経験はありませんか？ 実装した機能が期待とは異なる挙動を示すとき、あなたはどうやって問題に向き合えばよいのでしょうか。

ソフトウェア開発の現場では、開発者がプログラムの実行中に発生するイベントを追跡するために「ロギング」を活用します。ログを適切に残しておけば、問題が発生した際にも原因を効率的に突き止められます。

このガイドでは、アプリケーションのログを残すべき理由と、Pythonのloggingモジュールを使ってプログラム内のイベントを記録する方法を詳しく解説します。

なぜログを残すべきなのか

ログを残すことは、保守性の高いコードを書くうえで大きな助けになります。loggingのようなモジュールを使えば、プログラム内で発生したすべてのイベントを正確に記録できます。その結果、「どのコード行が実行され、どこで失敗したのか」をひと目で把握できるようになります。

Pythonでは、多くの開発者がprint()文を使ってコードの動きを確認しがちです。初心者から熟練者まで誰もが一度は使う手法であり、手軽さという明確な理由があります。print()文はシンプルで、すぐに使い始められるのが魅力です。

しかし、print()文はログ記録の最適解ではありません。まず、print()文はあらゆる出力をコンソールに表示できるため、「どの出力がログとして残すべきもの」で「どれがプログラム本体の出力なのか」の区別がつきにくくなります。さらに、print()文はデフォルトではログを保存しません。シェルを閉じれば出力は消えてしまいます。

そこで活躍するのがPythonのloggingモジュールです。標準ライブラリであるloggingモジュールを使えば、コード内でどんな処理が実行されたのかをより正確に記録でき、デバッグやエラー修正の効率が大幅に向上します。

Python loggingモジュールの基本的な使い方

ここからは、生徒の成績リストを処理して試験の合否を判定するプログラムに、ロギングメッセージを組み込んでいきます。まずは次のコードを見てください。

students = ["Martin", "Lewis", "Terri", "Bart"]
grades = [92, 78, 72, 38]
pass_fail = []

for i in range(0, len(students)):
    print("Calculating grade for {}".format(students[i]))
    if grades[i] > 55:
        pass_fail.append(True)
        print("{} has passed their exam.".format(students[i]))
    else:
        pass_fail.append(False)
        print("{} has failed their exam.".format(students[i]))

print("Student grades have been calculated. Moving on to send emails to parents of students who have failed their exams.")

このプログラムは、4人の生徒それぞれが試験に合格したかどうかを判定します。名前を格納するリスト、点数を格納するリスト、合否結果を格納するリストの3つを宣言し、forループで1人ずつ処理を進めています。

このプログラムを実行すると、次のように出力されます。

Calculating grade for Martin.
Martin has passed their exam.
Calculating grade for Lewis.
Lewis has passed their exam.
Calculating grade for Terri.
Terri has passed their exam.
Calculating grade for Bart.
Bart has failed their exam.

print()文でもコードが正しく動いていることは確認できますが、代わりにloggingモジュールを使えば、デバッグ用メッセージとプログラム本来の出力を明確に区別できるようになります。

loggingライブラリをインポートする

まず、プログラムの先頭でlogging標準ライブラリを読み込みます。

import logging

ログレベルを設定する

ライブラリをインポートしたら、ログの記録を始められます。この例ではDEBUGレベルを使用します。警告ではなく、コードの細かい動作を追跡したいからです。参考として、loggingで指定できる主なログレベルは以下の通りです。

• CRITICAL：深刻なエラーを表示する（logging.critical()）
• ERROR：問題が発生したことを表示する（logging.error()）
• WARNING：予期しない動作を表示する（logging.warning()）
• INFO：プログラムが正常に動作していることを表示する（logging.info()）
• DEBUG：コードをデバッグするための詳細情報を表示する（logging.debug()）

loggingライブラリのデフォルト設定はWARNINGのため、DEBUGレベルを使うには次のように設定を変更する必要があります。

import logging

logging.basicConfig(level=logging.DEBUG)

print()文をlogging.debug()に置き換える

これで準備完了です。成績計算の進行状況や完了を知らせるprint()文を、デバッグ用のステートメントに置き換えてみましょう。

import logging

logging.basicConfig(level=logging.DEBUG)

students = ["Martin", "Lewis", "Terri", "Bart"]
grades = [92, 78, 72, 38]
pass_fail = []

for i in range(0, len(students)):
    logging.debug("Calculating grade for {}".format(students[i]))
    if grades[i] > 55:
        pass_fail.append(True)
        print("{} has passed their exam.".format(students[i]))
    else:
        pass_fail.append(False)
        print("{} has failed their exam.".format(students[i]))

logging.debug("Student grades have been calculated. Moving on to send emails to parents of students who have failed their exams.")

実行すると、次のような出力が得られます。

DEBUG:root:Calculating grade for Martin
Martin has passed their exam.
DEBUG:root:Calculating grade for Lewis
Lewis has passed their exam.
DEBUG:root:Calculating grade for Terri
Terri has passed their exam.
DEBUG:root:Calculating grade for Bart
Bart has failed their exam.
DEBUG:root:Student grades have been calculated. Moving on to send emails to parents of students who have failed their exams.

出力内容自体は先ほどとほぼ同じですが、「Calculating grade for…」というメッセージや、成績計算の完了を知らせるメッセージの前に「DEBUG:root:」というテキストが付いている点が異なります。

これにより、プログラムが今どの処理を行っているのかを常時把握できるようになります。loggingモジュールが自動的にこのプレフィックスを付与してくれるため、どのテキストがプログラム本来の出力で、どれがデバッグ用なのかが一目瞭然です。

この例でいえば、「[生徒名] has passed/failed their exam」というメッセージこそが、ユーザーにとって重要な合否情報です。それ以外のメッセージはプログラムの動作確認には役立ちますが、ユーザーには不要です。だからこそ、こうしたステートメントをlogging呼び出しで記録するのです。

ログをファイルに保存する方法

loggingモジュールを使えば、ログをファイルに保存することもできます。Pythonシェルを閉じてもログが失われないため、特定の実行時にプログラムがどう動いたかという永続的な記録を残せます。

やり方はシンプルで、basicConfig()の設定行にfilename引数を追加するだけです。これだけで、ログが指定したファイルへ自動的に書き込まれます。

import logging

logging.basicConfig(level=logging.DEBUG, filename="student_data.log")

# ...

この状態でプログラムを実行すると、ログが指定したファイルに追記されます。「student_data.log」ファイルを開くと、次のようになっています。

DEBUG:root:Calculating grade for Martin
DEBUG:root:Calculating grade for Lewis
DEBUG:root:Calculating grade for Terri
DEBUG:root:Calculating grade for Bart
DEBUG:root:Student grades have been calculated. Moving on to send emails to parents of students who have failed their exams.

注目すべきは、ファイルに記録されているのがlogging.debug()で指定したメッセージだけだという点です。print()文による通常の出力とデバッグログが自然に分離されるため、ログの管理がとても容易になります。

タイムスタンプを追加する

さらに、ログエントリーがいつ記録されたのかを把握したい場合は、format引数を追加します。

logging.basicConfig(
    level=logging.DEBUG,
    filename="student_data.log",
    format="%(asctime)s:%(levelname)s:%(message)s"
)

このコードにより、student_data.logファイルには次のように記録されます。

2020-06-18 08:27:50,123:DEBUG:Calculating grade for Martin
2020-06-18 08:27:50,123:DEBUG:Calculating grade for Lewis
2020-06-18 08:27:50,123:DEBUG:Calculating grade for Terri
2020-06-18 08:27:50,123:DEBUG:Calculating grade for Bart
2020-06-18 08:27:50,124:DEBUG:Student grades have been calculated. Moving on to send emails to parents of students who have failed their exams.

これで、コードの各行がいつ実行されたのかがわかるようになりました。規模の大きいプログラムでは、この情報が特に有用です。コードの実行順序の確認や処理速度の分析に役立ちます。

まとめ

Pythonのloggingモジュールは、デバッグ作業において非常に強力なツールです。プログラム内で実行されるすべてのイベントを追跡でき、それらを独立したログファイルとして保存することも可能です。loggingを活用すれば、コードのデバッグがより効率化され、プログラム実行時に何が起こったのかを正確に把握できるようになります。まずは小さなスクリプトからlogging.basicConfig()とlogging.debug()を試してみてください。