構造化ログと実装 -Goのslogによる実践-

Go

この記事は、CYBOZU SUMMER BLOG FES '24 (クラウド基盤本部 Stage) DAY 4の記事です。

クラウド基盤本部Cloud Platform部の pddg です。cybozu.comのインフラ基盤移行まだまだがんばっています。

今回の記事は、社内向けに書いていた「構造化ログとは何か・Goのslogパッケージをどう使うべきか」という話を一般向けに書き直したものです。なんとなくslogを使っているという状態から、チームでどのようにログを取るべきか方針を決められるようになるくらいの状態に持っていくための一助になればと思います。

背景

構造化ログとは、主にJSONなどの機械的に読み取り可能な形でパラメータを付加した形式のログのことです。このようなログは、付加したパラメータなどを動的にパースしてフィルタ・加工することで、容易にログを絞り込んだり可視化に利用しやすいというメリットがあります。それなりの規模に達したアプリケーションのログはもはや人が目で追いきれるものではないため、ツールの力を使って人が読める量・読める表現に落とし込むことが重要になってきており、そのためには構造化ログは事実上必須となっていると筆者は感じています。

同じ情報を表す以下のログ行について考えてみます。構造化ログの方は単にJSONとしてパースすれば、jqのようなCLIツールやGrafana Loki*1のLogQL*2などのクエリによってログ行を加工できるツールで容易に扱えます。一方、フラットに書かれた後者のログはまずはパースのために法則性を見出して正規表現などを駆使する必要があります。

{"logged_at":"2024-06-20T00:00:00Z","severity":"INFO","message":"ok","http_method":"GET","url":"/api","http_status_code":200,"response_time":10}

2024-06-20T00:00:00Z INFO: ok GET /api 200 10

これはまだアクセスログであるため簡単ですが、次のようなログ行が非常に多数あるのであればどうでしょうか。筆者の感覚としては、ここから特定のユーザに関するログのみを抽出するのは割と大変だろうと思っています。

2024-06-20T00:00:00Z INFO: created "Example" user (user_id=10)
2024-06-20T01:00:00Z INFO: update user 10 "Example2" from "Example"
2024-06-20T02:00:00Z INFO: user 10 logout

他にも、上記のようなログを何も考えずJSONにするだけでは恩恵は薄いです。以下に示すログは確かにJSONになっていますが、肝心のmessageの中身はそのままで、ユーザ単位での絞り込みなどが難しい点はほとんど変わっていません。

{"logged_at":"2024-06-20T00:00:00Z","severity":"INFO","message":"created 'Example' user (user_id=10)"}
{"logged_at":"2024-06-20T01:00:00Z","severity":"INFO","message":"update user 10 'Example2' from 'Example'"}
{"logged_at":"2024-06-20T02:00:00Z","severity":"INFO","message":"user 10 logout"}

同じ内容を示す扱いやすい構造化ログにするなら、例えば以下の様にすると良いでしょう。

{"logged_at":"2024-06-20T00:00:00Z","severity":"INFO","message":"user created","username":"Example","user_id":10}
{"logged_at":"2024-06-20T01:00:00Z","severity":"INFO","message":"user updated","from":"Example","to":"Example2","user_id":10}
{"logged_at":"2024-06-20T02:00:00Z","severity":"INFO","message":"user logout","user_id":10}

つまり、構造化ログはJSONなどの機械的に読み取り可能なフォーマットで記述したものですが、「扱いやすい」構造化ログとは、単にJSONを使っていれば達成できるというものではないということです。

構造化ログに求められるもの

機械的に読み取り可能なフォーマット

これはまず必ず備えられているべき性質です。つまりあるフォーマットに従って内容をパース出来れば良いということです。現在の構造化ログの多くで用いられているのはJSONです（筆者の主観）。ただし、このような性質を備えるものはJSONだけという訳ではありません。一行にまとめて書くことができ、機械的に読み取り可能なテキストフォーマットのうち正規表現によるパースを除けば、例えば以下の様なものも存在しています。

  • CSV
    • カンマ区切り
  • TSV
    • タブ区切り
  • LTSV
    • Labeled Tab-Separated Values
    • label1:value1\tlabel2:value2 みたいなフォーマットになっている
  • logfmt
    • key1=value1 key2=value2 のような形式で記述する

LTSVは一昔前に主にWebサーバ（Apache HTTP Serverやnginx）のログで使われ、Fluentdなどもデフォルトでサポートしています。logfmtは最近Grafanaが推している印象があります。一方、多くのクラウドサービスではJSONが用いられる傾向にあるようです。CloudWatch Logs、GCP Cloud Logging、DataDog LogsなどがデフォルトでJSON形式の構造化ログに対応しています。

JSON方式は仕様がきっちり決まっており、人が書くことも読むこともでき、パラメータをネストできるという明確なメリットがあります。ただしネストされたパラメータを扱えるかはサービスによって異なり、例えばGrafana Lokiではネストされたパラメータを容易に扱うことはできません*3。

