Diary of a Perpetual Student

Perpetual Student: A person who remains at university far beyond the normal period

Go言語でHTTPレスポンスを透過的にキャッシュする

Webアプリケーションの裏側にさらにHTTPサーバが立っていて、レスポンスを返すために裏側のサーバにリクエストを送ってその結果を必要とするような構成があります。裏側のサーバに設定さえたAPIレートリミットへの対応やサーバへの過負荷を避けるため、キャッシュを利用してリクエストが飛びすぎないようにしたいケースがあるでしょう。

Go言語のHTTP ClientにはTransportというパラメータがあり、これを差し替えることで透過的なクライアントサイドのキャッシュ層を導入することができます。

実際にライブラリとして作ってみたのでご紹介します。

github.com

使い方

利用例を用意しています。

https://github.com/Arthur1/http-client-cache/blob/82d0e8e327b9fd37554a135b0915891621689a6b/_example/main.go

まずは以下のように、ファクトリ関数でtransportを生成し、http.ClientのTransportに設定します。

redisCli := redis.NewClient(&redis.Options{Addr: "localhost:6379", DB: 0})
transport := httpclientcache.NewTransport(
    rediscache.New(redisCli), httpclientcache.WithExpiration(5*time.Minute),
)
client := &http.Client{Transport: transport}

このclientのDoメソッドに*http.Requestを渡してあげることで、リクエストが5分間Redisにキャッシュされます。期限内にこのclientを利用して同じHTTPメソッド・本文のリクエストを送るとレスポンスが得られますが、HTTPリクエストを送っているわけではなくキャッシュから取り出しています。

req1, _ := http.NewRequest(http.MethodGet, "https://example.com", nil)
res1, _ := client.Do(req1) // origin response

req2, _ := http.NewRequest(http.MethodGet, "https://example.com", nil)
res2, _ := client.Do(req2) // cached response

実装の詳細

先ほど紹介したライブラリの実装のポイントをかいつまんで説明します。

キャッシュキーを生成する

キャッシュストレージとのやり取りに必要なので、*http.Request(のURL・メソッド・本文)から一意に定まるハッシュキーを生成します。

このとき、リクエストボディが必要になるのですが、io.ReadCloserという型になっており二度Bodyを読むことができません。すなわち、キャッシュキーを作るためにBodyを読んでしまうと、実際にclientがリクエストを送る時にBodyを読めなくなってしまいリクエストに失敗してしまいます。

この問題を防ぐため、以下のようにReadCloserを作り直して代入する必要があります。

body, err = io.ReadAll(req.Body)
if err != nil {
    return "", err
}
req.Body = io.NopCloser(bytes.NewReader(body))

Bodyが取得できたら、あとは他のパラメータと合わせてハッシュを生成しましょう。キーの暗号化要件は求められないため、軽量なハッシュアルゴリズムであるhash/fnvパッケージを利用しています。

http-client-cache/cache/key/key.go at 82d0e8e327b9fd37554a135b0915891621689a6b · Arthur1/http-client-cache · GitHub

キャッシュと読み書きして必要に応じてHTTPリクエストを送るTransportを作る

Transportに求められるinterfaceはRoundTripperで、Requestを引数にとってResponseとerrorを返すメソッドを実装すれば良いです。

type RoundTripper interface {
    RoundTrip(*Request) (*Response, error)
}

フォールバック先のTransportをフィールドに持った構造体を作って、RoundTripperインタフェースを実装しましょう。

  • キャッシュヒット時
    • キャッシュから得たResponseを返す
  • キャッシュミス時
    • フォールバック先のTransportを利用してOriginにリクエストを送る
    • TTLを決めてレスポンスをキャッシュに格納する
    • Originから得たResponseを返す

上記のような手続きを行うRoundTrip()を作ってあげれば良いです。以下のコードでは、細かいところは簡略化しています。

type TransportWithCache struct {
    Base http.RoundTripper
}

func NewTransportWithCache() *TransportWithCache {
    return &TransportWithCache{Base: http.DefaultTransport}
}

