Pythonのlogging入門

はじめに

Pythonは比較的わかりやすい言語だと思いますが、ロガー周りは少しややこしいです。
プログラムを作成する場合に、printで出力するのも問題はないのですが、ある程度の規模のプログラムを作成する場合は、ログ戦略を工夫する必要があります。
今回の記事ではプログラムでの出力をprintから少し高度なことしたいなー、という人向けの記事になります。
loggerを使う場合の注意点なども書いているので、初学者以外の方も学びがあるかもしれません。

前提知識：ログレベルについて

プログラムからは様々なログが出力されると思います。
通常、重要なログもあれば、そこまで重要ではないがあると嬉しいなというログもあります。
ログをある程度グループ分けして出力することで、運用時の調査がよりスムーズになるように設計することが多いです。
例えば、システムに何か問題があったときに、とりあえずエラーのログだけを絞り込んで調査したい、その時にログがグルーピングされていないと、全部のログ情報から自力でエラーログを絞り込まなければなりません。
ログレベルによってログをグルーピングすることで調査が便利になったり、出力するログの量を制御したりなどができます。

loggingを使うと何がいいのか

いくつかのメリットがあると思っています。

• 出力のフォーマットを統一することができる
• ログレベルの細かな制御ができる

出力のフォーマットを統一できるとは、例えばログの前に自動で時間情報を付与したりできる、などです。
ログレベルの細かな制御ができる、とは例えば開発環境では出力するログはDEBUGログまで、本番環境ではINFOログ以上のログを出力するように制御する、などです。
これらのことはprintの利用だけでは実現できません。

メリットばかり書いてもよくないので、デメリットも書きます。

• 学習コストが少しかかる
• 内容を理解せず使うと思わぬ罠にハマる

logggingを使うだけであればそこまで難しくはありません。
ただ、それだけだとprintで出力するのとと変わらないので、ある程度内容をしっかり理解して利用する必要があります。
また、浅い理解だと思わぬ罠にハマることがあります。

logging前提知識

Pythonのloggingは階層構造になっています。
大元のrootロガーがあって、それの下にユーザが作成したロガーが存在する、というイメージです。

上記の図におけるhandlerとは実際にログを出力する処理を担当する部分で、標準出力に出すのか、ファイルに書き出すのかなどを設定できます。
levelはログレベルがどれなのか、の設定です。
(これ以外の情報も持ちますが、上記図では省略しています。)

では、カスタムロガー1でDEBUGログ出力した場合、どのようになるでしょうか。
まず、カスタムロガー1のログレベル設定がDEBUG、ハンドラーのログレベル設定がDEBUGであれば、カスタムロガー1でログが出力されます。
次に、ログ情報は上位に伝搬するので、rootロガーに情報が渡り、rootロガーのハンドラーのログ設定がDEBUGである場合はrootロガーでもログが出力されます。

このあたりのフローは以下がわかりやすいです。
Logging Flow

logging入門(rootロガーを使う)

以下の資料を参考に解説します。
Logging HOWTO

上記記事ではまず、以下のコードでログ出力ができます、と記載があります。

import logging
logging.warning('Watch out!')  # このメッセージはコンソールに出力される
logging.info('I told you so')  # このメッセージは出力されない！！

実際に出力される結果は以下になります。

WARNING:root:Watch out!

いくつか疑問が浮かぶのではないでしょうか。
引数には「Watch out!」しか入れていないのに、出力結果に含まれる「WARNING:root:」はどこから来たのか？、や、なぜinfoログは出力されていないのか、です。

その疑問点について解説していきましょう。
まず、logging.warningのような形でログ出力をすると、利用されるロガーはrootロガーと呼ばれるものになります。
rootロガーの設定としてログの出力フォーマットは「<ログレベル>:<ロガー名>:<メッセージ>」とする、WARNING以上のログを出力する、という設定になっています。
(厳密には少し違います、basicConfigという関数の呼び出しでformatとhandlerが設定されることで上記表示となります)
なので、出力されるメッセージが設定に沿った形で出力され、WARNING以上のログしか出力されない、ということが起きていたのです。

