【Python】仕組みを理解してログ出力を使いこなす
Pythonでログ出力といえば、標準モジュールの logging を利用する方法が一般的ですね。ググって出くるブログ記事を読めば、なんとなくの理解でも使えてしまうので、しっかりと仕組みを理解せずとも使えてしまいますし、それでも問題ないケースも多いと思います。
ただし、少し凝ったことをしようとするならば、一度Pythonのロギングの仕組みを抑えておいたほうが圧倒的に実装が楽になります。今回はloggingモジュールの仕組みを理解したうえで使いこなすこと目的に、図解やコードを交えて分かりやすく解説していきます。
スポンサーリンク
Pythonがログを出力する仕組み
まずは、ログ出力機能を実装するオブジェクトたちの機能・役割を整理します。
| オブジェクト | 機能・役割 |
| ログレコード（logging.LogRecord） |
ログ出力されるメッセージそのものの情報を持つ。ロガー間でやり取りされるのはこのログレコードである。 |
| ロガー（logging.Logger） | ログレコードを生成したり、ほかのロガーに受け渡す。受け取ったログレコードをハンドラに渡す。 |
| ハンドラ（logging.Handler） | ロガーに紐づけられ、受け取ったログレコードを出力する。 |
| フォーマッタ（logging.Formatter） | ハンドラに紐づけられ、設定に従い受け取ったレコードの書式を整形する。 |
| フィルタ（logging.Filter） | ロガーやハンドラに紐づけられ、受け取ったレコードを処理するかしないかを決定する。 |
ログレコード（logging.LogRecord）
ログ出力されるメッセージそのものの情報を持ちます。
ログのメッセージ本文はもちろんのこと、下記の情報を持っています。（抜粋）多くは明示的に値を渡す必要はなく、自動で記録されます。
- ログレコードの生成時刻
- ログレコードに設定されたログレベル
- 呼び出されたソースのファイル名
- 呼び出されたソース中の行番号
- スタックトレース
LogRecordオブジェクトに設定される全情報については、下記を参照のこと。
https://docs.python.org/ja/3/library/logging.html#logrecord-attributes
ログレコードを生成するのはロガーの仕事、出力するのはハンドラーの仕事です。
ロガー（logging.Logger）
ロギングの中心的役割を果たします。
ログのレコードを生成したり、そのレコードをほかのロガーに受け渡したりする機能を持ちます。実際にログを出力するのは、ロガー自体ではなく、ロガーに紐づけられたハンドラー（logging.Handler）です。
ロガーは各開発者が自分で定義・生成することができます。ロガーはそれぞれ名前（Logger.name）を持ち、各開発者がロガーを生成するときに、そのモジュール名を名前に設定することが一般的です。
# getLogger関数の第一引数に設定された文字列が、そのロガーの名前になる
logger = logging.getLogger(__name__)
print(__name__)
print(logger.name)出力：
__main__
__main__ロガーの階層構造
アプリケーションのなかで、ロガーは階層構造を持ちます。階層構造は名前を元に作成され、その表現方法はPythonのモジュールの階層表現と同じです。（文字列とドット（.）を使って表現され、ドットを挟むと階層が1段深くなります。）
下位層のロガーで生成されたレコードは、その親ロガーに伝播していきます。（設定によっては伝播させないことも可能）そして、最後にルートロガーに到達します。ルートロガーは、常に階層構造の最上位に位置するロガーのことです。ルートロガーは開発者自ら生成する必要はなく、loggingモジュールが定義します。
ロガーが階層構造を持っていると何がうれしいのかも参考にしてみてください。
ハンドラ（logging.Handler）
ログレコードを出力する役割を持ちます。
ハンドラは任意のロガーに紐づけられ、ロガーが受け取ったログレコードを出力します。
import logging
import sys
logger = logging.getLogger(__name__)
# 標準出力(コンソール)にログを出力するハンドラを生成する
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.WARNING)
# ハンドラをロガーに紐づける
logger.addHandler(sh)
logger.warning("unauthorized.")出力：
unauthorized.
出力先はコンソール、ファイルなど多岐にわたり、それぞれの出力先ごとに専用のハンドラーがあらかじめ定義されています。メール送信やHTTPリクエスト送信するためのハンドラーも用意されています。定義済みのハンドラーは下記にリストアップされています。
https://docs.python.org/ja/3/howto/logging.html#useful-handlers
今までハンドラとか設定した覚えはないけど、ログ出力できていたよ？も参考にしてみてください。
フォーマッタ（logging.Formatter）
フォーマッタはハンドラに紐づけられ、ハンドラが受け取ったログレコードをフォーマット（整形）する役割を持ちます。
フォーマッタのコンストラクタにフォーマット文字列を渡すことで、ログレコードに含まれる時刻とメッセージの書式設定を変更することが可能です。また、デフォルトのフォーマッタはテキスト形式の出力を想定したものですが、logging.Formatterクラスを継承して独自のフォーマッタを作成し、JSON形式でログ出力をすることなども可能です。※1もっとも、ただJSON形式でログを出力したいだけであれば、もっと簡単な実装方法もあります。（https://docs.python.org/ja/3/howto/logging-cookbook.html#implementing-structured-logging）
フォーマット文字列の詳細は、下記を参照のこと。
https://docs.python.org/ja/3/library/stdtypes.html#old-string-formatting
import logging
import sys
logger = logging.getLogger(__name__)
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.WARNING)
# フォーマッタを定義する（第一引数はメッセージのフォーマット文字列、第二引数は日付時刻のフォーマット文字列）
fmt = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s", "%Y-%m-%dT%H:%M:%S")
# フォーマッタをハンドラに紐づける
sh.setFormatter(fmt)
logger.addHandler(sh)
logger.warning("unauthorized.")出力：
2021-02-17T00:05:13 - __main__ - WARNING - unauthorized.フィルタ（logging.Filter）
ロガーやハンドラが、受け取ったログレコードを処理するかしないかを決定する条件を定義します。
定義したフィルタは、ロガーやハンドラに紐づけて使用します。
フィルタオブジェクトは、これまで挙げたloggingモジュールのオブジェクトとは異なり、デフォルトの状態では使われることはありません。ログレベルだけではコントロールし切れないような、任意の条件でログのフィルタリングを行いたい場合に開発者が定義して使用することができます。
import logging
import sys
# 指定された文字列がメッセージに含まれている場合のみ処理させるフィルタの例
class TextFilter:
def __init__(self, text=""):
self.text = text
# フィルタメソッド
# 処理したい条件ではTrue、処理したくない条件ではFalseを返すような関数を作成。
# 引数recordには、ログレコード（logging.LogRecord）が渡される。
def filter(self, record):
if self.text in record.getMessage():
return True
return False
logger = logging.getLogger(__name__)
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.WARNING)
# フィルタをハンドラに紐づける
sh.addFilter(TextFilter("internal server error"))
logger.addHandler(sh)
logger.warning("unauthorized.") # フィルター条件にマッチしないので出力されない。
logger.warning("internal server error.")出力：
internal server error.上記実装例を見てお気づきかもしれませんが、フィルタオブジェクトはlogging.Filterを継承する必要はありません。filter()メソッドを持つオブジェクトを渡すと、ログレコードをfilter()メソッドのパラメータに入れて呼んでくれます。
フィルタオブジェクトをさらに簡潔に実装するも参考にしてください。
ログが出力されるまでのフロー
出力されたログレコードは、ロガーの階層構造を子ロガーから親ロガーへと伝播していきますが、実際にログレコードがどのタイミングで出力されるかは、それぞれのロガーやハンドラに設定されたログレベルや、フィルタの設定によります。
ログレコードが生成されてから、出力されるまでのフロー図がPython公式のチュートリアルに載っているので、そちらを参考にすると理解しやすいです。
https://docs.python.org/ja/3/howto/logging.html#logging-flow
ログレベル
ログレコード、ロガー、ハンドラにはそれぞれログレベルを設定することができます。
ログレコードに設定したログレベルが、ロガーやハンドラに設定したログレベルと同等かそれ以上の場合のみ、実際にログレコードが処理されます。
ログレベルは、CRITICAL > ERROR > WARNING > INFO > DEBUG > NOTSET の順で高くなります。
import logging
import sys
logger = logging.getLogger(__name__)
sh = logging.StreamHandler(sys.stdout)
logger.addHandler(sh)
# ロガーのログレベルをWARNINGに設定する
logger.setLevel(logging.WARNING)
logger.info("this messege is never displayed.") # この行は出力されない
logger.warning("unauthorized.")出力：
unauthorized.少しややこしいのですが、logger.<ログレベル>は、<ログレベル>のログレコードを生成してロガーに渡すといいうメソッドなので、ロガー自体のログレベルを設定している訳ではありません。
ロギングについてよく言われること、Tips
logging.info()は使ってはいけない？
少し踏み込んだロギング解説記事を見ると、上記のようなことが書いてあったりします。これはどういうことかというと、loggingモジュール直下のinfo()やwarning()関数を使うと問題が起きる可能性があるよということです。
どこに問題があるかというと、ルートロガーに直接ログレコードを渡してしまうという点です。Pythonの経験が浅いとあまりピンとこないと思うので、具体例を出します。
下記コードでは、自作のMyClassが、ルートロガーに直接ログレコードを渡しているBadLoggingClassを参照しています。ここで、自作クラスのデバッグログを取得しようとするとどうなるでしょうか？
import logging
# お作法に従わないロギングを実装するクラス
class BadLoggingClass:
def invoke(self):
for index in range(100):
# 何らかの処理
logging.warning("unusable information.") # ルートロガーに直接ログレコードを渡す
import logging
from xxx import BadLoggingClass
# お作法に従ったロギングを実装するクラス
class MyClass:
def invoke(self):
bad = BadLoggingClass() # お作法に従わないクラスを依存関係に持つ
bad.invoke()
# 何らかの処理
logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())
logger.debug("important information.")
import logging
import sys
from yyy import MyClass
# MyClassのデバッグログを取得するためのコード
logger = logging.getLogger("yyy")
logger.setLevel(logging.DEBUG)
logger.propagate = False
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.DEBUG)
logger.addHandler(sh)
# 処理の実装
my_class = MyClass()
my_class.invoke()
出力：
WARNING:root:unusable information.
WARNING:root:unusable information.
WARNING:root:unusable information.
WARNING:root:unusable information.
WARNING:root:unusable information.
WARNING:root:unusable information.
WARNING:root:unusable information.
...中略...
important information.MyClassのデバッグログを取得したいだけなのにもかかわらず、BadLoggingClassのログが大量に出てしまい、本当に見たいログが埋もれてしまっています。上記例からもわかるように、ログ出力の管理は利用者が完全にコントロールできるようにするべきです。ログレコードをルートロガーに直接渡すという行為は、それを阻害してしまいます。
とはいえ、loggingモジュール直下のこれらの関数は、ロガーの設定をあれこれしなくてもログ出力ができるというメリットもあるので、書いてすぐ捨てるような簡単なスクリプトであればこちらを使っても特に実害はないかと思います。
ライブラリ等、他人や他のチームが使う可能性があるようなモジュール開発を行う場合は、logging直下の関数を使うのは避けるべきです。また、ハンドラの設定（logging.NullHandlerを除く）もするべきではありません。なぜなら、これら2つの設定については、設定がライブラリ使用側にも影響するうえ、設定した挙動を変えるのにライブラリのソースを直接変更する以外に方法がなく、著しく使い勝手が落ちるためです。
今までハンドラとか設定した覚えはないけど、ログ出力できていたよ？
デフォルトの動作では、ログレコードの伝播がストップした段階で対応するハンドラが一つも設定されていなかった場合、sys.stderrにログレベルWARNING以上のログを吐くように設定されています。
また、クラウド上でPythonのコードを実行する場合についても、あらかじめハンドラが設定されているケースがあります。（例えば、AWS LambdaのPythonランタイムでは、デフォルトでルートロガーにハンドラが設定されているので、明示的にハンドラを設定しなくてもCloudwatch Logsにログ出力することができます。）
ロガーが階層構造を持っていると何がうれしいのか
ログの出し分けがしやすくなります。「出し分け」とは、出力先をファイルとコンソールで分けたり、出力自体の有無の切り替えたりすることを指します。
上記画像を例にすると、numpy.lib配下のモジュールはファイルに出力、numpy.core配下のモジュールはコンソールに出力、それ以外のモジュールのログは出力しない、という感じの設定が簡単になります。
この要件は、ロガーの名前にモジュール名が設定されるのが一般的な理由のひとつとなっています。
フィルタオブジェクトをさらに簡潔に実装する
フィルタオブジェクトがfilter()メソッドを持たない場合はcallableであるとみなされ、ログレコードをパラメータに入れてフィルタオブジェクトが呼び出されます。つまり、上記の実装と全く同じ機能を持つフィルタを下記のように実装することも可能です。
import logging
import sys
logger = logging.getLogger(__name__)
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.WARNING)
sh.addFilter(lambda r: "internal server error" in r.getMessage())
logger.addHandler(sh)
logger.warning("unauthorized.")
logger.warning("internal server error.")まとめ
出てくるオブジェクトの数が多く、初心者の頃は少々とっつきづらいところもあるloggingモジュールですが、仕組みを理解してしまえば、強力なツールとなってくれるかと思います。より深く仕組みを理解するには、loggingモジュールのソースコードを読んでみるのもおすすめです。（実装としては理解しやすい部類です。ライブラリ作成の参考にもなります。）
今回紹介したオブジェクト群は、継承したクラスを定義することで簡単に動作をオーバーライドすることができるので、カスタマイズ性も高いです。ぜひ試してみてください。
参考
Logging HOWTO — Python 3.9.1 ドキュメント
logging — Python 用ロギング機能 — Python 3.9.2 ドキュメント
Logging クックブック — Python 3.9.2 ドキュメント
スポンサーリンク
脚注
| 1. | 戻る | もっとも、ただJSON形式でログを出力したいだけであれば、もっと簡単な実装方法もあります。（https://docs.python.org/ja/3/howto/logging-cookbook.html#implementing-structured-logging） |
ものすごく分かりやすかったです。
今まで呪文のように書いていた言葉が理解できてスッキリしました!