標準ライブラリの範囲で構造化ログで出力するようにしてみる

構造化ログ?

通常のloggingライブラリなどで使われるログをテキストログと呼ぶとすると、構造化ログとテキストログには以下の様な違いがある。

テキストログ

  • ログは人が読むもの
  • 通常テキストファイルに出力され、grepなどにより該当するログを見つける
  • 1つのログの単位はテキスト(文字列)
  • (パラメーターを自由に付けたりというのはむずかしい)

構造化ログ

  • ログは機械が読むもの
  • 何らかのアプリケーションにより検索され、何らかのビューから情報を確認する
  • 1つのログは何らかの構造化された表現(e.g. JSON)
  • (パラメーターを自由に付加できる)

すごく雑にいうとテキストログと言うのは以下のような出力のものを指してる。

2017-05-20 21:13:44,296 INFO:app:hello
2017-05-20 21:13:44,296 ERROR:app:broken
Traceback (most recent call last):
  File "~/sandbox/daily/20170520/example/broken.py", line 7, in broken
    return 1 / 0
ZeroDivisionError: division by zero

一方で構造化ログと言うのは以下のようなもの(通常はフォーマットされていない)。

{
  "time": "2017-05-20 21:15:24,348",
  "level": "INFO",
  "meg": "hello",
  "caller": "~/sandbox/daily/20170520/example/hello.py:8",
  "source": "app",
  "age": 20,
  "name": "foo"
}
{
  "time": "2017-05-20 21:15:24,348",
  "level": "ERROR",
  "meg": "broken",
  "caller": "~/sandbox/daily/20170520/example/broken.py:9",
  "source": "app",
  "stack": "Traceback (most recent call last):\n  File \"~/sandbox/daily/20170520/example/broken.py\", line 7, in broken\n    return 1 / 0\nZeroDivisionError: division by zero"
}

構造化ログの場合は、一度出力された後にcollector的なものが送信を行うにせよ、fluentdなどの何らかのブローカー的なものに丸投げするにせよ、最終的にはどこかのシステムのdata sourceとなり溜まっていく感じになると思う。

(パラメーターを自由に付けたりというのはむずかしい)という話

(パラメーターを自由に付けたりというのはむずかしい)という話。これに関しては括弧書きの理由は完全にそうと言えるわけではないし。作りが貧弱なせいもあるので何とも言えないのだけれど。これはこういう話のことを指していた。

pythonのloggingモジュールのロガーは、情報の呼び出しに付加的な情報をつける事ができる。最終的に文字列になるという話なら当然フォーマット文字列で済む話しではあるし。以下の様な感じで文字列を生成してあげれば良い(生成された文字列をそのままロガーに渡さないのはsentryなどでaggregateされたときなどのことを考えると自明ですね)。

logger.info("error is occured errno: %d", 404)
# 2017-05-20 21:27:04,692 INFO:__main__:error is occured errno: 404

また、loggingのロガーはログのフォーマットを変えたりすることもできて、ここに何を出力したいかを指定してあげる事もできる。例えば上の表示を以下の様に変える事もできる。

fmt = "%(asctime)s: level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
logging.basicConfig(level=logging.INFO, format=fmt)
logger.info("error is occured errno: %d", 404)

# 2017-05-20 21:29:40,159: level=INFO main.py:6 -- error is occured errno: 404

ここで利用できる属性は ドキュメントに書いてあるLogRecordの属性の部分だけなのだけれど。

extra というキーワードを付けることで、追加で利用できる属性を増やすことができる。

extraの罠

例えば、以下の様にして何らかの情報を追加できる。meという属性を追加できるようにしてみた。そしてログ出力時には me="(o_0)" という値を渡している。

# fmt = "%(asctime)s: level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
fmt = "%(asctime)s: me=%(me)s level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
logging.basicConfig(level=logging.INFO, format=fmt)
logger.info("error is occured errno: %d", 404, extra={"me": "(o_0)"})

# 2017-05-20 21:34:50,188: me=(o_0) level=INFO main.py:6 -- error is occured errno: 404

extraで渡されたmeが実際に上手くログに反映されてはいるのだけれど。これでは問題がある。この新たに追加されたmeを渡していないログの呼び出しはエラーになってしまう。

logger.info("ok")

こういう感じにエラーになる(meは必須なのに見当たらないという話)。

