pythonのloggerに項目を動的に追加する方法

概要

pythonで動的に表示項目を追加してログ出力する方法について調べたのでまとめる。

実装

class MyLogger(logging.LoggerAdapter):
    def process(self, msg, kwargs) -> tuple:
        # 受け取ったキーワード引数をextraキーの値に設定
        information = {"extra": {"kwargs": kwargs}}
        return msg, information


def get_logger(name: str) -> logging.LoggerAdapter:
    logger = logging.getLogger(name)

    # ハンドラーの追加
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(MyLoggerFormatter(datefmt="%Y-%m-%d %H:%M:%S"))
    logger.addHandler(handler)

    # レベル設定
    logger.setLevel(logging.INFO)

    return MyLogger(logger, {})


class MyLoggerFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        d = {
            "msg": record.msg,
            "level": record.levelname,
            "time": self.formatTime(record, self.datefmt),
        }
        # ログ出力時のキーワード引数を表示文字列に加えるため、dictに追加
        d.update(record.kwargs)
        return json.dumps(d, ensure_ascii=False)


if __name__ == "__main__":
    logger = get_logger(__name__)
    logger.info("メッセージ", key1=1, key2="aaa")
    logger.info("メッセージだけ")

実行時出力

{"msg": "メッセージ", "level": "INFO", "time": "2021-03-01 09:31:23", "key1": 1, "key2": "aaa"}
{"msg": "メッセージだけ", "level": "INFO", "time": "2021-03-01 09:31:23"}

解説

loggerの動き

loggerの.info呼び出し時の動きはおおよそ以下になる。
1. infoメソッド呼び出し(メソッドのシグニチャ固定されている。ログ項目を付加するにはextra引数にわたす必要がある。)
2. infoメソッドの引数に合わせてLogRecordが生成される
3. loggerにセットした各handlerにLogRecordが渡され、処理される。(各Handlerクラスのemitメソッド)
4. Formatterが設定されている場合は3の出力処理の前にFormatterクラスのformatメソッドを通る。 formatメソッドではLogRecord -> strの変換が行われる。

参考： github.com

実装方針

表示する項目のキーを動的に追加する(追加する項目をキーワード引数で設定したい)ためには以下が必要。

  • infoメソッドに追加項目のキーワード引数を渡す。
    → LoggerAdapterを利用
  • extra引数に設定された情報をログ出力時に表示する。
    → 独自formatter(MyLoggerFormatter)クラスの利用(formatメソッド)

LoggerAdapter

infoメソッド等の呼び出し時に、processメソッドで以下の変換が行われる。 infoメソッド呼び出し時に受け取った(msg, kwargs) -> Loggerに渡す(msg, kwargs)
これを利用して、infoメソッド呼び出し時の引数を、Loggerで処理可能な形に変換することが可能。

以上により、ログ表示の入力データをLogger内で処理可能なデータに変換可能。

使い所

ログ出力時に特定のkey:valueを表示したいことは色々とありそう。
ちなみにMyLoggerFormatterのformatメソッドを修正することで、表示形式を色々と変えることができる。
一例として、json.dumpsのindent設定(indent=2)を行った場合の出力は以下になり、jsonが複雑な場合は見やすい。

{
  "msg": "メッセージ",
  "level": "INFO",
  "time": "2021-03-01 09:54:09",
  "key1": 1,
  "key2": "aaa"
}
{
  "msg": "メッセージだけ",
  "level": "INFO",
  "time": "2021-03-01 09:54:09"
}

参考