リクエストログミドルウェアに後続ロジックから情報を渡したいときの2つのアプローチ #LayerXテックアドカレ

この記事は、LayerX Tech Advent Calendar 2024 の8日目の記事です。

tech.layerx.co.jp

バクラクビジネスカード開発チーム Tech Lead の budougumi0617 です。

今回はGoでWebアプリケーションを作る際に利用するHTTPミドルウェアでリクエストログを出力する際のTipsです。
HTTPハンドラー内のビジネスロジックで取得・導出した情報をリクエストに付与する方法を解説します。

TL;DR

Go言語でWebアプリケーションを開発する際、よくある手法としてミドルウェアでユーザーIDやテナントIDといった情報を持ったリクエストログ（アクセスログ）を出力します。
大抵の場合はリクエストログミドルウェアの前段にかませた認証ミドルウェアで取得した情報を使ってリクエストログにID情報を付与しますが、外部サービスに公開したWebhookのような場合、認証情報が取得できないことがあります。
本記事では、このようなケースでもビジネスロジック中（HTTPハンドラー内の実ロジック）で取得した情報をリクエストログミドルウェアに渡す方法を2つ紹介します。

http.ResponseWriterをラップする
context.Contextへのポインタオブジェクトを格納する

どちらもデメリット（懸念事項）があるため、用法用量を守って利用する必要があります。

課題感: Datadogでフィルターを作成したり、ログ分析を行う上ですべてのリクエストログにテナントIDやユーザーIDの情報を含めたい

弊社ではDatadogを用いて本番環境の監視を行っています。また、ログはDWHに格納してSnowflakeやLooker Studioからの分析で利用しています。
通常の（認証済みユーザーによる）リクエストでは、認証ミドルウェアでテナントIDやユーザーIDを特定し、context.Contextオブジェクトに詰め込んだ上でリクエストログ出力時に利用しています ¹。

Webhook用エンドポイントのような特殊ケースではミドルウェア層でIDを取得できないことがある

私が所属しているカードチームのAPIサーバには、外部サービスからのWebhookを受け取るエンドポイントがいくつかあります。
具体的な内容は割愛しますが、興味があるかたは @shnjtk の以下の資料をごらんください。 speakerdeck.com

これらWebhookのリクエストは決済リクエストなど、大抵がいずれかのテナントに紐づくリクエストではあります。しかし、他社から受けとったリクエストのため、自社の認証基盤のが発行した認証情報は含まれていません。
また、他社ベースの情報であるため、リクエストボディの中身を単純に見るだけではテナントIDなどはわかりません（他社が発行したIDを元に弊社DBからテナント情報を探すなどの過程が必要）。
つまり、次で説明するようにオーソドックスなミドルウェアの処理の流れの中ではIDを取得できず、リクエストログミドルウェアの段階でcontext.ContextにIDが入っている前提が崩れてしまいます。

テナントIDが無いリクエストログによってアラート運用に支障が出ていた

テナントIDなしのリクエストログでも、後からリクエストIDで追跡すれば他のログ出力と組み合わせてテナント特定は可能です。
しかし、Datadog上のアラート設定などでテナントIDを条件に使っているケースでは、テナントIDがないログが存在することは運用上不便です。

こうした状況で、ビジネスロジック中で導出したユーザーIDやテナントIDなどをどうにかしてリクエストログミドルウェアに渡したいなと考えました。

おさらい: 通常のHTTPミドルウェアにおけるリクエストログ出力とID情報付与の流れ

前述の課題に対するアプローチを紹介する前に、オーソドックスな認証ミドルウェアとリクエストログの組み合わせをおさらいしておきます。

GoでHTTP APIサーバを作成する時はhttp.Handlerインターフェースベースで各エンドポイントを実装します。
認証情報の確認、エラーハンドリング、リクエストログの出力といった共通機能については、利用するフレームワークによって多少の差異はありますが、
func (next http.Handler) http.Handler 形式のミドルウェアを使って実装することになるでしょう。
そして、マルチテナントSasSで用いるAPIサーバのリクエストログでは、ユーザーIDやテナントIDなどの情報も含めることが一般的です。
認証済みリクエストに対して、一般的な構成では以下のようなフローでリクエストログにID情報を付与します。