--- Logging error ---
Traceback (most recent call last):
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 980, in emit
    msg = self.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 830, in format
    return fmt.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 570, in format
    s = self.formatMessage(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 539, in formatMessage
    return self._style.format(record)
  File "/opt/local/python/3.5/lib/python3.5/logging/__init__.py", line 383, in format
    return self._fmt % record.__dict__
KeyError: 'me'
Call stack:
  File "main.py", line 13, in <module>
    main()
  File "main.py", line 6, in main
    logger.info("ok")
Message: 'ok'
Arguments: ()

さすがにこんなに引数にセンシティブなログは使いたくない気持ちを持つ人が多い。はず。そもそもこの方針はあんまり良くない。

extraはあんまり使いたくない

formatでの属性の追加は何かcontextualな情報を渡すための機能では無さそう。もうちょっとアプリの実行時には静的に決まっている情報などを付加的に表示するための機能のような気がしてきた。例えば実行時のhostなんかを載せたりだとか。そのためにfilterみたいな機能もある。

handlerとの関係を意識しないと使えないけれど。以下の様な感じで。

class HostInjector(logging.Filter):
    def __init__(self, name="", host=None):
        super().__init__(name)
        self.host = host

    def filter(self, record):
        record.host = self.host
        return True

def main():
    logger.info("ok")


if __name__ == "__main__":
    fmt = "%(asctime)s: host=%(host)s level=%(levelname)s %(filename)s:%(lineno)s -- %(message)s"
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(logging.Formatter(fmt))
    handler.addFilter(HostInjector(host="127.0.0.1:4444"))
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

こういう感じ。ログ出力に localhost:4444 というホストの情報を埋め込んでいる。

2017-05-20 22:00:58,859: host=127.0.0.1:4444 level=INFO main.py:17 -- ok

もう少し丁寧に説明すると、loggerは複数のhandlerを持ち、handlerはそれぞれ自分に割り当てられた処理をする(例えば上の例ではStreamHandlerが標準出力にメッセージを出力する)。handlerが利用する出力自体はFormatterが作成する。またloggerやhandlerは自身に渡ってきた情報を元に部分的に修正を加えるような変換を持つ事ができる。この変換はfilterによって行われる。と言うような感じ。

元々のloggingが持っている情報も込みで構造化ログを行いたい

extraで情報を与えることもできて、メッセージの出力結果が加工出来るようになったところで、構造化ログの話に戻ると、構造化ログはそもそも自由だった。自由にパラメータを付加する事ができるのだった。一方で既存のFormatterとformat文字列を渡す枠組みではそれに上手く対応する事ができない。

構造化ログの自由な引数の受け渡しに対応するためには何が必要かを整理してみる。

  • Loggerは、渡されたログ出力のためのイベントを生成する
  • Handlerは、イベントを待ち受ける。自分に渡されたイベントに従ったアクションを行う
  • Formatterは、渡されたイベントから生成されたメッセージ(正確にはLogRecord)を、整形して好みの出力表現に変える

まずFormatterは変える必要はありそう。

単純なformatterを作ってみる

単純なformatterを作ってみる。とりあえず、meを渡してみることにした。formatterはjson形式でdumpしている。

import json
import sys
import logging
logger = logging.getLogger(__name__)


class StructuralFormatter:
    def format(self, record):
        d = {"msg": record.msg, "me": record.me, "level": record.levelname}
        return json.dumps(d)


def main():
    logger.info("ok", extra=dict(me="(o_0)"))


if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

結果はこの通り。

{"msg": "ok", "level": "INFO", "me": "(o_0)"}

ただ問題が2つ位ある。1つは大した事がないのだけれど。あとの2つはとても問題。

  • loggerを使う際のextraが面倒くさい
  • ある特定の属性を付加することは出来るが、任意の属性を付加するということができていない。
  • 他のloggerに影響を与えるかもしれない(かもしれない)

後者がとても問題。問題の根本はどこにあるかというと、内部で作られるメッセージオブジェクト(LogRecord)が余分な情報(extra)を全部自分自身の属性としてsetattrしてしまう点。varsとかしてしまえば全部の情報を保持してしまうし。一方でデフォルトの情報を取り除くみたいな実装もしたくはない。

ちなみにvarsをrecordに対して使うとこういう感じの出力になる(フォーマットはしている)。

{
  "args": [],
  "lineno": 14,
  "relativeCreated": 1.5249252319335938,
  "msg": "ok",
  "exc_text": null,
  "module": "main",
  "processName": "MainProcess",
  "filename": "main.py",
  "process": 93274,
  "threadName": "MainThread",
  "funcName": "main",
  "levelname": "INFO",
  "created": 1495286618.802307,
  "levelno": 20,
  "me": "(o_0)",
  "thread": 140735293480960,
  "stack_info": null,
  "name": "__main__",
  "exc_info": null,
  "msecs": 802.3068904876709,
  "pathname": "main.py"
}

救世主はLoggerAdapter

loggingモジュールはLoggerAdapterというクラスも用意してくれている。これは何かと言うとLoggerのインターフェイスを持ったもののAdapterでprocess()を提供している。このオブジェクト経由で呼ばれた通常のログ出力のメソッド(info()やdebug()などのこと)は必ずこのprocess()を経由して内部に保持したロガーに渡される。そんなわけで、以下のようにLoggerAdapterを継承したクラスを使ってwrappingしてあげると良いことが起きる。

class StructLogger(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        information = {
            "extra": {
                "kwargs": kwargs,
                "structual": True,
            }
        }
        return msg, information


def get_logger(name):
    return StructLogger(logging.getLogger(name), {})


class StructuralFormatter:
    def format(self, record):
        d = {"msg": record.msg, "level": record.levelname}
        d.update(record.kwargs)
        return json.dumps(d)


def main():
    logger = get_logger(__name__)
    logger.info("ok", me="(o_0)")

良いことの1つ目はlogger.info等を利用したときの余分なextraの引数が不要になったこと。そしてもう1つの良いことは任意の引数に対応出来るようになったということ(実質kwargsというextraが渡されているだけなのでFormatterではkwargsを見るだけで良い)。

ただこれだけでは実用に耐えないのでもうちょっと頑張る必要がある

他のloggerと干渉しないformatterを作りたい

他のloggerと干渉しないformatterになるようにしたい。上で作った実装ではLoggerAdapterでラッピングしたオブジェクトを作るための独自のget_loggerを作っていた。とは言え既存のコードやライブラリの中ではこの独自のget_loggerではなく。通常の logging.getLogger が使われているということもありそうではある。これが干渉してしまってエラーにってはマズイ。

当然ではあるけれど、独自の get_logger を使わないで作ったloggerのログ出力はextraで期待した情報を含んでいないのでエラーが発生する。

logging.getLogger(__name__).info("ng")
# AttributeError: 'LogRecord' object has no attribute 'kwargs'

これを直したい。治す方法はそんなに大変ではなく、作ったAdapterでは何らかのマーカー的な情報(structual=True)を渡して、Formatterではそのマーカーを見て処理を分岐させれば良い。

class StructLogger(logging.LoggerAdapter):
    def process(self, msg, kwargs):
        information = {
            "extra": {
                "kwargs": kwargs,
                "structual": True,
            }
        }
        return msg, information


def get_logger(name):
    return StructLogger(logging.getLogger(name), {})


class StructuralFormatter:
    def __init__(self, formatter=None):
        self.formatter = formatter or logging.Formatter(logging.BASIC_FORMAT)

    def format(self, record):
        if getattr(record, "structual", False):
            return self.formater.format(record)
        d = {"msg": record.msg, "level": record.levelname}
        d.update(record.kwargs)
        return json.dumps(d)

今度は大丈夫。

logger = get_logger(__name__)
logger.info("ok", me="(o_0)")

raw_logger = logging.getLogger(__name__)
raw_logger.info("ng")

# {"msg": "ok", "me": "(o_0)", "level": "INFO"}
# INFO:__main__:ng

例外情報の取得

標準のloggingライブラリはexc_info=Trueをつけていれば例外情報をstack_info=Trueをそのときのスタックの情報を付加して出力してくれる。この機能も有効にしたい。

このstacktrace関連の機能、loggerをラップしたオブジェクトから呼ぶと意図しない位置を見たりしてしまう。だとか色々な懸念があってあんまり触れたくないな〜みたいな感じの気持ちになっていたりしたのだけれど。真面目にloggingモジュールのコードを読んだ結果。loggingモジュールに定義されているオブジェクトに限り特別扱いの優遇措置を行なってくれているので、これもそんなに大変ではなくちょっとした修正で対応できる。

@@ -9,7 +9,9 @@
             "extra": {
                 "kwargs": kwargs,
                 "structual": True,
-            }
+            },
+            "stack_info": kwargs.pop("stack_info", False),
+            "exc_info": kwargs.pop("exc_info", False),
         }
         return msg, information
 