rootロガーはすべてのロガーの大元となるロガーであり、原則利用すべきではないとされています。
では、rootロガーを利用して、infoログを出力するようにするためにはどうすればいいのでしょうか？
そのためには、コードを以下のように修正します。

import logging
logging.basicConfig(level=logging.DEBUG)
logging.warning('Watch out!')
logging.info('I told you so')

結果は以下になります。

WARNING:root:Watch out!
INFO:root:I told you so

しっかりINFOログも出力されていますね。
追加したlogging.basicConfig(level=logging.DEBUG)でログレベルの制御ができるのですが、これはrootロガーを利用するすべての処理に影響します。
例えば、あるロジックでrootロガーの設定を書き換えると、別の場所でrootロガーを利用しているところにも影響が及ぶ、ということです。
プログラムは疎結合で作るべきという原則から考えるとこういうことが起きると困るので、原則rootロガーは利用すべきではない、ということが分かります。

logging入門(カスタムロガー)

rootロガーは使うべきではない、ということは前章で解説しました。
ではどうすればいいかというと、カスタムのロガーを作成して利用します。

import logging
custom_logger = logging.getLogger('custom_logger')
custom_logger.warning('Watch out!')
custom_logger.info('I told you so')

出力結果は以下になります。

Watch out!

ここで疑問に思われるかもしれません。
まず、なぜINFOログが出力されていないのか、カスタムロガーを作成したが特にハンドラーを設定していないのにログが出力されているのはなぜか、です。
前述でロガーにはレベルやハンドラーを持つ、と説明しました。
では、カスタムロガーを作成するとデフォルトでハンドラーなどが紐づくのでしょうか？
答えはNoです。
では、rootロガーのハンドラーが利用されるのでしょうか？
それも答えはNoです。
それは以下のコードで確認ができます。

import logging
custom_logger = logging.getLogger('custom_logger')
custom_logger.warning('Watch out!')
custom_logger.info('I told you so')
print(logging.root.handlers)
print(custom_logger.handlers)

実行結果

Watch out!
[]
[]

つまり、どのロガーにもハンドラーは設定されていないが、なぜかログが出力されている、ということになります。
これは、loggingソースコード内のlastResort(日本語で最後の手段という意味)という部分で定義されており、ロガーにハンドラーが一つもない場合、標準出力にWARNING以上のログを出力する、という実装になっているからです。
つまり、ハンドラーを設定しなくてもWARNING以上のログはデフォルトで出力されるが、バグのもとなのでこの実装を当てにしてはいけません。

では、どうすればいいのかというと自分でロガーを作って、自分でハンドラーを紐づける必要があります。

import logging
custom_logger = logging.getLogger('custom_logger')
custom_logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler() # ハンドラーを作成
handler.setLevel(logging.DEBUG) # ハンドラーのログレベルを設定
custom_logger.addHandler(handler) # カスタムロガーにハンドラーを紐づける

custom_logger.warning('Watch out!')
custom_logger.info('I told you so')
print(custom_logger.handlers)

実行結果

Watch out!
I told you so
[<StreamHandler <stderr> (DEBUG)>]

確かにDEBUGログ以上のログが出力されていますね。
また、カスタムロガーにも一つhandlerが紐づいているのがわかります。

内容をまとめるとloggingを使う場合は、カスタムロガーを使いましょう、その際はハンドラーの設定をしっかりしましょう、ということになります。

おまけ：rootロガーの設定を追加してみる

少し踏み込んでrootロガーにデフォルト設定を追加した場合のコードも見てみましょう。

import logging
custom_logger = logging.getLogger('custom_logger')
custom_logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler() # ハンドラーを作成
handler.setLevel(logging.DEBUG) # ハンドラーのログレベルを設定
custom_logger.addHandler(handler) # カスタムロガーにハンドラーを紐づける

logging.basicConfig() # rootロガーにデフォルト設定を追加

custom_logger.warning('Watch out!')
custom_logger.info('I told you so')
print(custom_logger.handlers)
print(logging.root.level)
print(logging.root.handlers)