認証ミドルウェア
- リクエストヘッダやCookie、セッションなどから認証情報を取得し、ユーザーIDやテナントIDをhttp.RequestオブジェクトにWithContextメソッドもしくはCloneメソッドで埋め込む。
リクエストログミドルウェア
- 後続の処理を実行後、ContextオブジェクトからID情報を取り出し、リクエストログへ出力します。

具体的な実装としては次のような形になります。

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

type userIDKey struct{}
type tenantIDKey struct{}

func AuthMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        userID, tenantID := authenticate(r) // リクエストデータから認証情報を取得
        ctx := context.WithValue(r.Context(), userIDKey{}, userID)
        ctx = context.WithValue(ctx, tenantIDKey{}, tenantID)
        next.ServeHTTP(w, r.WithContext(ctx))
    })
}

func RequestLogMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()
        next.ServeHTTP(w, r)
        duration := time.Since(start)
        ctx := r.Context()
        userID := ctx.Value(userIDKey{})
        tenantID := ctx.Value(tenantIDKey{})
        log.Printf("Request log user=%v tenant=%v duration=%v\n", userID, tenantID, duration)
    })
}

// AuthMiddleware(RequestLogMiddleware(businessLogicHandler)) という形でミドルウェアを組み合わせる

ログイン済ユーザーが実行した認証済のリクエストに対してはこの構成で問題なくリクエストログにID情報を付与できます。

ここで問題になるのが次の前提知識です。

前提知識1: Goの`context.Context`はイミュータブル

context.Contextはイミュータブルです。WithValueで新たなキーと値のペアを付与すると新しいContextオブジェクトが返りますが、既存Contextオブジェクトを直接書き換えることはできません。
つまり、ハンドラー内部でContextオブジェクトに値を入れたとしても、呼び出し元のContextオブジェクトは通常変更されません。また、ハンドラー内部でContextオブジェクトからValueメソッドで取り出した値を変更しても元のContextオブジェクトには反映されません。

https://go.dev/play/p/181CW1UrxO3

type tenantIDKey struct{}

func main() {
    orgTenantID := "original"
    ctx := context.WithValue(context.Background(), tenantIDKey{}, orgTenantID)

    tenantID := ctx.Value(tenantIDKey{}).(string)
    tenantID = "update"
    fmt.Printf("change %q\n", tenantID) // change "update"

    fmt.Printf("result %q\n", ctx.Value(tenantIDKey{}).(string)) //result "original"
}

前提知識2: `*http.Request`経由では親関数(呼び出し元)へ`Context`を戻せない

*http.Requestオブジェクトが内包するContextオブジェクトを上書きすることはできません。
WithContextメソッドを呼ぶと新しい*http.Requestオブジェクトが返ってきますが、呼び出し元のミドルウェアに新しい*http.Requestオブジェクトを戻すことはできません。

つまり、以下のようなコードはうまくいきません。

func handler(w http.ResponseWriter, r *http.Request) {
    userID := getUserIDFromRequestBody(r)
    // 親のContextに値を追加しているわけではない
    newCtx := context.WithValue(r.Context(), "userID", userID)
    
    // 新しい*http.Requestを作成しているが、親の*http.Requestには影響しない
    newReq := r.WithContext(newCtx)
}

これらの前提知識をうまく回避してHTPハンドラー内のロジックからリクエストミドルウェアにIDを渡す2つのアプローチを紹介します。

アプローチ1: `http.ResponseWriter`実装をラップしてIDを伝搬する

http.ResponseWriterインターフェースを満たすオブジェクトにIDを受け渡しするAPIを仕込むのが最初のアプローチです。ミドルウェアでhttp.ResponseWriterインターフェースを満たすオブジェクトとしてラップしたオブジェクトを仕込んでおくことで、後続の処理からIDをラップしたオブジェクトにセットできます。ミドルウェアにはビジネスロジック実行後にhttp.ResponseWriterインターフェースを満たすオブジェクトを確認することでIDを取得可能です。