@@ -26,14 +28,18 @@
         if not getattr(record, "structual", False):
             return self.formatter.format(record)
         d = {"msg": record.msg, "level": record.levelname}
+        if record.exc_info:
+            d["stack"] = self.formatter.formatException(record.exc_info)
+        if record.stack_info:
+            d["stack"] = self.formatter.formatStack(record.stack_info)
         d.update(record.kwargs)
         return json.dumps(d)

これでこのstack_info=Trueを付加してstack traceを一緒に表示させたいコードの結果は

def main():
    logger = get_logger(__name__)
    logger.info("ok", me="(o_0)", stack_info=True)
    logging.getLogger(__name__).info("ng", stack_info=True)


if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()

以下のようになる。stackという部分にstack traceの情報が詰まっている。整形方法などは既存のformatterにおまかせしている。

{"me": "(o_0)", "stack": "Stack (most recent call last):\n  File \"main.py\", line 49, in <module>\n    main()\n  File \"main.py\", line 41, in main\n    logger.info(\"ok\", me=\"(o_0)\", stack_info=True)", "msg": "ok", "level": "INFO"}

INFO:__main__:ng
Stack (most recent call last):
  File "main.py", line 49, in <module>
    main()
  File "main.py", line 42, in main
    logging.getLogger(__name__).info("ng", stack_info=True)