ログメッセージとパラメータの分離

ログとは基本的にはイベントデータのようなものです。何らかの操作が発生した、こういうアクセスが来た、こういうリクエストを送った……。そのアクションと、そのアクションを構成するパラメータを分離することが解析しやすい構造化ログを構成するために必要であると筆者は感じています。

例えばアクセスログも自然言語的に書けば以下の様になりますが、これは非常に扱いづらいものです。

User named "Example" accessed to /api/info from xx.xx.xx.xx at 2024-06-18 00:00:00 UTC, then the server returns 200 OK in 100ms

こうなっている方が、機械的に検証しやすいでしょう。

{"logged_at":"2024-06-18T00:00:00Z","message":"access log","url":"/api/info","http_method":"GET","http_status_code":"200","response_time":0.1,"remote_ip":"xx.xx.xx.xx","username":"Example"}

このように、ログ出力内容をより解析しやすいよう、記録したいアクションとそれを構成するパラメータを分けて記述しましょう。

一連の操作を特定するパラメータの付与

基本的にWebサービスのシステムでは、他のサービス・クライアントからのリクエストであったり、時刻的なトリガーを元に起動するシステムのようなものが多いです。それらは一定のアクションを行い、終了します。次のトリガーが来たらまたそれを処理するアクションを行い、終了します。このトリガーは同時に複数存在することもあります。例えば、あるAPIのあるパスへのリクエストが同時に複数来ることは高トラフィックなサービスではよくあることです。ここで、ユーザ名を変更するというAPIがあったとして、そのログを考えてみましょう。

{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":10,"username":"Example2"}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":200}

うん、悪くないですね。では2つのリクエストが同時に来て、そのうちの一つが失敗した場合はどうでしょうか。

{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH"}
{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":10,"username":"Example2"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":11,"username":"Example3"}
{"logged_at":"2024-06-18T00:00:02Z","message":"failed tp update user","user_id":11,"username":"Example3","error":"failed to connect to database"}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":200}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":500}

まだギリギリ意味は分かりそうです。 user_id: 11 のユーザの更新に失敗し、その結果500が返ったとだいたいの人には伝わりそうに思います。ただ、これは人の想像に大きく依存してしまっている面があります。500が返ったというログはありますが、これが user_id: 11 の操作と必ずしも結びつけるとは限りません。もっと前のリクエストが遅延していて、このタイミングで完了しただけかもしれません。また、このときの失敗したAPIリクエストに関するログ全てを抽出してほしいと言われると、膨大なログの海の中からそれっぽいものを手動で取り出すしかありません。これらに共通するパラメータがなく、機械的に特定できないからです。

そこで利用されるのがいわゆるリクエストIDや、トレースIDと呼ばれるものです。各操作に対して十分にランダムなIDを採番し、それをログに付与します。これはユニークな値であるため、ある特定の操作のログを十分に特定出来ます。一度先ほどのログにトレースIDを付与してみます。ここではわかりやすくするため、適当なトレースIDを利用しています。

