Pythonのloggingモジュールの使い方

これもずっと前に書いたつもりでいたら書いてなかったので書きます。プログラムを開発していると、ログを実装することがあります。Jupyterでインタラクティブにやる時はprintで十分なのですが、機械学習モデルや何かしらのロジックを実装して本番環境で稼働させるなら何かしらログが残る仕組みは必須です。そして僕は横着してJupyterのファイルをそのままバッチとして使い始めたりもするのでJupyterでもロギングを使うことがあります。

その様な時、Pythonにはloggingモジュールという大変便利なモジュールが標準で用意されています。
参考: logging — Python 用ロギング機能 — Python 3.11.4 ドキュメント

このloggingライブラについては必ずドキュメントを読んでから使うことをお勧めします。というのも、このモジュールにはアンチパターンが多く、例えばルートロガーをそのまま使うなどの、適当に書いたらそう書いちゃう実装がリスクが大きいからです。

最近はドキュメントでも上の方で、logging.getLogger(name)を使えってちゃんと書かれる様になりましたね。それでは、使い方書いていきます。

getLoggerを用いたロガーの取得

loggingモジュールでは最初にロガーを取得します。これをやることでそのモジュールごとに独立したロガーが生成され、設定をいじってもシステム全体の他のロガーの設定に影響が出ない様にできます。ロガーには名前をつけるのですが、__name__という変数を使うと自動的にモジュール名が入るので良いでしょう。スクリプト本体の場合は__name__の値は__main__になります。

import logging


logger = logging.getLogger(__name__)

これでloggerが生成されましたが、初めて使った人がそのまま利用しようとすると、デバッグログやinfoのログが出ないことに気づくと思います。

# debugと info は何も出力しない。
logger.debug("デバック")
logger.info("インフォ")

# warning/error/critical は標準エラー出力に出力
logger.warning("ワーニング")
# WARNING:__main__:ワーニング
logger.error("エラー")
# ERROR:__main__:エラー
logger.critical("クリティカル")
# CRITICAL:__main__:クリティカル

ざっくり言うと初期設定ではこういう動きに設定されているということです。
もっと詳しく説明すると、この時点ではloggerにはログの出力先(これをhandlerという)が設定されておらず、この様な場合は警告以上の重要度のメッセージを「lastResort」っていう最終手段のハンドラが出力してくれているという状況になっています。ハンドラが設定されてなくても重要なメッセージはユーザーに伝えようと言うモジュールの思いやりです。

さて、上記のままではせっかくのデバッグメッセージ等が揉み消されるし出力も簡素すぎるのでここから色々設定していきます。

ハンドラーの作成と追加

まず、先ほどの例では出力先を制御しているハンドラが設定されていないので、こちらの追加方法を説明します。

これはファイルに書き出したい場合や標準エラー出力に出力したい場合などに備えて複数のクラスがあるのでそれをインスタンス化し、 addHandlerでロガーに設定します。複数設定も可能です。

ハンドラたちのドキュメントはこちら。次の様なイメージで設定します。

参考: logging.handlers — ロギングハンドラ — Python 3.11.4 ドキュメント

# ファイルに書き出すハンドラ
file_handler = logging.FileHandler('{ファイルパス}')
logger.addHandler(file_handler)

# 標準エラー出力に書き出すハンドラ
stream_handler = logging.StreamHandler()
logger.addHandler(stream_handler)

ログレベルの設定

ログにはログレベルという概念があって、ロガーと、出力先であるハンドラそれぞれがどのレベル以上のログを出力するかという持っています。両方を満たさなければ出力されません。例えば、ロガーはINFO以上、ハンドラがERROR以上を出力する設定なら、ERROR以上のログだけが出力されるという様な仕組みです。

ハンドラが個別に設定を持っていることで、標準エラー出力とログファイルに別々の設定を提供したりできますし、ロガー自体が設定を持っているので、開発中と本番運用中で一括して設定を変えることなどもできます。

ログレベルはこちらの通り で、
NOTSET(0) → DEBUG(10) → INFO(20) → WARNING(30) → ERROR(40) → CRITICAL(50)
の順です。

それぞれ setLevelメソッドを持っているのでそれで設定します。上記のレベルは数値でもいいし、モジュールが定数を持ってます。

次の様なイメージで設定します。

# ロガーのログレベル設定
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler()
# ハンドラのログレベル設定
handler.setLevel(logging.INFO)
logger.addHandler(stream_handler)

ハンドラごとに設定を変えれば、DEBUGはファイルだけ、INFO以上はファイルと標準出力両方といった設定ができます。

フォーマッターの使い方

ここまでで、ログの出力有無の制御ができたので、最後に出力内容を設定します。これはフォーマッターという仕組みで実現します。

設定によって詳細な時刻や、ログレベル、モジュール名、行番号などを情報に加えることができます。例によってこれもハンドラごとに設定できるので、標準エラー出力には時刻はいらないけど、ファイルには時刻も残したいって出しわけなどができますね。

フォーマッター中で使える変数はこちらの表にまとまっています。
参考: LogRecord 属性

実際に使うのはこの辺かな。

• asctime ・・・ 時刻を人間が読める書式にしたもの。
• levelname・・・DEBUGとかERRORなどのログレベル。
• message・・・ロギングの時に渡されたメッセージ本文。
• name・・・ロガーの名前。
• funcName・・・ロギングの呼び出しを含む関数の名前。
• lineno・・・ソース行番号

使い方のイメージとしては、次の様に %スタイルでフォーマットを作り、setFormatterでセットします。

formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

上記の例は%スタイルでこれはFormatterのコンストラクタのstyle引数がデフォルトの’%’だからこうなってるのですが、style引数に ‘{‘ を渡せば中括弧スタイルでも定義できます。個人的はそちらの方が好きです。

# 以下の二つは同じ
formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
formatter = logging.Formatter("{asctime} - {levelname} - {message}", style="{")

一通り動かす

以上をまとめて、書いておきます。これをベースに好みの形でいじっていけば良いロガーがが作れると思います。

import logging


logger = logging.getLogger(__name__)
logger.handlers.clear()
logger.setLevel(logging.DEBUG)

formatter = logging.Formatter("{asctime} - {levelname} - {message}", style="{")

file_handler = logging.FileHandler("sample.log")
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.INFO)
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

# 使い方。debugはファイルのみ、それ以外はファイルと標準エラー出力に表示。
logger.debug("debug")
logger.info("info")
logger.warning("warning")
logger.error("error")
logger.critical("critical")

何度も書くのは面倒なので自分は上記のコードに色々工夫を入れたものモジュール化して使い回しています。(訳あってこの間、久しぶりに書き直すことになりました。その時loggerの使い方を記事にしてないことに気づいたことがこの記事の発端でした。)