(内部的にスタックトレースの取得に使っているloggingのfindCallerというメソッドが自分自身のsourceファイル(logging/init.py)だけは特別扱いしてくれているので、LoggerAdapterを経由してのラッピングなら、ログ出力の実行位置を気にすること無く期待通りの結果を返すのも嬉しい(例えば、filenameやlinenoなどの情報など))

contextual logging

contextual loggingについて

LoggerAdapterを使ったことには、もう1つ幸運が隠されていて。それはcontextual loggingに対応する事がとても簡単なこと。contextual loggingとは何かというと、コード中の実行時のそのスコープに依存した情報を保持して蓄えたロガーを提供できるという機能。

例えば、structlogというライブラリでもこれらの機能は利用する事ができる。

"""
実行時の関数の呼び出し関係は以下の様になっていて、hでは渡されていない情報をログ出力では利用したいということがある。
f:
  g:
    h:
"""

import time
from structlog import get_logger


def f(logger, x):
    logger = logger.bind(time=time.time()).bind(f="on f")
    return g(logger, x)


def g(logger, x):
    logger = logger.bind(g="on g")
    return h(logger, x)


def h(logger, x):
    logger = logger.info("h is called")
    return x * x


if __name__ == "__main__":
    logger = get_logger(__name__)
    f(logger, 10)
    logger.info("end")

hで呼び出されたloggerはそのスコープの文脈に依存した情報(f,g,time)を持っているのでログ出力時にそれらに関する情報も出力する。一方でトップレベルのロガーには影響を与えていない。

time=1495288627.372377 f='on f' g='on g' event='h is called'
event='end'

こういうできごとは例えばバッチ処理を書くときなどにけっこう起きる。ロギングが難しいのは通常の関数ではlexical scope的なもので良い一方でロギングに使う値に関しては一部dynamic scope的(実行時の呼び出し関係のトップレベルの情報)な情報が欲しくなるところ。例えばバッチのトップレベルでbatch idみたいなものを情報として付加しておきたいが、後々の末端の操作ではbatch idから取得したもっと瑣末な値が対象になっている。一方でログ出力にはどのバッチの処理だったかも記録したいのでbatch idが含まれて欲しい。そういう感じ。こういう自体に対応するためにcontextual loggingはある。

一方で、そのためにはロガーもしくはそれを保持した値を持ち回らないとだめにはなってしまっている。

contextual loggingへの対応

構造化ログはしばしばcontextual loggingへの対応を謳っている事が多い。今まで作ってきたロガーでも対応してみることにしよう。structlogと同様にbindというメソッドをもたせるようにしてみる。

これは実はそんなに大変ではなくって、今まで作っていたLoggerAdapterにメソッドをちょっと追加して変更を加えるだけで良い。

@@ -1,8 +1,14 @@
+from collections import ChainMap
+
+
 class StructLogger(logging.LoggerAdapter):
+    def bind(self, **kwargs):
+        return self.__class__(self.logger, ChainMap(kwargs, self.extra))
+
     def process(self, msg, kwargs):
         information = {
             "extra": {
-                "kwargs": kwargs,
+                "kwargs": ChainMap(kwargs, self.extra),
                 "structual": True,
             },
             "stack_info": kwargs.pop("stack_info", False),

これで contextual logging の対応は終わる。先程のstructlogで行なったコードの例はこちらでも動く。

def main():
    logger = get_logger(__name__)
    f(logger, 10)
    logger.info("end")

if __name__ == "__main__":
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(StructuralFormatter())
    logging.basicConfig(level=logging.INFO, handlers=[handler])
    main()
{"level": "INFO", "time": 1495289299.355759, "f": "on f", "g": "on g", "msg": "h is called"}
{"level": "INFO", "msg": "end"}

最後の状態のgistはこんな感じ

https://gist.github.com/podhmo/c8b15022fd4b09c9c15e45f1f511f697

ちなみにlogging.StreamHandlerを使っているのでstringであることを前提にしているけれど。辞書のまま使いたいのであればそのようにコードを変更する事もできる。また内部的に使う辞書をOrderedDictにすれば好みの順序でのログ出力もされるようになる。

参考