{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH","trace_id":"XXX"}
{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":10,"username":"Example2","trace_id":"XXX"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":11,"username":"Example3","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:02Z","message":"failed tp update user","user_id":11,"username":"Example3","error":"failed to connect to database","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":200,"trace_id":"XXX"}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":500,"trace_id":"YYY"}

user_id: 11 さんの操作に失敗したログのトレースIDは YYY のようですね。では trace_id: YYY で絞り込んでみれば、リクエストが飛んできてからレスポンスが返るまでの一連の操作が分かるはずです。

{"logged_at":"2024-06-18T00:00:00Z","message":"request start","url":"/api/user","http_method":"PATCH","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:01Z","message":"update user","user_id":11,"username":"Example3","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:02Z","message":"failed tp update user","user_id":11,"username":"Example3","error":"failed to connect to database","trace_id":"YYY"}
{"logged_at":"2024-06-18T00:00:02Z","message":"request end","url":"/api/user","http_method":"PATCH","http_status_code":500,"trace_id":"YYY"}

トレースIDをどのように定義するかはやや考える必要があります。利用するSaaS、IaaSによって独自のものが定義されている場合もあります（例：AWS X-Rayの X-Amzn-Trace-Id ）。 HTTPのリクエストでは最近はOpenTelemetryなどでデフォルトのフォーマットとして採用されているW3C Trace ContextがW3Cによって定義され、今後はデファクトスタンダードになっていくと思われます。OpenTelemetryのライブラリを利用することで、ある程度楽に実装出来るはずです。

実際にサイボウズのサービスでは一部このW3C Trace Context準拠の traceparent ヘッダへの対応を始めており、ログの絞り込みだけでなくGrafana Tempo*4による分散トレーシングにも活用されています。

適切なメタデータの付与

アクションを構成するパラメータ以外にも、付与しておくと嬉しいデータがあります。

  • ホスト名
    • 複数あるアプリケーションサーバのうちのどれで処理されたのかを特定したい等
  • そのログがどこに出力されたか
    • ログ基盤に回収された後に、どこに書かれたログなのかを特定する必要がある場合
  • そのサービスを特定するパラメータ
    • 色々なサービスのログが混在するところから特定のサービスのログを抽出したい等

これらのパラメータを誰がどのように付与するかはいくつか方式が考えられます。

最もシンプルにやるならば、そのログを出力するアプリケーション自体がこれらの情報を付与するように構成できます。起動時にホスト名やサービス名などをロガーの設定に注入したり、実際に出力する際にその出力先をログに含められます。

もう一つ、これらのログを回収して集約するための基盤に送信する際に付与する方法もあります。例えばfluentd、promtail等のログを回収するエージェントがこれらの情報を自動で付与することもできます。これは特にアプリケーション内部から把握することが難しい（もしくは面倒な）メタデータも付与出来るという意味で有用です。例えばKubernetesのnamespaceや、そのVMが動作している実際の物理ホストの情報などはアプリケーションが内部から知ることは難しく、これらを自動でログに付与するにはこういったログ回収エージェントを使うのが良いでしょう。

実際にサイボウズのKubernetesクラスタではコンテナがstdout・stderrに吐いたログは各ノードにデプロイされているpromtailによって回収され、その際promtailは情報を加工して複数のメタデータを含めてGrafana Lokiに送信するようになっています。

slogパッケージによる実践

ここからは実際にこのようなログ出力をどのようにアプリケーションへ実装するかを解説していきたいと思います。筆者はGoが書けるので、Goにおける実装方法として考えられるものを紹介します。

Goにはロギングの機能を提供するパッケージが公式に（Go 1.22の時点では）2つ存在しています。昔からある log パッケージと、最近追加された log/slog パッケージです。 log は非常に簡易なログの機能を提供しています。 log パッケージが提供する機能は驚くほどシンプルで、細かい機能は多少あるものの、できることは概ね下記の2つだけです。

import "log"

func main() {
    const val = "world"
    log.Printf("hello %v\n", val) // 2009/11/10 23:00:00 hello world
    log.Fatalf("hello %v\n", val) // 2009/11/10 23:00:00 hello world
    // os.Exit(1) is called
}

https://go.dev/play/p/IMdYA83DxPM

一応 log.New という関数に特定のフラグを渡すことでログの出力内容を多少調整できるものの、任意のフォーマットでログを出力するといった機能は無く、severityなどの概念も存在しません。当然JSONでログを出力するといったこともできません。

機能的に足りないという背景から、Goではいくつかのロギングのためのモジュールが乱立してきました。有名どころでは以下の様なものがあります。

実際にこれらのモジュールを参考に、新たなパッケージである log/slog は実装されました。design docでも言及されており、これらのモジュールが備えていた構造化ログのための仕組みが参考にされています。

簡単に使うだけなら以下の様に使い始められます。ただしデフォルトではログはJSON形式にはなっていません。

import "log/slog"

func main() {
    slog.Info("info level log", "key", "value") // 2009/11/10 23:00:00 INFO info level log key=value
    slog.Warn("warning message")                // 2009/11/10 23:00:00 WARN warning message
    slog.Error("error message")                 // 2009/11/10 23:00:00 ERROR error message
}

https://go.dev/play/p/scJhYRVLYDg

機械的に読み取り可能なフォーマットで出力する

まずは必須であるフォーマットの変更を行います。そのためにはslogのアーキテクチャを知っておくとよいでしょう。slogは、ユーザが通常ログを記録するために使うフロントエンドのインターフェースである Logger と、Loggerからログの内容（ Record ）を渡され実際に何らかの形で出力する Handler に分かれています*5。

JSONで出力するためには、公式で提供されている JSONHandler を利用できます。

import (
    "log/slog"
    "os"
)

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level: slog.LevelInfo,
    }))
    logger.Info("hello world", "key", "value") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello world","key":"value"}
}

独自のフォーマットで出力したい場合も自身でHandlerを実装することで実現可能です。

グローバルなloggerの設定

JSONHandlerを使うためにコードのあらゆるところで slog.New すると、あらゆる箇所でHandlerの指定などが必要になってしまいます。実は slog.Info などで呼び出されるグローバルなLoggerを変更する方法が提供されているので、起動時などに一度グローバルのLoggerを変更することで、他の箇所では単に slog.Info や slog.Error を使うだけで同じフォーマットで出力できるようになります。

import (
    "log/slog"
    "os"
)

func otherFunc() {
    slog.Info("call in other func", "key", "value") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"call in other func","key":"value"}
}

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level: slog.LevelInfo,
    }))
    slog.SetDefault(logger)
    slog.Info("hello world", "key", "value") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello world","key":"value"}
    otherFunc()
}

https://go.dev/play/p/khKffCP9cGJ

