structlogを用いた構造化ログの導入

Webアプリケーションやバッチジョブを運用していくにあたって、エラーの影響範囲の調査のため、APIへのアクセスIDやバッチのジョブIDのついたログは欠かせないです。

このような類のIDをログとして残す場合には、そのIDの影響下にある全部の処理に対して該当のIDを渡したいです。

この類の処理をフルスクラッチで書こうとする場合、下記事項を考慮する必要があります。

ログのために既存のコードの引数を変えることはしたくないため、IDをロガー経由で渡す必要がある
IDを渡されるロガーは処理の間はIDを保持してほしい、それ故ロガーはシングルトンインスタンスか、それに相当するモジュールになる
asyncの入ったコードに対応するにはasyncio コルーチン間の割り込みを考慮する必要がある

また、ログレベル、ログの出力時刻等の個々のログに付随する属性を解析する際にmachine readableになっていてほしいという要望もあります。

これらを考慮した処理を実現してくれるライブラリが今回紹介する structlog になります。

www.structlog.org

~~Tomcatライクなロゴが印象に残ります。~~

導入

毎度おなじみpipです

pip install structlog

処理IDが絡んだログのサンプル

structlogを用いて処理IDをロガーにどのように出力させるか見ていきます。

まずユーザIDをログに出力するサンプルコードとして以下を考えます。

from structlog import get_logger

log = get_logger()


def some_other_function():
    log.info('other event')

def main():
    some_response = {'user_id': 12, 'user_agent': 'Chrome'}
    # some_response = {'user_agent': 'Chrome'}

    if 'user_id' in some_response:
        log.info('some event', user_id=some_response['user_id'])
        some_other_function()
    else:
        log.info('exceptional prec')
        some_other_function()


if __name__ == '__main__':
    main()

structlogはロガーのdebug, info等のメソッドに任意のフィールドを追加して出力することができます。(l.14) この実装の場合だと以下のようなログ出力になり、冒頭で想定した「IDの影響下にある処理のログにすべてIDがついてほしい」という要件を満たせません。

2021-05-25 19:04.28 [info     ] some event                     user_id=12
2021-05-25 19:04.28 [info     ] other event

ログコンテキストの構築

IDの影響下にある処理のログすべてにIDを持たせるには、次のように書きます。

import structlog
from structlog.threadlocal import (
bind_threadlocal,
clear_threadlocal,
merge_threadlocal
)
from structlog import configure


configure(
    processors=[
        merge_threadlocal,
        structlog.processors.add_log_level,
        structlog.processors.StackInfoRenderer(),
        structlog.dev.set_exc_info,
        structlog.processors.format_exc_info,
        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S", utc=False),
        structlog.dev.ConsoleRenderer()
    ]
)
log = structlog.get_logger()


def some_other_function():
    log.info('other event')

def main():
    some_response = {'user_id': 12, 'user_agent': 'Chrome'}
    # some_response = {'user_agent': 'Chrome'}

    if 'user_id' in some_response:
        bind_threadlocal(user_id=some_response['user_id'])
        log.info('some event')
        some_other_function()
    else:
        log.info('exceptional prec')
        some_other_function()

    clear_threadlocal()

if __name__ == '__main__':
    main()

structlog.threadlocal モジュールはスレッド単位でログに出力される属性を管理します。

merge_threadlocal : ログの設定のprocessorにかませることでスレッドに固有の変数をログに出力するよう設定が行われます
bind_threadlocal : スレッドに固有の変数のロードを行います
clear_threadlocal : スレッドに固有の変数をクリアします

このケースでは以下のログが出力され、user_id が見つかった後の処理すべてにIDが付与されることがわかります。

2021-05-25 20:30.50 [info     ] some event                     user_id=12
2021-05-25 20:30.50 [info     ] other event                    user_id=12

Python3.7　より導入されたcontextvarsモジュール関連の機能で structlog.contextvars モジュールもあります。これは asyncio を用いるようなサーバサイドAPIにおける、ID情報を付加したロギングに有効です。

構造化ログについて

もう一点、structlogがサポートする構造化ログについても見ていきます。下記のログはpythonを開発していればよく出力する形式のログです。

2021-04-02 10:47:02 [INFO] some precessing log

この類のログはhuman readableではありますが、ログの解析を行う際にはmachine readableではないので不便です。

構造化ログとはログの出力として頻繁に出される時刻、ログレベル、ログ本体等の情報がmachine readableな構造化データ（Json, TSV）にされたものを指します。

{
  "message": "some processing log", 
  "lineno": 1590, 
  "pathname": "/app/job/src/apiclient.py", 
  "job_id": 20, 
  "timestamp": "2021-04-02 10:47:02", 
  "level": "info"
}

このような形式のログもstructlogはサポートしています。

Json形式のログ設定サンプル

Jsonのログ出力用設定のサンプルです

import sys
import structlog
from structlog.threadlocal import (
bind_threadlocal,
clear_threadlocal,
merge_threadlocal
)
import logging


structlog.configure(
    processors=[
        merge_threadlocal,
        structlog.stdlib.filter_by_level,
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.processors.JSONRenderer()
    ],
    context_class=dict,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)
logging.basicConfig(
    format="%(message)s",
    stream=sys.stdout,
    level=logging.INFO,
)

log = structlog.get_logger()


def some_other_function():
    log.info('other event')

def main():
    some_response = {'user_id': 12, 'user_agent': 'Chrome'}
    # some_response = {'user_agent': 'Chrome'}

    if 'user_id' in some_response:
        bind_threadlocal(user_id=some_response['user_id'])
        log.info('some event')
        some_other_function()
    else:
        log.info('exceptional prec')
        some_other_function()

    clear_threadlocal()

if __name__ == '__main__':
    main()

ロガーの出力を標準入出力に吐く設定がstructlog経由で行えないのは謎ですが、標準ライブラリのロガーを生成するようにstructlog経由で設定でき(l.25)、標準ライブラリのロガーに対して標準入出力に出力するように設定しています(l.29)

以下出力です

{"user_id": 12, "event": "some event", "logger": "__main__", "level": "info", "timestamp": "2021-05-26T03:16:44.301541Z"}
{"user_id": 12, "event": "other event", "logger": "__main__", "level": "info", "timestamp": "2021-05-26T03:16:44.301945Z"}

構造化されたログが出力されました。