Python
logging

Python でモジュールごとに logging する。または dictConfig の落とし穴。

Python でちょっと凝ったログの出力をしたい場合 logging というライブラリを使うのが定番です。また設定には dictConfig を使います。ただ後方互換性のために落とし穴があるので、意図しない動作になる時は disable_existing_loggers を False にするのがコツです。と、いうような話題を書きます。

logging には2つの主要な要素 Logger と Handler があります。



  • Logger にアプリやライブラリはログを書き込む。


  • Handler でメインスクリプトはログの記録方法を指定する。



    • Formatter でログの書式を設定する。




基本の使い方

基本の使い方は簡単です。

# 以下の二行はイディオムです。現在のモジュール名が付いた Logger が出来ます。

import logging
logger = logging.getLogger(__name__)

# Logger には debug, info, warning などのメソッドがあるので、重要度に応じて使います。
logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

この例では Handler が指定されていないので、デフォルトの Handler が使われます。デフォルトの Handler は WARNING 以上のログを stderr に書き込みます。というわけでここでは DEBUG や INFO は無視されて、次のように表示します。

Warn

ちょっと深入りしますが、デフォルトの動作の実装を見ます。

ライブラリコードを見ると、ここは 「何も Handler が登録されていない時は lastResort を使う」 となっています。

        if (found == 0):

if lastResort:
if record.levelno >= lastResort.level:
lastResort.handle(record)

lastResort の定義は、「level が WARNING で stderr に出力する StreamHandler」 です。このハンドラは全くカスタマイズ出来ないので、デフォルト動作はオマケと考えるべきです。

_defaultLastResort = _StderrHandler(WARNING)

lastResort = _defaultLastResort


info や debug を表示する。

WARNING 以下のログも表示したい場合は自分で Handler を用意します。(本当は basicConfig でもっと簡単に設定出来ますが、応用が効かないのでここでは触れません。)

import logging

logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作る。
handler = logging.StreamHandler()

# logger に StreamHandler を設定する。
logger.addHandler(handler)

# logger の閾値を DEBUG 以上に設定する。
logger.setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

addHandler() によってデフォルトの lastResort の代わりに指定した Handler を使います。そして setLevel() で閾値を設定します。setLevel() は Logger 側にも Handler 側にもあり、両方の条件を満たしたログだけ表示します。Logger 側の閾値のデフォルトは WARNING なので DEBUG を表示したい場合は明示的に setLevel() する必要があります。Handler 側のデフォルトは NOTSET (閾値なし) なので未設定で良いです。実行結果はこうなります。

Debug

Info
Warn


Logger の階層構造

Logger には階層構造があります。


  • logging.getLogger(): getLogger を引数無しで呼ぶと root logger が得られる。すべての Logger の親。

  • logging.getLogger('parent'): getLogger に引数を指定すると、名前付き logger が返る。通常 logging.getLogger(__name__) を使う。

  • logging.getLogger('parent.child'): 名前は . で区切った階層構造を持つ。'parent.child' の親は 'parent'。

先程、「Logger の閾値のデフォルトは WARNING」と書いたのは嘘です。正確には:


  • Logger の閾値のデフォルトは NOTSET。つまり未設定。この場合親の閾値が使われる。

  • logger.getLogger() すなわち root logger の閾値はデフォルトで WARNING。

  • よって、Logger の実質的な閾値のデフォルトは WARNING。

この動作を確認するために、logging.getLogger(__name__) で得られる logger __main__ の代わりに root logger を設定しても上記と同じ結果になります。

import logging

logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作る。
handler = logging.StreamHandler()

# logging.getLogger(__name__) の代わりに root logger に StreamHandler を設定して閾値を DEBUG にする。
logging.getLogger().addHandler(handler)
logging.getLogger().setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')


モジュールのログを表示

複数のモジュールで出来ているプログラムのログが必要な時に、モジュールを選んで表示したり閾値を変えたくなります。たとえば module.py という名前のモジュールがあるとします。

# module.py

import logging
logger = logging.getLogger(__name__)

def log():
logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

これ呼び出して、先程と同じように Debug ログを表示してみます。分かりやすいように書式も変更します。

import module

import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# logger に StreamHandler を設定する。
logger.addHandler(handler)

# logger の閾値を DEBUG 以上に設定する。
logger.setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

残念ながら、Debug ログが表示されたのはメインのスクリプトだけで、module.log() にはデフォルトの handler が適用されてしまい Debug が表示されません。

DEBUG:__main__:Debug

INFO:__main__:Info
WARNING:__main__:Warning
Warning

モジュール内の Debug ログも表示したい時は明示的に handler を設定します。

import module

import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# このスクリプトの logger に先程作った Handler を登録して閾値を DEBUG にする。
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

# module の logger に先程作った Handler を登録して閾値を DEBUG にする。
logging.getLogger('module').addHandler(handler)
logging.getLogger('module').setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

出力

DEBUG:__main__:Debug

INFO:__main__:Info
WARNING:__main__:Warning
DEBUG:module:Debug
INFO:module:Info
WARNING:module:Warning


モジュールのログを表示 (root logger で手抜き)

もしも利用するモジュール全部のログを同じように表示したいだけなら、root logger で全部まとめて設定出来ます。

import module

import logging
logger = logging.getLogger(__name__)

# 以下の設定は logging.basicConfig(level=logging.DEBUG) と同じです。

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# 各 logger の代わりに root logger を設定する。
logging.getLogger().addHandler(handler)
logging.getLogger().setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

実行結果は上と同様です。


Formatter による書式設定

"%(levelname)s:%(name)s:%(message)s" のような記法で書式設定します。非常に分かりづらいですが、levelname などの名前は LogRecord attributes で定義されています。

時刻の指定はちょっと特殊で (あとで書く)


dictConfig による設定

このようにすると柔軟にログを設定出来ますが、ややこしくてやってられないと思います。dictConfig というのを使うと多少楽になります。

import logging

import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
default: { format: '
%(levelname)s:%(name)s:%(message)s' }
handlers:
console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
loggers:
module: { level: DEBUG, handlers: [ console ], }
__main__: { level: DEBUG, handlers: [ console ], }
"""
))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

出力

DEBUG:__main__:Debug

INFO:__main__:Info
WARNING:__main__:Warning
DEBUG:module:Debug
INFO:module:Info
WARNING:module:Warning

dictConfig 固有の書き方を覚えないといけないので、python 素の python で地道に書くより簡単かどうかは微妙ですが、dictConfig を使った既存のプロジェクトを使う時や、複雑な設定が必要な時には使うしか無いです。


dictConfig は既存の logger を消してしまう!

ただ、dictConfig には既存の logger を消してしまうという分かりづらい落とし穴があります。例えば上の例をさらにシンプルにして root logger での設定を試みます。

import logging

import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
default: { format: '
%(levelname)s:%(name)s:%(message)s' }
handlers:
console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
root:
level: DEBUG
handlers: [ console ]
"""
))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

これは何も表示されません!ちょっと自分でもよく理解していないのですが、logger の定義(import module を含む)を dictConfig の後ろにするか、disable_existing_loggers: False を設定する必要があります。私はこの問題の解決に数日費やしました。悲しい。。。以下正解です。

import logging

import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
default: { format: '
%(levelname)s:%(name)s:%(message)s' }
handlers:
console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
root:
level: DEBUG
handlers: [ console ]
disable_existing_loggers: False
"""
))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()

参考