これは同パッケージ内だけでなく、全てに波及します。よって自作モジュール内で slog.~~ な関数を使ってログを出力するようにしておけば、それを使う側が自由にログの出力方法や出力するログのレベルを変更できるというわけです((ただし、依存モジュール内で slog.New して独自のLogger・Handlerを使っている箇所には影響しないことに注意が必要です。))。

グローバルなLoggerに事前にkey valueを設定しておくこともできます。例えばホスト名を埋め込んでおきたい場合は以下の様に設定できます。

   hostname, err := os.Hostname()
    if err != nil {
        panic(err)
    }
    slog.SetDefault(logger.With("hostname", hostname))

この設定完了以降に呼ばれたログの記録には全て "hostname": "ホスト名" というパラメータが含まれるようになり、あらゆる所でホスト名をパラメータに追加する必要はありません。

パラメータを付与する

既に単純な "key": "value" の例は出てきていますが、ここではより複雑な例やよくある失敗例を紹介します。まず、複数のパラメータを渡したい場合はkeyとvalueのペアになるように渡します。

slog.Info("message", "key1", "value1", "key2", "value2")

ここで、key valueのペアが一致しない数渡されると、一致しないぶんはvalueとして扱い、 !BADKEY というキーで出力されます。

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{}))
    logger.Info("message", "keyonly") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","!BADKEY":"keyonly"}
}

https://go.dev/play/p/J5fUpf6DcZU

なお、このような問題は go vet により検出されます。 go vet は go test 時に自動で実行されているので、CIでは有効化しておくようにしましょう。

あるパラメータをネストして渡すこともできます。例えばhttpに関するパラメータを以下の様にしてまとめられます。

// デフォルト： 2009/11/10 23:00:00 INFO message http.method=GET http.path=/ http.status=200
// JSON： {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","http":{"method":"GET","path":"/","status":200}}
slog.Info("message", slog.Group("http", "method", "GET", "path", "/", "status", 200))

自分で定義したstructに LogValue() slog.Value という関数を実装しておくことで、slogは出力時にこれを使ってくれるようになります。

type MyStruct struct {
    value1 string
    value2 string
}

func (m MyStruct) LogValue() slog.Value {
    return slog.GroupValue(
        slog.String("key1", m.value1),
        slog.String("key2", m.value2),
    )
}

func main() {
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))
    instance := MyStruct{
        value1: "hoge",
        value2: "fuga",
    }
    slog.Info("message", "mystruct", instance) // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","mystruct":{"key1":"hoge","key2":"fuga"}}
}

https://go.dev/play/p/oxZeULLzGHx

このようなパラメータの付与を毎回書くのは面倒です。 slog.With を使ってパラメータを埋め込んだloggerを作成できます。このloggerはグローバルなloggerをコピーして作成されるので、この With で付与したパラメータがグローバルに作用することはありません。

logger := slog.With("key", "value")
logger.Info("message") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","key":"value"}
logger.Info("message2") // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message2","key":"value"}

ReplaceAttr オプションでkeyやvalueを書き換える

slog.JSONHandler が出力するキーや日時のフォーマットは固定になっており、設定から指定することが出来ません。 しかし、 slog.HandlerOptions の ReplaceAttr という任意の変換を行う関数を指定することで、デフォルトのキー名を書き換えるような操作や、日時のフォーマットを変換する操作ができるようになっています。

   logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
            switch a.Key {
            case slog.TimeKey:
                a.Key = "logged_at"
                a.Value = slog.StringValue(a.Value.Time().Format(time.UnixDate))
            }
            return a
        },
    }))

https://go.dev/play/p/6ErYqB-a3vw

後から付加されたkey・valueもこの関数で変換出来るので、例えばpasswordなどの機微情報を潰したりすることも一応可能です。

Tips: stringのdefined typeをキーとして使ってはいけない

defined typeは新しい型を作るときによく用いられています。例えばUser IDを表現するのに type UserID int64 を作ったりすることがあります。

type Key string

func main() {
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))

    const keyStr = "key"
    slog.Info("message", keyStr, "value")

    const key Key = "key"
    slog.Info("message", key, "value")
}

https://go.dev/play/p/avWsJuLvxhQ

Key が文字列なのでこのように指定できるように思いがちですが、実際にはこのケースの出力は以下の様になってしまいます。

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","key":"value"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"message","!BADKEY":"key","!BADKEY":"value"}

slogパッケージがkey valueのペア、もしくは slog.Attr を識別して変換する関数では、key の型が string であることを期待しています。そのため、 key にdefined typeを用いるとその型が仮に Stringer interfaceを満たしていてもkeyではなくvalueとして扱われるようになっています。なお、これも go vet により検出されます。

ただし、 slog.With を使う場合は（Go 1.22.5時点では） go vet による検出に対応できていないようです。以下の様な例でも同じ結果になりますが、こちらは go vet によって検出されませんでした。 slog.With や logger.With を使う場合、現状は気をつけるしかなさそうです。

type Key string