func (t *TransportWithCache) RoundTrip(req *http.Request) (*http.Response, error) {
    ctx := req.Context()
    key, err := t.cacheKey(req)
    if err != nil {
        // キャッシュキーの生成に失敗したらOriginにアクセスする
        return t.Base.RoundTrip(req)
    }

    cachedRes, ok, err := cache.Get(ctx, key)
    if err != nil {
        // キャッシュからの取得に失敗したらOriginにアクセスする
        return t.Base.RoundTrip(req)
    }
    if ok {
        // キャッシュヒット
        return cachedRes, nil
    }

    // Origin にアクセス
    res, err := t.Base.RoundTrip(req)
    if err != nil {
        return nil, err
    }
    // 200ならキャッシュにセットする
    if res.StatusCode == http.StatusOK {
        cache.Set(ctx, key, res, time.Minute)
    }
    return res, nil
}

http-client-cache/transport.go at 82d0e8e327b9fd37554a135b0915891621689a6b · Arthur1/http-client-cache · GitHub

http.Responseを保存可能な型に変換する

http.Responseはio.ReadCloserなどを含んだ構造体なので、そのままではRedisなどのデータストアに保存することができません。httputil.DumpResponseを利用することで、[]byteに変換することができます。

逆にhttp.Responseを復元する際には、http.ReadResponse関数が有効です。

req, _ := http.NewRequest(http.MethodGet, "https://example.com", nil)
res, _ := &http.Client{}.Do(req)
dumpedRes, _ := httputil.DumpResponse(res, true)
restoredRes, _ := http.ReadResponse(bufio.NewReader(bytes.NewReader(dumpedRes)), req)

http-client-cache/cache/engine/rediscache/redis.go at 82d0e8e327b9fd37554a135b0915891621689a6b · Arthur1/http-client-cache · GitHub

Cache Stampedeを防ぐ

キャッシュが破棄された時に、同時に並行してOriginにアクセスをしてキャッシュに格納しようとしてしまいバックエンドの負荷が高まってしまうCache Stampedeという問題があります。

これを防ぐため、singleflight packageを利用して、同じキャッシュキーのOriginへのリクエストは同時に1つしか飛ばないようにしています。

group.Do()ではhttp.Responseをそのまま返したいところなのですが、複数のgoroutineで同じ結果が共有されてしまうので、どれか1つのgoroutineしかBodyを読めなくなってしまいます。これを回避するため、先ほど紹介したhttputil.DumpResponseでbyte列にしてから返し、それぞれの呼び出し元で復元するようにしています。

