LoginSignup
36
27

More than 5 years have passed since last update.

@propella(Takashi Yamamiya)

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

Last updated at Posted at 2019-03-10

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

logging には２つの主要な要素 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()

参考

36
27
1

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
36
27