func main() {
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))

    const keyStr = "key"
    slog.With(keyStr, "value").Info("message")

    const key Key = "key"
    slog.With(key, "value").Info("message")
}

Tips: slog.Attrとパフォーマンス

keyとvalueのペアとして渡す以外に、 slog.Attr 型、 slog.Value 型で渡すという方法もあります。

// slog.Info("message", "key", "value") と等価
slog.Info("message", slog.String("key", "value"))

// これも等価
slog.Info("message", "key", slog.StringValue(value))

ただし簡単なベンチマークを取った限りでは、この方法はむしろ遅くメモリアロケーションの数も多かったです。slogのドキュメントによると最も効率的なのは slog.LogAttrs という関数を使うことだと書かれていました*6。これは slog.Attr 型しか受け付けません。しかし簡単なベンチマークを取った限りでは、 slog.Info("message", "key", "value") とする方法とほとんど大差なく、利便性を考えると多くのケースでは slog.Attr をあえて使う必要性は薄いように感じました。

package main_test

import (
    "context"
    "io"
    "log/slog"
    "testing"
    "time"
)

func TestMain(m *testing.M) {
    slog.SetDefault(slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
        Level: slog.LevelInfo,
    })))
    m.Run()
}

func BenchmarkSlogRaw(b *testing.B) {
    for range b.N {
        slog.InfoContext(context.Background(),
            "message",
            "key", "value",
            "key2", 1,
            "key3", true,
            "key4", time.Time{},
        )
    }
}

func BenchmarkSlogAttrValue(b *testing.B) {
    for range b.N {
        slog.InfoContext(context.Background(),
            "message",
            "key", slog.StringValue("value"),
            "key2", slog.IntValue(1),
            "key3", slog.BoolValue(true),
            "key4", slog.AnyValue(time.Time{}),
        )
    }
}

func BenchmarkSlogAttr(b *testing.B) {
    for range b.N {
        slog.InfoContext(context.Background(),
            "message",
            slog.String("key", "value"),
            slog.Int("key2", 1),
            slog.Bool("key3", true),
            slog.Any("key4", time.Time{}),
        )
    }
}

func BenchmarkSlogLogAttrs(b *testing.B) {
    for range b.N {
        slog.LogAttrs(context.Background(),
            slog.LevelInfo,
            "message",
            slog.String("key", "value"),
            slog.Int("key2", 1),
            slog.Bool("key3", true),
            slog.Any("key4", time.Time{}),
        )
    }
}

❯ go test -benchmem -bench . -count 1
goos: darwin
goarch: arm64
pkg: insideout
BenchmarkSlogRaw-12              1560402               739.5 ns/op            24 B/op          1 allocs/op
BenchmarkSlogAttrValue-12        1443043               841.5 ns/op           120 B/op          5 allocs/op
BenchmarkSlogAttr-12             1428519               851.0 ns/op           216 B/op          5 allocs/op
BenchmarkSlogLogAttrs-12         1662672               714.0 ns/op            24 B/op          1 allocs/op
PASS
ok      insideout       7.946s

パラメータの存在箇所とログを取る箇所が一致しないケースへの対処

ここまでで、slogを使った構造化ログを出力する仕組みや、出力時に任意のパラメータを含める仕組み、グローバルなslog Loggerにパラメータを予め注入してアプリケーション全体のログに特定のパラメータを付与する仕組みなどを見てきました。

一方で、構造化ログの説明で挙げたような「一連の操作を特定するパラメータ」は、アプリケーションのライフサイクルの途中で生まれ、一連の操作フローの中のみで生存しています。例えばトレースIDなら、API Serverのミドルウェア実装などでリクエスト受付時に共通して発行し（もしくはリクエストヘッダから取得し）、そのリクエスト内のログではその値を使い回したいものです。

グローバルなloggerに対してこの値を付加するのは適切では無いため、このようなパラメータを関数やパッケージを跨いで一貫してログに含めるにはどうすれば良いかは自力で考えなければいけません。なお、以降は現時点で知りうる情報をまとめただけであり、今後のベストプラクティスは変わっていく可能性があります。

1. Loggerの明示的な伝播

まず考えられるのは slog.With を使ってグローバルなloggerから任意のパラメータを付与した新しいloggerを作り、関数の引数やstructの変数として持たせる方法です。受け取った関数・structはグローバルなloggerではなく引数で渡されたloggerを利用する必要があります。

type Example struct {
    logger *slog.Logger
}

func NewExample(logger *slog.Logger) *Example {
    return &Example{
        logger: logger,
    }
}

func (e *Example) Hello() {
    e.logger.Info("hello")
}

func otherFunc(logger *slog.Logger) {
    logger.Info("otherFunc")
}

func main() {
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))
    slog.Info("init")

    logger := slog.With("key", "value")
    otherFunc(logger)

    NewExample(logger).Hello()
}

