Pythonのloggingで手出しできない所のhandlerを差し替える

python

元ネタ。コレをを見た時、確かにどうやったらいいんだろう? と思ってちょっと調べてみた。

やりたい事

  • ライブラリやらなんやらで書き出してるロギング部分を、自前で用意したロガーというかハンドラーに差し替えたい。

手出し出来ない例

例えば下記のような、hoge.py は手出しできないスクリプトだったとして、以下のようにログ取りになっていたとします。

# hoge.py 
# -*- coding: utf-8 -*-

from logging import warn

spam = u"スパム"
ham = u"ハムの人"

warn("%s %s", spam, ham)

handlerを差し替える

loggingモジュールの中を漁った結果、どうやら logging.root.handlersを弄れば、上記のような場合でも好きな LoggingHandlerに差し替えられるらしい。

1. root.handlers を強引に書き換える

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logging.root.handlers = [ltsv_handler] # root.handlersを上書きする

# hogeが呼ばれる前にloggingの設定をする
import hoge # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

行儀が悪い感じがとても怒られそうです。addHandlerというメソッドがあるのでそちらにしましょう。

2. addHandlerを使う

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logging.root.addHandler(ltsv_handler) # addHandlerに変えた。

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

というかそもそも、logging.getLogger()ていう風にやるとrootロガーだったのでそいつに対してaddHandlerすれば良かったという事実

3. rootロガーにaddHandlerを使う

# -*- coding: utf-8 -*-
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(ltsv_handler) # logging.getLogger() => rootロガー

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

ここまで書いて気がつきましたが、fileConfigでrootロガーを書き換えたらいいのでは？？？

4. fileConfigを使う

  • logger.iniを用意
[loggers]
keys = root

[handlers]
keys = ltsvhdr

[formatters]
keys = ltsvfmt

[logger_root]
level = DEBUG
handlers = ltsvhdr

[handler_ltsvhdr]
class = StreamHandler
args = (sys.stderr,)
level = DEBUG
formatter = ltsvfmt

[formatter_ltsvfmt]
format = time:%(asctime)s\tmessage:%(message)s
datefmt = %Y-%m-%dT%H:%M:%S%z
class = ltsvlogger.LTSVFormatter

script側ではfileConfigするだけ。

# -*- coding: utf-8 -*-
import logging.config
logging.config.fileConfig('logger.ini')

# hogeが呼ばれる前にloggingの設定をする
import hoge  # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

大体終わりです。

いろいろ怒られそうなので、書こうか迷うましたが、hogeを利用するスコープが限定的なら、mock.patchすればいいのでは！？？？とかいう愚行を一番最初に思いついた事を告白しておきます。石は投げないでください。

# -*- coding: utf-8 -*-
import mock
import logging
import ltsvlogger

formatter = ltsvlogger.LTSVFormatter(fields={
    'asctime': 'time',
    'message': 'message',
})
logger = logging.getLogger("nonrootlogger")
ltsv_handler = logging.StreamHandler()
ltsv_handler.setFormatter(formatter)
logger.addHandler(ltsv_handler)

with mock.patch("logging.warn", side_effect=logger.warn):
   import hoge # => message:スパム ハムの人 time:2014-02-10T23:41:54+09:00

ではではアデュー