[Tips] Pythonのロガーでユーザーが定義したキーを使って値を出力する方法

こんにちは、CX事業本部の夏目です。

自分が関わっている案件では、Pythonを使ってLambdaを実装しているのですが、PythonのLoggerには、任意のキーでログに値を残すことができる機能があったので共有します。

kwargs extra

Pythonのlogging.debug()関数にはextraというキーワード引数があります。
ここにdictを渡すことでユーザーがAttributeを定義することができます。 (dictのKeyがAttributeの名前になります)

case_01.py

import logging

logger = logging.getLogger('testLogger')
logger.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)-15s %(clientip)s %(user)-8s %(message)s')

handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.debug('message', extra={'user': 'test_user', 'clientip': '127.0.0.1'})

これを実行すると次のようになります。

$ python case_01.py
2019-11-01 21:33:04,440 127.0.0.1 test_user message

ユーザーが定義したAttributeを使うことができました。

ログをJSON化するようにしていると次のようになります。

case_02.py

import logging
import json


class JsonFormatter(logging.Formatter):
    def format(self, record):
        ret = {}
        for attr, value in record.__dict__.items():
            if attr == 'asctime':
                value = self.formatTime(record)
            if attr == 'exc_info' and value is not None:
                value = self.formatException(value)
            if attr == 'stack_info' and value is not None:
                value = self.formatStack(value)

            try:
                json.dumps(value)
            except Exception:
                value = str(value)

            ret[attr] = value

        return json.dumps(ret, indent=2) #ここではJSONを読みやすくするためにindentを設定しています


logger = logging.getLogger('testLogger')
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
logger.addHandler(handler)

logger.debug('message', extra={'user': 'test_user', 'clientip': '127.0.0.1', 'data': {'key': 'test_data', 'value': 111}})

$ python case_02.py
{
  "name": "testLogger",
  "msg": "message",
  "args": [],
  "levelname": "DEBUG",
  "levelno": 10,
  "pathname": "02_case.py",
  "filename": "02_case.py",
  "module": "02_case",
  "exc_info": null,
  "exc_text": null,
  "stack_info": null,
  "lineno": 33,
  "funcName": "<module>",
  "created": 1572612900.635088,
  "msecs": 635.0879669189453,
  "relativeCreated": 8.63194465637207,
  "thread": 4551808448,
  "threadName": "MainThread",
  "processName": "MainProcess",
  "process": 21294,
  "user": "test_user",
  "clientip": "127.0.0.1",
  "data": {
    "key": "test_data",
    "value": 111
  }
}

ここでは、LogRecordに含まれる全てのAttributeをJSONで表示させています。 見ての通り、extraで渡したuserとclientid, dataがログに出力されています。

これを使うと任意の値をログにわたすことができそうです。 (JSON化の際に値の型には注意が必要そうですが)

注意

extraにわたすdictのKeyはロギングシステムで使われているものは使えないようです。

ドキュメントを見て注意だけはしておきましょう。
https://docs.python.org/ja/3.6/library/logging.html#logging.Logger.debug

まとめ

以上、Logに任意のキーで値を渡す方法でした。

実は今までargs をこの用途で使っていたのですが誤用だとわかって調べていたら、この機能に気づきました。 (argsはログメッセージに値を組み込むための機能のようです)

ちょっとしたTipsですが役に立てば幸いです。