https://go.dev/play/p/DE97-niNdr8

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"init"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"otherFunc","key":"value"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello","key":"value"}
  • メリット
    • Loggerへの依存がコード上で明示される
    • 任意のkey・valueを設定できる
  • デメリット
    • 関数などの引数に手を加えなければならない。
      • これは通常破壊的な変更になる。
      • 将来ログを追加したい部分は予め受け取れるようにしておかなければならない。
      • 単純に引数が多いのはつらい。
    • ポインタなのでテスト時などでも省略できない。
      • nilを渡すとnil pointer referenceで落ちる

2. ContextにLoggerを埋め込むことによる暗黙的な伝播

GoのContextは実は任意のKey Value Storeとして使えるため、これまでのサードパーティーのLoggerの実装にもこのcontextに埋め込んでおく実装が存在しました。ただし、slogパッケージはこの機能を提供しないため、自分で実装する必要があります。以下の様な関数を実装すると埋め込みと取り出しができます。

type contextKey string

const loggerContextKey contextKey = "logger"

func FromContext(ctx context.Context) *slog.Logger {
    val := ctx.Value(loggerContextKey)
    if val == nil {
        return slog.Default()
    }
    return val.(*slog.Logger)
}

func NewContext(ctx context.Context, logger *slog.Logger) context.Context {
    return context.WithValue(ctx, loggerContextKey, logger)
}

このような関数を用意しておけば、以下の様にcontextへ特定のパラメータを付与したloggerを埋め込み、呼び出し先の関数で取り出して使うことで目的を達成できます。

func main() {
    // グローバルなloggerを設定
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
        Level: slog.LevelInfo,
    })))

    // グローバルなloggerからkey: valueを付与したloggerを作ってcontextに入れる
    ctx := NewContext(context.Background(), slog.With("key", "value"))
    otherFunc(ctx)
}

func otherFunc(ctx context.Context) {
    // グローバルなloggerを使った場合
    // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello from global logger"}
    slog.Info("hello from global logger")

    // Context埋め込みのloggerを使った場合
    logger := FromContext(ctx)
    // {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello","key":"value"}
    logger.Info("hello")
}

https://go.dev/play/p/w_yaUsa4d5h

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello from global logger"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello","key":"value"}

FromContext の実装としてデフォルトにフォールバックするようになっているので、仮にcontextに何も入っていなくてもランタイムでエラーになって壊れるということはありません。逆に言うとcontextに入れ忘れていてもエラーにはならないため、途中でcontextを新規生成して伝播しているとそこから先の呼び出し先だけではうまく適用出来ていないという状態になりうることに注意が必要です。

この方法の良い点は、任意の呼び出しツリーについてパラメータを注入できることです。関数A→関数B→関数Cという呼び出しをするとき、関数Bで新しいパラメータ key: value を導入してcontextにloggerを埋め込めば、Aやグローバルの実装に影響することなくBとCのその呼び出しのログにだけ key: value を注入できます。

func WithValues(ctx context.Context, keyAndValues ...any) (context.Context, *slog.Logger) {
    logger := FromContext(ctx).With(keyAndValues...)
    return NewContext(ctx, logger), logger
}

func main() {
    ctx := NewContext(context.Background(), slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))
    A(ctx)
}

func A(ctx context.Context) {
    logger := FromContext(ctx)
    logger.Info("A")
    B(ctx)
}

func B(ctx context.Context) {
    // パラメータを付与したloggerを作ってcontextに入れておく
    ctx, logger := WithValues(ctx, "key", "value")
    logger.Info("B")
    C(ctx)
}

func C(ctx context.Context) {
    logger := FromContext(ctx)
    // ここでは特にパラメータを付与していないが、Bで付与したパラメータが引き継がれる
    logger.Info("C")
}

https://go.dev/play/p/wl3nYAPDdjb

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"A"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"B","key":"value"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"C","key":"value"}
  • メリット
    • context.Context を採用している関数なら、引数を変更せず利用できる
      • 特定の呼び出しツリーのログにだけ特定のパラメータを引数に指定することなく注入できる
    • 任意のkey・valueを設定できる
  • デメリット
    • その関数が context.Context による中断などをサポートしているのか、単にLoggerのために要求しているのかわからない
    • 呼び出し先がcontextからloggerを取得してくれるとは限らない
      • サードパーティーライブラリがslogに対応していたとしても、グローバルな slog.Logger を呼んでいる可能性の方が高いだろう
      • どのようなキーでcontextに埋め込むかについてはコミュニティにおいてデファクトなものは存在せず、contextに埋め込む方法自体が様々な反対意見によりリジェクトされ実装されていない

3. Contextにメタデータを埋め込んでおきLoggerが取り出すことによる暗黙的な伝播

slogには第一引数に context.Context を取る以下の様な関数が実装されています。

https://pkg.go.dev/log/slog#hdr-Contexts

DebugContext(ctx context.Context, msg string, args ...any)

InfoContext(ctx context.Context, msg string, args ...any)

WarnContext(ctx context.Context, msg string, args ...any)