具体的な実装例は次のようになります。

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

type ResponseWriterDecorator struct {
    http.ResponseWriter
    tenantID string
}

func (rwd *ResponseWriterDecorator) SetTenantID(tenantID string) {
    rdw.tenantID = tenantID
}

func (rwd *ResponseWriterDecorator) TenantID() string {
    return rdw.tenantID
}

func RequestLogMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        rwd := &ResponseWriterDecorator{ResponseWriter: w}
        start := time.Now()
        next.ServeHTTP(rwd, r)
        // ハンドラー内でセットされたuserIDをここで取得
        tenantID := rwd.TenantID()
        log.Printf("request log tenant_id=%q duration=%v\n", tenantID, time.Since(start))
    })
}

func businessLogicHandler(w http.ResponseWriter, r *http.Request) {
    // ビジネスロジック
    if rwd, ok := w.(*ResponseWriterDecorator); ok {
        rwd.SetTenantID("update from businessLogicHandler")
    }
}

この方法の注意点

このアプローチでは、ミドルウェアがrwd.TenantIDメソッド経由で情報を取り出せます。
デメリットとしてはHTTPハンドラー内でhttp.ResponseWriterをキャストできるところまでIDを持ってこないといけない点があります。
カードチームのHTTPハンドラーもHTTPの処理をする層と具体的なビジネスロジックを実行する層を分離しているため、具体的なコードにすると少し奇妙になります。

package handler

import (
  usecase
)

func businessLogicHandler(w http.ResponseWriter, r *http.Request) {
  // インプットをHTTPの世界からGoの構造体に変換する処理
  input := parseInput(r.Body)
  // ビジネスロジックを実際に実行する処理
  result, tenantID, err :=  usecase.Execute(input)
  // エラーでもテナントIDはセットしておきたい。
  if rwd, ok := w.(*ResponseWriterDecorator); ok {
    if tenantID != "" {
      rwd.SetTenantID(tenantID)
    }
  }
  if err != nil {
    // エラーレスポンスを返す処理
    writeErrorResponse(w, err)
    return
  }
  // ビジネスロジックの結果をHTTPの世界に変換する処理
  writeSuccessResponse(w, result)
}

また、理想では透過的であるべきミドルウェアの存在をHTTPハンドラーの内部実装が認知している必要があります。

やり方2: `Context`オブジェクトへ構造体オブジェクトへのポインタを詰める

もう一つの手段は、Contextオブジェクト内に構造体オブジェクトのポインタを事前にWithValueメソッドで詰め込んでおくやり方です。
前提知識1で述べた通り、実際のcontextオブジェクトのValueに詰めた「値」自体はイミュータブルですが、その値（この場合ポインタが示す先にあるオブジェクト）の中の値は変更可能です。

具体的なサンプルコードは次のとおりです。

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

type requestInfoKey struct{}

type RequestInfo struct {
    TenantID string
}

func RequestLogMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        info := &RequestInfo{}
        ctx := context.WithValue(r.Context(), requestInfoKey{}, info)
        start := time.Now()
        next.ServeHTTP(w, r.WithContext(ctx))
        log.Printf("Access log tenant_id=%v duration=%v\n", info.TenantID, time.Since(start))
    })
}

func businessLogicHandler(w http.ResponseWriter, r *http.Request) {
    tenantID := "update from businessLogicHandler"
    if info, ok := r.Context().Value(requestInfoKey{}).(*RequestInfo); ok {
        info.TenantID = tenantID
    }
}

ここでは、RequestLogMiddlewareで*RequestInfoポインタをContextオブジェクトに詰めて、後続ハンドラーがRequestInfo.TenantIDフィールドへ値をセットします。リクエストログ出力時にはinfo.TenantIDを確認してログを出力します。

この方法の注意点

この手法は、Contextオブジェクトへ格納するデータをイミュータブルであるべきContextオブジェクトのValueが指すオブジェクトを更新しています。何回も値を書き換えるような使い方をするとゴルーチンセーフな前提を崩してしまうため、プロダクションコードではミドルウェアと別の共通ライブラリの仕組みで透過的に実行させるなどの工夫も必要そうです。