構造化ログから構造化イベントへ

オブザーバビリティ・エンジニアリングの5章のタイトルは「構造化イベントはオブザーバビリティの構成要素である」です。構造化イベントの定義は5.1節にあります。

イベントとは、本番環境のサービスへの影響を理解するために、ある特定のリクエストがそのサービスとやりとりしている間に発生したすべての記録です。

そこからさらにイベントの記録について説明が続きます。

空のマップを初期化することから始めます。このマップには、そのリクエストの有効期間中に発生したものに関する興味深い詳細、たとえばユニークID、変数の値、ヘッダー、リクエストで渡されたすべてのパラメーター、実行時間、リモートサービスへのコール、それらのリモートコールの実行時間など、後にデバッグに役立つであろうあらゆるコンテキストが追加されます。そして、リクエストが終了したりエラーが発生したりすると、そのマップ全体はリッチな情報として取得されます。

つまり、ログを1リクエストあたり1行まで減らす代わりに、ログのカラムを大幅に増やすのです。

構造化イベントという用語はオブザーバビリティ・エンジニアリングの著者が所属している honeycomb.io が利用している用語のようですが、広く定着しているわけでは無さそうです。同じプラクティスにStripeはCanonical Log Linesという名前を使っているようです。

brandur.org

structlogのドキュメントのBest PracticesでもCanonical Log Linesが紹介されています。

www.structlog.org

さて、ここを見るとCanonical Log Linesを実現するためにbindが使えそうに書いてあります。

structlog’s ability to bind data to loggers incrementally (snip) can help you to minimize the output to a single log entry.

しかし、 log.bind() の動作は（GoのContextのような）スタック型になっていて、リクエストの処理の最後にまとめて書き出すために属性を追記していくのには向きません。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    log = logger.bind(foo="bar")
    log.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"arg": "world", "event": "goodby"}

このサンプルでは foo="bar" が最後のログに反映されていません。これでは hello() の中でログを書くのをやめられません。

このスタック型にkey-valueを積み重ねていく設計は、immutableで一般的にはセンスの良いものですが、構造化イベントを実現するのに向いているとは思えません。

structlogのドキュメントではあまり言及されていない structlog.get_context() というAPIを使えば、loggerが持っているbind()済み変数が保存されたdict(=Context)を直接編集できるので、追記型の振る舞いも実現できます。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    lg = structlog.get_context(logger)
    lg["foo"] = "bar"
    logger.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"foo": "bar", "arg": "world", "event": "goodby"}

このサンプルで最後に "foo": "bar" が出力されているので、hello()の中のログを消せるようになりました。このとき、 lg["foo"] = "bar" の部分は lg["hello.foo"] = "bar" か lg["hello"] = {"foo": "bar"} と書き換えると良いと思います。

構造化イベントのサポートが弱いのは、structlogだけではなく多くの構造化ログライブラリに共通する点だと思います。しかし、リクエストスコープのコンテキストを持つ仕組みは一般的なので、構造化イベントの実装は難しくありません。

例えばFlaskであれば flask.g.log_event = {} みたいな辞書を用意して、そこにイベントを足していけば良いでしょう。この仕組みなら、Goでもリクエストの先頭でContext にイベント追記用の map か sync.Map を格納すれば良いでしょう。

ここまで構造化イベントをベストプラクティスとして紹介してきましたが、私は全てのログを構造化イベントにまとめるべきだとは思っていません。メトリクスを抽出したり、ユーザーの行動分析に役立つ要素なら構造化イベントが適していると思いますが、デバッグに役立つ中間値や分岐を残すログであったり、パフォーマンス分析のためにタイミングを記録するログまで構造化イベントにする必要はないでしょう。

そのようなログは、リクエストIDと限られた属性だけをbindしたカラムの少ないログをデバッグレベルで出力するとか、トレーシングを使っているならトレースの属性やイベントとして記録するのが良いでしょう。ログを分けることで、保存期間を分けたり、異なるサンプリングをできます。たとえば構造化イベントは全てのログに対してとってアクセスログと同じ期間記録し、デバッグやパフォーマンス分析用のログはトレースと一緒にサンプリングしてより短い期間で破棄すると良いでしょう。