ErrorContext(ctx context.Context, msg string, args ...any)

これらの関数へ渡したcontextは、最終的に実際のLoggerのHandlerのメソッドに渡ります。

https://pkg.go.dev/log/slog#Handler

Handle(context.Context, Record) error

Handlerのwrapperを作り、その中でcontextからパラメータを取り出してログに付加することで、contextにパラメータを埋め込むだけでパラメータを伝播できます。

type CtxKey string

const (
    CtxKeyTraceID CtxKey = "trace_id"
)

type ContextAwareHandler struct {
    slog.Handler
}

func (c ContextAwareHandler) Handle(ctx context.Context, r slog.Record) error {
    // contextに値が入っていれば取り出してログに付与する
    keys := []CtxKey{CtxKeyTraceID}
    for _, key := range keys {
        if value := ctx.Value(key); value != nil {
            r.Add(string(key), value)
        }
    }
    return c.Handler.Handle(ctx, r)
}

// この関数を実装しないと、embedしているHandler自身のWithAttrsが呼ばれてしまい、
// embedしているHandler自身が返ってしまう
func (c ContextAwareHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    return ContextAwareHandler{
        c.Handler.WithAttrs(attrs),
    }
}

// この関数を実装しないと、embedしているHandler自身のWithGroupが呼ばれてしまい、
// embedしているHandler自身が返ってしまう
func (c ContextAwareHandler) WithGroup(name string) slog.Handler {
    return ContextAwareHandler{
        c.Handler.WithGroup(name),
    }
}

func main() {
    slog.SetDefault(slog.New(
        ContextAwareHandler{
            slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{}),
        }).With("global", "value"),
    )
    A(context.Background())
}

func A(ctx context.Context) {
    slog.InfoContext(ctx, "A")
    B(ctx)
}

func B(ctx context.Context) {
    ctx = context.WithValue(ctx, CtxKeyTraceID, "some value")
    slog.InfoContext(ctx, "B")
    C(ctx)
}

func C(ctx context.Context) {
    // ここではパラメータを付与していないが、Bで付与したパラメータが引き継がれる
    slog.InfoContext(ctx, "C")
}

https://go.dev/play/p/Zgzm1fi27WL

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"A"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"B","trace_id":"some value"}
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"C","trace_id":"some value"}
  • メリット
    • context.Context を採用している関数なら、引数を変更せず利用できる
    • 特定の呼び出しツリーのログにだけ特定のパラメータを引数に指定することなく注入できる
    • ログを記録する側はslogが公式に実装している関数を使うだけで良いため、サードパーティーのライブラリでも slog.~~Context なメソッドを使っていればパラメータをログに足せる
  • デメリット
    • その関数が context.Context による中断などをサポートしているのか、単にLoggerのために要求しているのかわからない
    • slog.~~Context 以外の関数でログを取ると、Handlerには初期状態のcontextが渡されるため、パラメータを取り出せない
      • slog.Info などは context.Background() して渡しているため（ref）
      • slog.~~Context 以外を使うと警告するサードパーティーのlinterは存在する（ref）
    • keyが増える度に実装に変更を加えなければならない
      • handlerで明示的に取り出す必要があるため、任意のkey valueをcontextに入れておいて取り出せるわけではない
    • 一度ログを記録する度にcontextから取り出してパラメータを足すという実装が挟まるため、オーバーヘッドが比較的大きい（後述）

1~3のどれを採用すべきなのか

2か3は現状ほとんど好みになっているように感じています。1はそもそも使う箇所が限定的な場合のみ採用することになるでしょう。例えば同一パッケージ内のプライベート関数などでは、contextを渡すよりもloggerそのものを渡してしまった方が楽に実装できる場合もあります。 一応2と3についてはパフォーマンス上のオーバーヘッドがあるため、その点に注意する必要があります。

// 2
func BenchmarkSlogContextEmbeddedLogger(b *testing.B) {
    ctx := NewContext(context.Background(), slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
        Level: slog.LevelInfo,
    })).With(string(CtxKeyTraceID), "123456"))
    b.ResetTimer()
    for range b.N {
        logger := FromContext(ctx)
        logger.Info("message", "key", "value")
        logger.Info("message", "key2", "value2")
    }
}

// 3
func BenchmarkSlogCtxAwareHandler(b *testing.B) {
    slog.SetDefault(slog.New(ContextAwareHandler{
        slog.NewTextHandler(io.Discard, &slog.HandlerOptions{
            Level: slog.LevelInfo,
        }),
    }))
    ctx := context.WithValue(context.Background(), CtxKeyTraceID, "123456")
    b.ResetTimer()
    for range b.N {
        slog.InfoContext(ctx, "message", "key", "value")
        slog.InfoContext(ctx, "message2", "key2", "value2")
    }
}

結果は以下の様になりました。3は現状単一のkeyのみをcontextから取り出していますが、それでもログを出力する度に取り出すため2の方法に比べるとオーバーヘッドが大きいです。 多数のkeyを取り出す場合は更にその差は広がるでしょう。

