pythonのloggingモジュールでログ出力をする時に付加的な情報を出力する方法

はじめに

pythonのloggingモジュールで出力されるログの表現を変えようという話。おおまかに3つ方法がある

• デフォルトでサポートしている範囲で付加的なログ出力
• ログ出力を渡す際に付加的な情報を渡してログ出力
• 全てのログ出力に特定の情報を付加してログ出力

デフォルトでサポートしている範囲で付加的なログ出力

何も設定しない場合の出力

pythonのloggingモジュールではフォーマットを変更する事によって、出力の表現を変える事ができる。

import logging
logger = logging.getLogger(__name__)

logging.basicConfig(level=logging.DEBUG)

logger.info("hello")
logger.info("bye")

何も設定せずに logging.basicConfig() を使った場合には以下のような出力になる。

INFO:__main__:hello
INFO:__main__:bye

ログ出力に使われるformatterを変更した場合

formatterを変更してあげることで表示を変えることができる。変更自体はbasicConfigにformatオプションを付けるという方法でも可能。

import logging
logger = logging.getLogger(__name__)

fmt = "%(asctime)s %(levelname)s %(name)s :%(message)s"
logging.basicConfig(level=logging.DEBUG, format=fmt)
# logging.root.handlers[0].setFormatter(logging.Formatter(fmt=fmt))


logger.info("hello")
logger.info("bye")

以下のような出力になる。

2016-10-10 19:49:50,692 INFO __main__ :hello
2016-10-10 19:49:50,693 INFO __main__ :bye

デフォルトでできることであってもそれなりのことはできる。以下のような情報が付加できる。

• asctime -- 現在時刻
• levelname -- ログのレベル(e.g. DEBUG, INFO, ERROR, ...)
• message -- メッセージ (logger.info() などに渡された文字列)
• pathname -- ログが呼び出された物理的なパス(絶対パス)
• funcName -- ログが呼び出された関数名

詳しくは以下を見ると良い。

ログ出力を渡す際に付加的な情報を渡してログ出力

ログ出力の際に付加的な情報をその都度渡して出力時の情報を追加する事ができる。具体的にはextraオプションを指定する。
extraオプションで指定したdictの中の値はログ出力のformatterから触れるようになる。(正確にはLogRecordオブジェクトの __dict__ に保持されるようになる)

例えば、以下のようにしてwhoとcostという情報を更かしてみる。文字列の整形にはおおよそフォーマット文字列のミニ言語の記法が使える。

import logging
import random
logger = logging.getLogger(__name__)

fmt = "%(message)10s [who=%(who)s cost=%(cost).5f]"
logging.basicConfig(level=logging.DEBUG, format=fmt)

logger.info("hello", extra={"who": "foo", "cost": random.random() * 5})
logger.info("bye", extra={"who": "foo", "cost": random.random() * 5})

以下のような出力になる。

     hello [who=foo cost=2.48451]
       bye [who=foo cost=0.79263]

ちなみに不足している情報があった場合には KeyError になるので注意。

logger.info("noop")  # KeyError: 'who'

全てのログ出力に特定の情報を付加してログ出力

都度情報を渡すのではなく、常にある特定の情報を付加したい場合がある。
この場合には、LogRecordFactoryを変更してあげるのが良い。

例えば、call_countという同一メッセージ(fmt文字列でカウント)がログ出力された数を付加して表示してみることにする。

import logging
from collections import defaultdict
logger = logging.getLogger(__name__)


class Extension:
    def __init__(self):
        self.c = defaultdict(int)


class LogRecordExtension(logging.LogRecord):
    extension = Extension()

    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.extension.c[self.msg] += 1
        self.call_count = self.extension.c[self.msg]


if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG, format="%(asctime)s %(levelname)s %(message)s[%(call_count)d]")
    logging.setLogRecordFactory(LogRecordExtension)

    logger.info("hello")
    logger.info("hello")

    logger.info("%s: hello", "foo")
    logger.info("%s: hello", "bar")

以下のような出力になる。

2016-10-10 20:01:33,337 INFO hello[1]
2016-10-10 20:01:33,338 INFO hello[2]
2016-10-10 20:01:33,338 INFO foo: hello[1]
2016-10-10 20:01:33,338 INFO bar: hello[2]