+var group singleflight.Group

 func (t *TransportWithCache) RoundTrip(req *http.Request) (*http.Response, error) {
     ctx := req.Context()
     key, err := t.cacheKey(req)
     if err != nil {
         // キャッシュキーの生成に失敗したらOriginにアクセスする
         return t.Base.RoundTrip(req)
     }
 
     cachedRes, ok, err := cache.Get(ctx, key)
     if err != nil {
         // キャッシュからの取得に失敗したらOriginにアクセスする
         return t.Base.RoundTrip(req)
     }
     if ok {
         // キャッシュヒット
         return cachedRes, nil
     }
 
-    // Origin にアクセス
-    res, err := t.Base.RoundTrip(req)
-    if err != nil {
-        return nil, err
-    }
-    // 200ならキャッシュにセットする
-    if res.StatusCode == http.StatusOK {
-         cache.Set(ctx, key, res, time.Minute)
-     }
-    return res, nil
+    maybeDumpedRes, err, _ := group.Do(key, func() (any, error) {
+        // Origin にアクセス
+        res, err := t.Base.RoundTrip(req)
+        if err != nil {
+            return nil, err
+        }
+        // 200ならキャッシュにセットする
+        if res.StatusCode == http.StatusOK {
+            cache.Set(ctx, key, res, time.Minute)
+        }
+        dumpedRes, err := httputil.DumpResponse(res, true)
+        return dumpedRes, err
+    }
+    dumpedRes := maybeDumpedRes.([]byte)
+    return http.ReadResponse(bufio.NewReader(bytes.NewReader(dumpedRes)), req)
 }

待ち受けポートをカスタムしたsshdをアプデしたらsshで繋げなくなってしまった問題のポストモーテム

事象

piyolog.hatenadiary.jp

CVE-2024-6387の対応のため、個人開発サービスを運用していてインターネットに露出しているサーバのopenssh-serverをアップデートしていた。

Google CloudのCompute Engineで立てているあるサーバのopenssh-serverをapt upgradeでアップデートしたところ、以後sshで接続することができなくなってしまった。

原因

当該サーバではSSHのポート番号を22とは異なるものに設定していた。また、Cloud Firewallではtcp 22のインバウンド通信を不許可としており、SSHの代替ポートについて許可するルールとしていた。

apt upgrade時にsshd_configを更新しますがよろしいですかという確認が表示されていて、何も考えずにYを押してしまったところ、sshd_configが書き換えられた。

Configuration file '/etc/ssh/sshd_config'
 ==> Modified (by you or by a script) since installation.
 ==> Package distributor has shipped an updated version.
   What would you like to do about it ?  Your options are:
    Y or I  : install the package maintainer's version
    N or O  : keep your currently-installed version
      D     : show the differences between the versions
      Z     : start a shell to examine the situation
 The default action is to keep your current version.
*** sshd_config (Y/I/N/O/D/Z) [default=N] ? 

その結果、待ち受けポートを標準から変えていた設定がロールバックしてしまい、22番ポートでlistenするようになった。22番はFirewallでブロックしていたため、再接続できなくなってしまった。

影響

サーバの管理者である私がsshを経由して当該サーバにアクセスすることが不可能になった。個人開発サービスの可用性に影響はない。

対応

Firewallの設定を変更し、一時的に22番ポートのインバウンド通信を許可した。その結果22番ポート経由でsshで当該サーバに接続することができた。

sshd_configファイルを元の状態に書き換え、代替ポートで接続できることを確認した。

再発防止策

  • sshdをアップデートしたあと、そのセッションを閉じないまま別に接続してみて、これまでと変わらずに接続できることを確認する
    • sshdをアップデートしても、既存の接続は古いプロセスを使用し続ける
  • 設定ファイルを書き換えるようなメッセージが表示された場合にはノールックでYを押さずに差分を確認する

OpenTelemetryのテレメトリとMackerelのホストをResource Attributesで紐づけるためのOTelcol Processorを作りました

OpenTelemetryを使い始めるにあたって、既存の監視ツールからいきなり切り替えることは難しく、基本的には一時的に並行稼働させて様子を見ることになると思います。

これまでmackerel-agentをインストールし、Mackerelにホストとして登録してシステムメトリックを監視していたマシンに、新たにOpenTelemetry Collector+Host Metrics Receiverを導入するケースを考えてみましょう*1

Resource Detection Processorなどを併用することで、メトリックにホスト名などをResource Attributesとして付与することができます。しかし、比較のためにMackerel上のホストと対応させて眺めるには今一歩情報が足りません。

そこで、ホストにインストールされたmackerel-agentの設定ファイルを読み、Mackerel上のホストIDやURL、オーガニゼーション名といった情報をResource Attributesとして付与するMackerel Attributes Processorを開発しました。

github.com

以下のグラフは、実際にこのProcessorを利用してHost Metrics Receiver由来のメトリックにResource Attributesを付与したものになります。

属性名 属性値
mackerelio.host.id 4yWDxQP4GA5
mackerelio.host.url https://mackerel.io/orgs/arthur-1/hosts/4yWDxQP4GA5
mackerelio.org.name arthur-1

というような属性が付与されていることがわかります。

特定のattributeがあったらMackerelのホスト画面から対応するOpenTelemetryメトリックが見られる機能ができたらより捗りそうですね。

使い方

OpenTelemetry Collectorを自前でビルドするocbの設定ファイルで以下のように追記し、Mackerel Attributes Processorを含んだCollectorのバイナリを生成しましょう。

 receivers:
   - gomod: github.com/open-telemetry/opentelemetry-collector-contrib/receiver/hostmetricsreceiver v0.103.0

 processors:
+  - gomod: github.com/Arthur1/opentelemetry-collector-arthur1/processor/mackerelattributesprocessor v0.4.0

 exporters:
   - gomod: go.opentelemetry.io/collector/exporter/otlpexporter v0.103.0

あとは以下のように設定ファイルを用意してOpenTelemetry Collectorを起動させればOKです。

 receivers:
   hostmetrics:
     collection_interval: 60s
     scrapers:
       memory:

+processors:
+  mackerelattributes:

 exporters:
   otlp/mackerel:
     endpoint: otlp.mackerelio.com:4317
     compression: gzip
     headers:
       Mackerel-Api-Key: ***censored****

 service:
   pipelines:
     metrics:
       receivers:
         - hostmetrics
+      processors:
+       - mackerelattributes
       exporters:
         - otlp/mackerel

実装

https://github.com/Arthur1/opentelemetry-collector-arthur1/blob/ff90509af4ac1c9861910e260b8149aa2262a96b/processor/mackerelattributesprocessor/processor.go ファイルがメインの実装部分になります。

起動時にmackerel-agent.confからAPIキーとホストIDファイルの設置場所を読み取っています。APIキーを読んでいる理由は、オーガニゼーション名は設定ファイルに載っておらずMackerel APIを叩いて取得する必要があるからです。ホストIDファイルがわかったらあとはそのファイルを読み取り、これら属性付与に必要な情報を変数に保存します。

以降はこの操作を1分に1回行います。ただし、mackerel-agent.confやホストIDファイルの更新日時を見て、変更されていなければスキップするようにしています。

processorとしてはリソースに紐づく様々なテレメトリがやってきたら、変数の値を読んでその通りにResource Attributesを付与しているだけのシンプルな実装です。このあたりはKubernetes Attributes Processorの実装を参考にしています。

最後に

https://github.com/Arthur1/opentelemetry-collector-arthur1リポジトリではOpenTelemetry Collectorの自作Component群と、それらを同梱した動作検証用のCollectorを公開しています。将来MackerelのOpenTelemetry Collectorディストリビューションが作れたら良いなと思い個人研究をしています。よかったらぜひ使ってみて感想を教えてください。

*1:mackerel-agentが収集するシステムメトリックはOpenTelemetry CollectorのHost Metrics Receiverで同等に取得可能であることはmackerel-agentが作るシステムメトリックグラフをOpenTelemetryで可能な限り再現する - Diary of a Perpetual Studentにてご紹介しました。

OpenTelemetry Metricsを手軽に投稿できるCLIツールotlcのv0.2.0をリリースしました

blog.arthur1.dev

でご紹介した、OpenTelemetry Metricsを手軽に投稿できるCLIツール「otlc」のv0.2.0をリリースしたので再度ご紹介します。

github.com

使い方

インストール

(macOS, Linux)×(x86_64, arm64)向けのバイナリをGitHubのReleaseで配布しています。

Homebrewをお使いの方は以下のコマンド1つでインストールが可能です。

$ brew install Arthur1/tap/otlc
$ otlc --version
otlc is a Command-line Tool to Export Telemetry by OTLP (OpenTelemetry Protocol).
Version:    unknown
Go version: go1.22.4
Arch:       arm64

go install派の方はこちらからどうぞ。こっちならWindowsでも動くかもしれない(未検証)。

go install github.com/Arthur1/otlc/cmd/otlc@latest

メトリックの投稿

まずは環境変数に投稿先の情報を入れます。今回はMackerelのOpenTelemetry対応機能に投稿してみましょう。これらの情報は環境変数を利用しなくても対応するオプションでセット可能です。(詳しくは--helpオプションで確認してください。)

export OTEL_EXPORTER_OTLP_ENDPOINT="otlp.mackerelio.com:4317"
export OTEL_EXPORTER_OTLP_HEADERS="Mackerel-Api-Key=***your_api_key***"

その後、以下のようなコマンドを実行すると、上記で設定した宛先にOTLPでメトリックが投稿されます。

  • メトリック名: awesome.metric
  • メトリック種類: Gauge
  • データポイント属性: hoge="poyo"・fuga="1"
  • データポイント値: 123.45
  • データポイント時刻: 現在
otlc metrics post --name awesome.metric --attrs hoge=poyo,fuga=1 123.45

ちょっとしたメトリックを継続的に投稿する時や検証の際に、SDKを使ったプログラムを書かなくてもコマンドラインでシュッと投稿できて便利です。

どうぞご利用ください。

v0.1.xとの差異

駆け出しなので結構破壊的な変更をしました。今後は仕様を安定させるつもりです。早くv1に上げたいのでフィードバックお待ちしています。

設定ファイルの廃止とOTel Exporterの標準的な環境変数の読み取りに対応

v0.1.xでは投稿先を設定する際にYAMLの設定ファイルを書くのが標準のやり方だったのですが、これを廃止しました。代わりに、同様の情報をコマンドラインオプションで指定できる他、OTLP Exporter onfigurationで定義された名前での環境変数の読み取りに対応しました。

--valueオプションの廃止

メトリックの値を指定する際に--valueオプションを利用していましたが、これをやめて単に引数としました。

--timestampオプションの追加

--timestampオプションでメトリックの時刻をUNIX秒で指定できるようになりました。

otlc metrics post --name awesome.metric --attrs hoge=poyo,fuga=1 --timestamp 1719276600 123.45

過去の時刻で投稿したため、先ほどのグラフが点から線になりました。

投稿時に異常終了するように

メトリックが投稿できない場合、これまではエラー内容がログに出力されるだけでしたが、コマンドとして異常終了するようになりました。

$ otlc metrics post --name awesome.metric --attrs hoge=poyo,fuga=1 123.45
otlc: error: failed to upload metrics: rpc error: code = PermissionDenied desc = authenticate error, please check mackerel-api-key
$ echo $?
1

実装の変化

元々はアプリケーションを計装する際に用いるOpenTelemetry SDK GoのMeterとInstrumentを使って実装していました。Instrumentでメトリックを生成したのちにMeterProviderをすぐにシャットダウンすることで即時に投稿することを期待した、という形です。

https://github.com/Arthur1/otlc/blob/27866d6f826d6aa267f1f0de1687fddfe50b89b9/metrics/post.go#L37-L87

前回のブログで

より低いレイヤーのメソッドを利用して組み立てるとより自由なコマンドラインツールに仕上げられるかもしれません。

と書いた通り、MeterやInstrumentに頼る実装を改め、メトリックデータを直接生成してエクスポートするようにしました。

https://github.com/Arthur1/otlc/blob/94f56eb8612042f799a80664a54110ee6ef5ed5a/internal/metric/generate.go#L23-L76

メトリックの時刻が指定できるようになったり、投稿失敗時に異常終了するようになったりしたのはこの置き換えによるものです。

IPsec VPN実装であるLibreswanの状態を監視できるMackerelプラグイン

IPsec VPN実装であるLibreswanの状態をメトリックとして見られるようにするMackerelプラグインを作りました。

github.com

strongSwanのものは先人が作っていましたが、Libreswanのものがなかったので自作した形です。

nonylene.hatenablog.jp

何が見られるか

Libreswanで作ったVPNサーバの状態が見られます。

  • IPsec Connectionの合計(active/loaded)
  • IPsecのSecurity Associations(total/authenticated/anonymous)
  • IKEのSecurity Associations(total/open/half-open/authenticated/anonymous)

インストール

mkr installに対応した形式で配布しています。

sudo mkr plugin install Arthur1/mackerel-plugin-libreswan

でインストールして

[plugin.metrics.libreswan]
command = ["/opt/mackerel-agent/plugins/bin/mackerel-plugin-libreswan"]

と書けば動きます。

Docker上で動かしているLibreswanにも対応

以下のようにVPNサーバをDockerで動かしている例もあるでしょう。

github.com

ipsecコマンドが実行できるコンテナ向けにこのプラグインを実行したければ、-docker-execオプションを活用できます。例えば、

$ docker exec -it ipsec-vpn-server ipsec version
Libreswan 5.0

のようにしてipsecコマンドを実行できる環境の場合には、

[plugin.metrics.libreswan]
command = ["/opt/mackerel-agent/plugins/bin/mackerel-plugin-libreswan", "-docker-exec", "ipsec-vpn-server"]

のように、-docker-execオプションとしてコンテナ名を渡してあげると動きます。

OTel Collectorでrunnによるシナリオテストの結果を投稿できるrunnreceiverを作りました

blog.arthur1.dev

の続編です。今回はrunnによるシナリオテストの結果を投稿するツールをOpenTelemetry CollectorのReceiver (Scraper)として作ってみました。

リポジトリ

以下のリポジトリで id:arthur-1 によるOpenTelemetry Collectorの自作Component群を公開しています。

github.com

使い方

ビルド

ocb (builder)によってOpenTelemetry Collectorをカスタムビルドする必要があります。カスタムビルドの方法は公式のドキュメントBuilding a custom collector | OpenTelemetryを参照してください。

runnreceivcerをビルドに含める場合には、ocbのconfig YAMLのreceivers部分に、以下のように行を追加しましょう。

 receivers:
+   - gomod: github.com/Arthur1/opentelemetry-collector-arthur1/receiver/runnreceiver v0.2.0

 exporters:
   - gomod: go.opentelemetry.io/collector/exporter/otlpexporter v0.101.0

config

利用する際は以下のようにOpenTelemetry Collectorのconfigを記述します。runbooksにはrunnのYAMLの文字列の配列を記述してください。

receivers:
  runn:
    runbooks:
      - |
        desc: blog.arthur1.dev's test
        runners:
          req: https://blog.arthur1.dev
        steps:
          test1:
            req:
              '/':
                get:
                  body: null
            test: current.res.status == 200
          test2:
            req:
              '/hoge':
                get:
                  body: null
            test: current.res.status == 404
    collection_interval: 1m

exporters:
  otlp/mackerel:
    endpoint: otlp.mackerelio.com:4317
    compression: gzip
    headers:
      Mackerel-Api-Key: ***censored***

service:
  pipelines:
    metrics:
      receivers:
        - runn
      exporters:
        - otlp/mackerel

これで./otelcol-custom .--config ./otelcol-config.yamlのようにしてOpenTelemetry Collectorを実行すると、以下のように、テストが成功したかどうかと、テストに含まれる各ステップの所要時間をメトリックとして投稿します。(以下のグラフはMackerelのOpenTelemetry対応機能によって生成されたグラフを公開したものです。)

将来的にはメトリックだけでなくトレースとしても投稿できるようにする予定です。

おまけ:Receiver自作に関する情報

先日、Pepabo Tech Conference #22 春のSREまつりに登壇させていただき、「otelcol receiver 自作RTA」というタイトルでLT(というよりライブコーディング実演)しました。

speakerdeck.com

こちらのスライドでは、OpenTelemetry CollectorのReceiverを自作する際の流れや気をつけたいTIPSをご紹介しています。ぜひご覧ください。

日本語で書かれた他のエントリにはないおもしろポイントは、

  • mdatagenは現在単純なgo installでインストールできないのでソースコードを持ってくる必要がある
  • mdatagenで記述するYAMLをVSCodeで快適に書くためにJSONスキーマを自作した https://github.com/Arthur1/otelcol-metadata-schema

あたりです。

Go言語のloggerをDefault1つで済ませる方法:slog Handlerがcontextの中身を見てよしなにするパターン

先日、kamakura.go #6にて、「slog登場に伴うloggerの取り回し手法の見直し」という題で登壇しました。Go Conference 2024にこの内容でproposalを出していて落選してしまったのですが、kamakura.go #6のテーマ「昔のGo、今のGo」とピッタリだったので応募して発表の機会を頂いたという経緯です。

speakerdeck.com

この発表は以下のエントリのrefinement版となる内容です。今度は机上論ではなく実践経験をもとに話を組み立てています。

blog.arthur1.dev

loggerの引き回しと、なぜそれが必要だったのか

あるアプリケーション・モジュールの構造化ログについて、常に特定のフィールドを付与したいというニーズがあります。例えばWebアプリケーションなら、ソースコードの関数・モジュール名、リクエストID、ユーザIDといったログの検索に有益な情報をログに付与したいでしょう。

その時に、ログの出力命令ごとにいちいちフィールドを指定しまくるのは大変です。単純にコード量が多いし、仮に付与したいフィールドが増えたときに一行一行変更して回らないといけません。ログに出したい変数を持って回る必要もあります。

log.WithFields(log.Fields{"module": "userService", "user_id": 1}).Info("validation passed")
...
log.WithFields(log.Fields{"module": "userService", "user_id": 1}).Info("succeeded")

(このあたりのサンプルコードは構造化ログのライブラリとしてhttps://github.com/sirupsen/logrusを使用したケースです。)

そこで、必要に応じてloggerインスタンスを作り、呼び出し先でも利用できるように引き回す手法があります。例えば、ユーザIDが確定した時点でユーザIDを常にログに含むようなloggerを作って、それ以降の処理ではこのloggerを利用してログを書くといったやり方です。

logger := log.WithFields(log.Fields{"module": "userService", "user_id": 1})
logger.Info("validation passed")
...
// loggerを作った命令とは別の関数の場合、loggerをここでも使えるように引き回す必要がある
logger.Info("succeeded")

loggerの引き回し手法はいくつかありますが、私個人としては以下の記事で推奨されている手法の1つである「contextにloggerを入れる」パターンが好みです。

zenn.dev

package mylog

import "context"

type key struct{}

func ContextWithLogger(ctx context.Context, logger Logger) context.Context {
    return context.WithValue(ctx, key{}, logger)
}

func FromContext(ctx context.Context) Logger {
    return ctx.Value(key{}).(Logger)
}
func A() {
    logger := log.WithFields(log.Fields{"user_id", 1})
    ctx := mylog.ContextWithLogger(context.Background(), logger)
    B(ctx)
}

func B(ctx context.Context) {
    logger := mylog.FromContext(ctx)
    logger.Info("Hello, world!")
}

ただし、この手法はloggerを利用したい関数でcontextからloggerを取り出す命令を書かなければいけないので、そこだけ若干煩雑でコードの美しさが損なわれると感じていました。

slogの特徴

さて、Go 1.21からはGoビルトインのlog/slogパッケージが登場しました。https://go.googlesource.com/proposal/+/master/design/56345-structured-logging.mdがプロポーザルの内容で、こちらを読むとどのような思想で設計されたのかを知ることができます。

Logger/Handler

LoggerとHandlerという2つのインタフェースに概念が分離されました。

Loggerのほうはフロントエンド・ファサードのような立ち位置で、たとえばloggerのInfo(msg string, args ...any)というメソッドを呼ぶことでINFOレベルのログが書けますというインタフェースが定義されています。

Handlerは実際にログのレコードを作って書き込むという処理を担います。text、jsonといった出力フォーマットを変えることができるのはもちろん、ログレコードに特定のフィールドを追加するといった処理も可能です。

Loggerのインタフェースとして、contextを引数に持つ関数が用意される

InfoContext(ctx context.Context, msg string, args ...any) のように、ログを出力する関数の引数にcontextを持つものが用意されました。Handlerは渡されたcontextの値を利用することができます。

デフォルトLogger

従来のlog packageと同様にslog.SetDefault(l *Logger)というデフォルトのloggerを登録しておける関数が用意されています。デフォルトのloggerを登録しておくと、loggerのインスタンスからログ出力関数を呼び出さなくてもslog.Info()のようにpackage名から直接ログを書き出すことができます。

実装としてはグローバル変数にloggerが格納されているのと大差ないのですが、複数のgoroutineから呼ばれことを考慮してsync/atomicが利用されています*1

contextの中身を見て自動でフィールドを追加するHandlerがあれば……

これらの特徴を見て私は「場所によって構造化ログに自動で入れたいフィールドを制御したいという理由だけで、リクエストごとloggerを作って引き回す必要はなくなったのでは」と思いました。具体的には、contextの値を読み取って自動でフィールドを追加するようなHandlerを作り、これを用いて作ったloggerをデフォルトとして登録してしまえば、リクエストごと作ったloggerを引き回す必要がなくなるという見立てです。

こういった方針で作ってみたのが以下のコードです。contextに含まれる特定のキーの値をHandlerがログレコードのフィールドに追加するようなHandlerができました。

package main

import (
    "context"
    "log/slog"
    "os"
)

var keys = []string{"user_id", "request_id"}

type MyLogHandler struct {
    slog.Handler
}

var _ slog.Handler = &MyLogHandler{}

func (h *MyLogHandler) Handle(ctx context.Context, r slog.Record) error {
    for _, key := range keys {
        if v := ctx.Value(key); v != nil {
            r.AddAttrs(slog.Attr{Key: string(key), Value: slog.AnyValue(v)})
        }
    }
    return h.Handler.Handle(ctx, r)
}

func main() {
    logger := slog.New(&MyLogHandler{slog.NewJSONHandler(os.Stderr, nil)})
    slog.SetDefault(logger)
    A()
}

func A() {
    ctx := context.WithValue(context.Background(), "user_id", 1)
    ctx = context.WithValue(ctx, "request_id", "000")
    B(ctx)
}

func B(ctx context.Context) {
    slog.InfoContext(ctx, "Hello, world!")
}

https://go.dev/play/p/pjs7A-WNptj

slog.InfoContext(ctx, "Hello, world!")という呼び出しで

{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"Hello, world!","user_id":1,"request_id":"000"}

というログが書き出されます。

任意のkeyでもログに書けるようなHandler

先ほどの手法では、ログに書き出したいcontextのフィールドのリストを定義しておく必要があります。しかし、ログに書き出したいものが増えるたびにリストを編集するのは大変だし、そもそもloggerという存在がアプリケーションの内部のことを知っている(たとえばrequest_idというログに書き出したい存在がいること)ように見えて微妙な感じがします。

contextにsync.Mapを持ち、その中身をログに書くHandler

ログに書き出したいcontextのkeyを1つ1つ管理しなくても良い手法として、contextにmapを持ってしまい、handlerとしてはmapの中身を全部書き出してしまうやり方があります。mapのキーだけ決めてしまえば良いです。

  • context
    • user_id <- このキーをログに出すと管理
    • request_id <- このキーをログに出すと管理

という構造だったのが、

  • context
    • logcontext (map) <- このキーをログに出すと管理
      • user_id
      • request_id
      • その他なんでも

という構造になるイメージです。

ただし、goroutine safeになるようにただのmapではなくsync.Mapを使うと良いでしょう。実際にこの指針で実装されたslog HandlerがGitHubで公開されています。

github.com

2024-05-22 追記:上記slog-contextの実装は、親のcontextに入っているmapを子から破壊する実装になっていました。issueとPRが出ていたのでそのうち直されるかも WithValue on contex with existing fields affects the parent context · Issue #5 · PumpkinSeed/slog-context

OpenTelemetry Baggageの中身をログに書くHandler

また、ログに書き出したいものの置き場としてOpenTelemetryのBaggageを利用するのも手です。

opentelemetry.io

Baggageはテレメトリのためのコンテキスト情報をspan(service)をまたいでも伝達するためのキーバリューストアです。Baggageの基本的な使い方として挙げられるのは、下流のサービスに上流のサービスのコンテキスト情報(何らかのIDとか)を受け渡し、下流のサービスではBaggageから値を取り出してspanのattributeに追加する、といった流れです。Baggageに入れるのはテレメトリに付与したい情報なので、その中身をログに書きだしても大抵は不都合がないでしょう。

OpenTelemetry Baggageをcontextから取り出してログに書くslog handlerについても、すでにサードパーティの実装があります。Baggageの中身だけでなくトレースIDもログレコードに付与してくれるので、ログとトレースを紐づけたいときにとても便利です。

github.com

まとめ

典型的なWebアプリケーションにおいて、「ここだけはJSONログにしたい」など複数のslog handlerを併用したいことは少ないと感じています。やりたいのは高々ログに付与する属性を制御したい程度でしょう。その役割はcontextの中身を見てよしなにするリッチなhandlerに任せることで、リクエストごとにloggerインスタンスを作る必要がなくなります。リクエストごとloggerが作られないのなら、頑張って引き回す必要もなくなり、デフォルトのloggerに登録しておけばどこでもslog packageから呼び出してシンプルにログを書き出すことができます。Webアプリケーションのloggerとしてはこの考え方で十分実用に適うと思います。