loggingの使い方を模索する

はじめに

Python3.6.1で確認。
Pythonのログ出力を、loggingの木構造を上手く活かしつつ柔軟にあれこれやる方法を模索したのでまとめてみた。

基本方針

• printでログを出すと後からファイルにログ出力したくなった時に困る
  • なので最初からloggingモジュールで出力しておきたい
• とはいえさくっと書きたいので簡単な書き方が望ましい
• logging.debug()とlogger.debug()のtypo（特にエディタによる補完）を防ぐためにロガーだけを使う
  • 同じ目的でloggingを単体インポートしない
• 外部モジュールのログがうるさい時に自分のログだけを出力させたい

単発スクリプトのログ出力テンプレート

単発のスクリプトの場合、以下のように書く

test.py

from logging import basicConfig, getLogger, DEBUG
import my_mod

# このスクリプト本体のロガーを取得してログレベルを設定する
logger = getLogger(__name__)
logger.setLevel(DEBUG)

def main():
    # ここからメイン処理を書く
    logger.debug('This is debug message.')
    logger.info('This is info message.')
    logger.warn('This is warning message.')
    logger.error('This is error message.')
    logger.critical('This is critical message.')
    my_mod.some_func()

if __name__ == '__main__':
    # このスクリプトから呼び出されるモジュール全体のログ設定を行う
    basicConfig(
        format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # メイン処理実行
    main()

実行結果

$ python test.py
[2018-01-07 22:23:13] __main__ DEBUG: This is debug message.
[2018-01-07 22:23:13] __main__ INFO: This is info message.
[2018-01-07 22:23:13] __main__ WARNING: This is warning message.
[2018-01-07 22:23:13] __main__ ERROR: This is error message.
[2018-01-07 22:23:13] __main__ CRITICAL: This is critical message.
[2018-01-07 23:42:08] my_mod WARNING: This is my_mod warning message!

留意点

• デフォルトだとbasicConfig()は標準エラー出力に全てのログを吐き出す
• ログフォーマットがデフォルトでいいならbasicConfig()の引数は必要ない
• スクリプト内でimportして使っている外部モジュールがロガーを設定している場合もログ出力される
  • デフォルトだとWARNING以上のレベルのログが出力される
  • デフォルトの出力レベルを変更したい場合は、basicConfig(level=CRITICAL)のようにオプション引数を追加する
  • 外部モジュールのログが鬱陶しい場合は後述のテンプレートを使うこと
• メインスクリプトはDEBUG以上の全てのレベルのログが出力される
• 標準エラー出力でなく、ログファイルに出力したい場合はbasicConfig(filename='./test.log')のようにオプション引数を追加する

単発スクリプトのログ出力テンプレート（外部モジュールのログ除外）

スクリプト内で呼び出す外部モジュールの関数がログを出力する場合、ログがうるさくなる場合がある。
欲しい情報は自作スクリプトのログと成功失敗だけで、それ以外の情報がログにあると作業の効率が下がる、みたいなケースを想定。
外部モジュールのログを出力時に握り潰し、自分のスクリプトのログのみを出力させる場合は以下のようにする。

test.py

from logging import getLogger, StreamHandler, Filter, basicConfig, DEBUG
import my_mod

# このスクリプト本体のロガーを取得してログレベルを設定する
logger = getLogger(__name__)
logger.setLevel(DEBUG)


def main():
    # ここからメイン処理を書く
    logger.debug('This is debug message.')
    my_mod.some_func()

if __name__ == '__main__':
    # ストリームハンドラに__main__のログのみ出力するフィルタを追加
    sh = StreamHandler()
    sh.addFilter(Filter('__main__'))
    # モジュール全体のログ設定に上記ハンドラを含むリストを渡す
    basicConfig(
        handlers=[sh],
        format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S',
    )

    # メイン処理を実行する
    main()

実行結果

$ python test.py
[2018-01-07 23:43:58] __main__ DEBUG: This is debug message.

これで外部モジュールであるmy_modの処理のみログが出力されなくなった。

留意点

• このままだと外部モジュールのエラーログを握りつぶすことになるため、システムのログとして別途全てのログを出力しておく方が望ましい。
  • 標準エラー出力には全てのログ、ログファイルには特定ロガー以下だけのログを出力する、といった使い分けをするとよい。具体例は後半の応用パターン参照のこと。
• 標準エラー出力でなく、ログファイルに出力したい場合は前半を以下のように書き換える

-from logging import getLogger, StreamHandler, Filter, basicConfig, DEBUG
+from logging import getLogger, FileHandler, Filter, basicConfig, DEBUG
:
-# ストリームハンドラに__main__のログのみ出力するフィルタを追加
-sh = StreamHandler()
-sh.addFilter(Filter('__main__'))
+# ファイルハンドラに__main__のログのみ出力するフィルタを追加
+fh = FileHandler('./test.log')
+fh.addFilter(Filter('__main__'))
# モジュール全体のログ設定に上記ハンドラを含むリストを渡す
basicConfig(
-   handlers=[sh],
+   handlers=[fh],
    format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S',
)
:

パッケージ単位のログ出力テンプレート

スクリプトが肥大化してフォルダ単位でパッケージにまとめるようになった場合、
以下のようにするとログ管理が楽。

サンプル構成

my_project
├── __init__.py  # 空ファイル
├── consumer.py
└── my_package
    ├── __init__.py  # 空ファイル
    ├── main.py
    └── util
        ├── __init__.py  # 空ファイル
        ├── util_1.py
        └── util_2.py

実際のコード

・consumer

consumer.py

from logging import getLogger, basicConfig, DEBUG
from my_package import main
import my_mod

def consumer_main():
    # 自作パッケージの関数
    main.main()
    # 外部モジュールの関数
    my_mod.some_func()

if __name__ == '__main__':
    # モジュール全体のログ設定を行う
    basicConfig(
        format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # my_packageロガーのみログレベルをDEBUGに設定
    getLogger('my_package').setLevel(DEBUG)

    # メイン処理を実行
    consumer_main()

・main

main.py

from logging import getLogger, NullHandler
from .util import util_1, util_2

logger = getLogger(__name__)

# 呼び出し元でハンドラが設定されない限りログを出力しない
getLogger(__package__).addHandler(NullHandler())

def main():
    logger.info('This is main info message!')
    util_1.util_1()
    util_2.util_2()

・util_1

util_1.py

from logging import getLogger

logger = getLogger(__name__)

def util_1():
    logger.debug('This is util_1 debug message!')

・util_2

util_2.py

from logging import getLogger

logger = getLogger(__name__)

def util_2():
    logger.error('This is util_2 error message!')

・my_mod

my_mod.py

from logging import getLogger

logger = getLogger(__name__)

def some_func():
    logger.warning('This is some_func warning message!')

実行結果

$ python consumer.py
[2018-01-08 01:11:01] my_package.main INFO: This is main info message!
[2018-01-08 01:11:01] my_package.util.util_1 DEBUG: This is util_1 debug message!
[2018-01-08 01:11:01] my_package.util.util_2 ERROR: This is util_2 error message!
[2018-01-08 01:11:01] my_mod WARNING: This is some_func warning message!

留意点

• 各モジュールにgetLogger(__name__)と書いておけば、呼び出した時のパッケージ構造込みでログを出力してくれる
• スクリプト内でimportして使っている外部モジュールがロガーを設定している場合もログ出力される
  • デフォルトだとWARNING以上のレベルのログが出力される
  • デフォルトの出力レベルを変更したい場合は、basicConfig(level=CRITICAL)のようにオプション引数を追加する
  • 外部モジュールのログが鬱陶しい場合は後述のテンプレートを使うこと
• my_package内の処理のみDEBUG以上の全てのレベルのログが出力される
• 標準エラー出力でなく、ログファイルに出力したい場合はbasicConfig(filename='./test.log')のようにオプション引数を追加する
• main.pyでgetLogger(__package__).addHandler(NullHandler())としているのは、呼び出し元が意図していないログ出力を行わないため
  • basicConfig()を実行しない場合でも、デフォルトではWARNING以上のレベルのログが標準エラー出力に吐かれてしまう
  • モジュールをインポートしている側が意図していない標準エラー出力を吐くと、テスト等で困る場面がある
  • そのため、パッケージのトップレベルのロガーに何も出力しないハンドラを追加している
  • 参考: ライブラリのためのロギングの設定

パッケージ単位のログ出力テンプレート（外部モジュールのログ除外）

パッケージを利用する場合も単発スクリプトと同様、外部モジュールのログを出力させないことが可能。
consumer.pyを以下のように書き換えればよい。

consumer.py

from logging import getLogger, basicConfig, Filter, StreamHandler, DEBUG
from my_package import main
import my_mod

def consumer_main():
    # 自作パッケージの関数
    main.main()
    # 外部モジュールの関数
    my_mod.some_func()

if __name__ == '__main__':
    # ストリームハンドラにmy_packageロガーのみに絞るフィルタを追加
    sh = StreamHandler()
    sh.addFilter(Filter('my_package'))

    # モジュール全体のログ設定に上記ハンドラを含むリストを渡す
    basicConfig(
        handlers=[sh],
        format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # my_packageロガーのみログレベルをDEBUGに設定
    getLogger('my_package').setLevel(DEBUG)

    # メイン処理実行
    consumer_main()

実行結果

$ python consumer.py
[2018-01-08 01:20:06] my_package.main INFO: This is main info message!
[2018-01-08 01:20:06] my_package.util.util_1 DEBUG: This is util_1 debug message!
[2018-01-08 01:20:06] my_package.util.util_2 ERROR: This is util_2 error message!

これで外部モジュールであるmy_modの処理のみログが出力されなくなった。

応用パターン

標準エラー出力には外部モジュール含めた全てのログ、ログファイルには自作パッケージ処理のみのログを出力してみる。
consumer.pyを以下のように書き換える

consumer.py

from logging import getLogger, basicConfig, Filter
from logging import StreamHandler, FileHandler, DEBUG
from my_package import main
import my_mod

def consumer_main():
    # 自作パッケージの関数
    main.main()
    # 外部モジュールの関数
    my_mod.some_func()

if __name__ == '__main__':
    # 全てのログを扱うストリームハンドラを生成
    sh = StreamHandler()

    # ファイルハンドラにmy_packageロガーのみに絞るフィルタを追加
    fh = FileHandler('./my_package.log')
    fh.addFilter(Filter('my_package'))

    # モジュール全体のログ設定に上記ハンドラを含むリストを渡す
    basicConfig(
        handlers=[sh, fh],
        format='[%(asctime)s] %(name)s %(levelname)s: %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )

    # my_packageロガーのみログレベルをDEBUGに設定
    getLogger('my_package').setLevel(DEBUG)

    # メイン処理実行
    consumer_main()

実行結果

・標準エラー出力

[2018-01-08 02:07:00] my_package.main INFO: This is main info message!
[2018-01-08 02:07:00] my_package.util.util_1 DEBUG: This is util_1 debug message!
[2018-01-08 02:07:00] my_package.util.util_2 ERROR: This is util_2 error message!
[2018-01-08 02:07:00] my_mod WARNING: This is some_func warning message!

・my_package.log

my_package.log

[2018-01-08 02:07:50] my_package.main INFO: This is main info message!
[2018-01-08 02:07:50] my_package.util.util_1 DEBUG: This is util_1 debug message!
[2018-01-08 02:07:50] my_package.util.util_2 ERROR: This is util_2 error message!

このテンプレにたどり着いた背景

• ルートロガーを設定せずに自作パッケージのロガーだけを生成する場合、外部モジュールにlogging.error()などを使われるとログが正しく出ない場合がある
  • したがってルートロガーは必ず設定する必要がある
  • 簡単にルートロガーを設定するならbasicConfigを頼ると楽
• ルートロガーに来たログを全部出力するとたまにうるさい
  • 自作パッケージのログだけ欲しいが、自作パッケージのロガーだけ生成するのは上述した理由で避けたい
  • ルートロガーに全てのログが来るのはloggingの設計的には正しいので、ハンドラ側で出力するログを絞ることにする
• ログレベルがDEBUGの時のみ意図しない副作用を発生させる外部モジュールがあったりすると困るので、ログレベルは自作パッケージのみピンポイントでDEBUGにしておきたい
  • ハンドラ側で出力されなくても、ライブラリを利用した結果大量のDEBUGログがルートロガーに流れるとパフォーマンス落ちそうというのも理由の１つ
  • basicConfigではログレベルを設定せず、別途自作パッケージのロガーを取得して設定する
  • WARNINGでも副作用出るならbasicConfigのログレベルはERRORやCRITICALを指定する
  • DEBUGはともかく、ERRORやCRITICALを出すようなブロックで意図しない挙動をするライブラリは少ないはず
  • あったら諦めて泥臭くどうにかする
• 将来的にコンシューマー側のモジュールを別のモジュールから呼ぶことになっても改修が発生しないように、最初から実行時のみログ出力するようにする

参考

https://docs.python.jp/3/howto/logging.html
https://docs.python.jp/3/library/logging.html
https://qiita.com/amedama/items/b856b2f30c2f38665701