BenchmarkSlogContextEmbeddedLogger-12            1259684               944.9 ns/op             0 B/op          0 allocs/op
BenchmarkSlogCtxAwareHandler-12                   959714              1219 ns/op              64 B/op          4 allocs/op

よって自分がやりたいことに応じて以下の組み合わせで使えば良いと考えています。

  • コンポーネントや関数をまたいでログに多様なパラメータを付与する予定がある
    • 1+2で実装する。ハンドラーに付与予定の全てのパラメータを取り出すコードを書く必要がなくなり、思いついたkey valueを付与しても動く。
  • コンポーネントや関数をまたいでログに付与するパラメータは限定的である
    • 1+3で実装する。共通のハンドラーで対応するだけでよく、対応するライブラリを作る際も slog.~~Context を使うことだけ気をつけていれば良い。
  • パフォーマンスにシビアである
    • 1+2で実装する。contextからloggerを一度取り出すだけで済むため、毎回contextからkeyの有無をチェックする必要のある3に比べるとオーバーヘッドが少ない。

なお、前述したように、今後のGoコミュニティ内でのデファクトスタンダードの推移によって結論は変わる可能性があります。

どこで何の値をログに含めるべきかのルールを決める

とりあげた3つの手法のいずれを使うにしても、呼び出し元から渡ってきた context.Context や slog.Logger に今どういうパラメータが埋め込まれているかを知ることはできません。更に、slogは高速化のため追加のパラメータが重複していてもそのままjsonとして出力するという実装になっている（mapとして処理していない）ため、「分からないから必要そうな物を毎回足す」という実装をしていると、ログが重複するキーまみれになってしまう可能性があります。

func main() {
    slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{})))
    slog.With("key", "value").Info("hello", "key", "value", "key", "value")
}

https://go.dev/play/p/QMYcy7C6JOL

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"hello","key":"value","key":"value","key":"value"}

以下の様なルールにしておくと多少判断しやすくなるかもしれません。

  • 明示されていない値を付与しない
    • 違反する例：トレースIDをログに付与するため、あらゆる箇所で context.Context からあるかもしれないトレースIDを取り出して付与する
    • 1・2の方法ではトレースIDを生成した箇所でloggerに付与しておく、3の方法ではトレースIDをログのために取り出すのはHandlerのみとすることで回避出来る
  • 基本的に呼び出し元でパラメータを付与する
    • 違反する例：APIクライアントにおいて取得対象のIDをログに付与するため、引数としてIDを指定したAPIクライアント実装の中でIDをログに付与する
    • これは呼び出し元が付与しておくべきである。
      • そのIDを元に組み立てたURLなど、何らかのバリデーション・加工を施した場合は呼び出し先で付与してもよい。
    • 呼び出し先から更に別の呼び出しをした先でも付与すると重複してしまう可能性があるため、必ず呼び出し先で付与するようにするルールはうまくワークしない可能性が高い。
      • 例えばAPIクライアントに対して、キャッシュのためのラッパを追加できるような実装があるとする。キャッシュの実装→実際のクライアントの実装という順で呼ばれることになる。それぞれでidを足すと重複する。一方、クライアントの中でしか付与しない場合、ラッパの中でログを取ってもその情報は現れない。
    • 例外：フレームワークを使っている場合。フレームワークにcontextないしslogのサポートが入っていれば別だが、そうでない場合は引数で渡されたものをそのまま付与するケースがあるかもしれない。

ただ正直このあたりのルールを完璧に決めるのは難しいとも感じています。レビュワーやチームと同意が取れており、重複したキーが出力されていないならそこまで細かく気にしなくても良いかなと思います。

まとめ

単にJSONの形式でログを出力すれば、従来のログより扱いやすくなると言うわけではありません。その後の絞り込みや解析のために有用なパラメータを、ログの起因となるイベントのメッセージから分離して容易に処理出来る状態にしておく必要があります。

Goのslogは既存のサードパーティーのライブラリからエッセンスをくみ取って作られており、このような構造化ログの出力のために必要な機能を概ね実装しています。公式に実装された機能だけで十分に意味のあるログを生成でき、パフォーマンス面での考慮もされています。

ただし、関数やコンポーネントをまたいだログのパラメータの共有については実装方法がユーザに任せられている状況です。こういった処理は実装していくと頻繁に生じますが、ここでどのような方法を取るべきかは状況によって異なっています。トレードオフを理解し、チームで使いやすいものを採用するようにしましょう。

*1:grafana.com

*2:grafana.com

*3:grafana-loki lacks basic feature of extracting nested json labels · Issue #6994 · grafana/loki · GitHub

*4:grafana.com

*5:Custom logging with slog Making Logging Fun Again! - Speaker Deck

*6:https://pkg.go.dev/golang.org/x/exp/slog#hdr-Attrs_and_Values