ポイントはlogging.basicConfig()で、ここでrootロガーにハンドラーなどが追加されます。

実行結果は以下になります。

Watch out!
WARNING:custom_logger:Watch out!
I told you so
INFO:custom_logger:I told you so
[<StreamHandler <stderr> (DEBUG)>]
30
[<StreamHandler <stderr> (NOTSET)>]

ログ情報は上に向かって伝搬すると説明しました。
まず、カスタムロガーのログ「Watch out!」が出力され、その後rootロガーのログ「WARNING:custom_logger:Watch out!」が出力されています。
また、カスタムロガーのハンドラーのログレベルは「DEBUG」ですが、rootロガーのハンドラーのログレベルは設定されていません((NOTSET)の部分が該当)。
また、細かい話になりますがrootロガーのログレベルはWARNINGですが、子からログ情報が伝搬された場合、ロガーのログレベルは考慮されず、ハンドラーのログレベルのみ考慮されます。(後述する「おまけ：ロガーの階層構造について」を参照)
つまり、rootロガーのログレベルはWARNINGであるが、ハンドラーのログレベルが設定されていないのでrootロガーでもログが出力される、ということになります。
なお、設定でログ情報が上に伝搬するのを防ぐこともできます。

おまけ：ロガーの階層構造について

loggingのログは階層構造になっています。
その階層自体はロガーを取得する際に名前にピリオドをつけることで階層構造を実現できます。
では、実際に階層構造のログを作る場合の例を記載します。

import logging
parent_logger = logging.getLogger('parent')
parent_logger.setLevel(logging.WARNING)
parent_handler = logging.StreamHandler()
parent_handler.setLevel(logging.DEBUG)
parent_formatter = logging.Formatter('PARENT: %(message)s')
parent_handler.setFormatter(parent_formatter)
parent_logger.addHandler(parent_handler)

# parentロガーはログ設定がWARNINGのため出力されない
parent_logger.debug('parent debug log') 
# parentロガーのログ設定がWARNINGで、ハンドラーのログ設定がDEBUGなので出力される
parent_logger.warning('parent warging log\n')


child_logger = logging.getLogger('parent.child')
child_logger.setLevel(logging.DEBUG)
child_handler = logging.StreamHandler()
child_handler.setLevel(logging.DEBUG)
child_formatter = logging.Formatter('CHILD: %(message)s')
child_handler.setFormatter(child_formatter)
child_logger.addHandler(child_handler)

# parentのログ設定はWARNINGだが、それは考慮されずparentロガーのハンドラーのログ設定がDEBUGなのでparentログも出力される
child_logger.debug('child debug log') 
child_logger.warning('child warging log')

実行結果

PARENT: parent warging log

CHILD: child debug log
PARENT: child debug log
CHILD: child warging log
PARENT: child warging log

ログ情報は子から親に伝搬していることがわかると思います。
また、子から親に伝搬する際に親のロガーのログレベルは考慮されず、ハンドラーのログレベルのみが考慮されることも上記コードからわかると思います。

おまけ：AWS LambdaのPythonのロガーについて

AWS LambdaのPython環境ではrootロガーにハンドラーが設定されています。

import json
import logging

def lambda_handler(event, context):
    custom_logger = logging.getLogger('custom_logger')
    custom_logger.setLevel(logging.DEBUG)
    custom_logger.debug('debug log')
    print(logging.root.handlers)
    
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

実行結果

[DEBUG]	2022-03-06T11:55:50.629Z	bae1f7f0-7c57-4720-a564-34791cbae26c	debug log
[<LambdaLoggerHandler (NOTSET)>]

実行結果からわかる通りrootロガーには「LambdaLoggerHandler」というハンドラーが紐づいています。
Lambdaの実装になれるとデフォルトでdebugログが出力されると勘違いして、素のPython環境でloggingを使うと勘違いするかもしれません。
AWS Lambdaのloggingは特別な環境、ということを理解しておくといいかもしれません。

参考

• cpython/Lib/logging/init.py