🪵

GoのカスタムRoundTripperでリクエストとレスポンスをログ出力する

2025/01/31に公開

はじめに

SaaS開発を行っていると、外部APIとの連携が必要になることが多いです。ここで外部APIとはパブリックに提供されているAPIはもちろん、パートナー企業が提供するAPIや、自社で運用している別のサービスのAPIも含みます。
どのような種類のAPI連携であっても、意図しない挙動がありサポートに問い合わせるとき「自分たちのリクエストがどうだったか」を示すログを提供することで、問題の解決が早まることがあります。

本記事では、http.RoundTripper を実装し、Observabilityを高める方法を紹介します。

また本記事のサンプルコードは以下にあります。

https://github.com/takashabe/roundtripper-sample

欲しい情報

Observabilityを考えるとき、基本的には以下の3つが欲しくなると思います。MetricsとTracingはotelを挟むことで簡単に取得できるので、ここではLoggingにフォーカスします。

  1. Logging

    • どのようなリクエストを送信し、どのようなレスポンスを受信したか記録する。
  2. Metrics

    • 外部APIのレスポンスタイム、成功/失敗率を収集し、パフォーマンスを監視する。
  3. Tracing

    • 1つのリクエストがどのように処理され、どのAPIとやりとりしたかを可視化する。

http.RoundTripperについて

Goでは http.RoundTripper インターフェースを実装して、それをHTTPクライアントに差し込むことで振る舞いをカスタマイズすることができます。

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

https://pkg.go.dev/net/http#RoundTripper

シンプルな例として、HTTPリクエストを送信する際に固定の文字列をログ出力するRoundTripperを実装してみます。

var _ http.RoundTripper = &SimpleRoundTripper{}

type SimpleRoundTripper struct {}

func (rt *SimpleRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
    log.Println("Sending request")
    return http.DefaultTransport.RoundTrip(req)
}

これを使って、以下のようにリクエストを送信すると Sending request というログが出力されます。

main.go
client := &http.Client{
    Transport: &SimpleRoundTripper{},
}
client.Get("http://example.com")
$ go run .
2025/01/31 08:50:48 Sending request

LoggingRoundTripperの実装

ここまででRoundTripperを実装する方法がわかったので、リクエストとレスポンスの内容をログ出力するLoggingRoundTripperを実装してみます。
基本的なアイデアは、httputilパッケージの DumpRequestOutDumpResponse を使ってリクエストとレスポンスを文字列に変換し、それをログ出力することです。

https://pkg.go.dev/net/http/httputil

type LoggingRoundTripper struct {}

func (lrt *LoggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
    ctx := req.Context()

     clone := req.Clone(ctx)
     b, err := io.ReadAll(clone.Body)
     if err != nil {
         return nil, fmt.Errorf("failed to read request body: %w", err)
     }
     defer clone.Body.Close()

     // 元リクエストのBodyをリストア
     req.Body = io.NopCloser(bytes.NewReader(b))

     // dump request
     clone.Body = io.NopCloser(bytes.NewReader(b))
     reqDump, err := httputil.DumpRequestOut(clone, true)
     if err != nil {
         return nil, fmt.Errorf("httputil.DumpRequestOut: %w", err)
     }
     log.Println(string(reqDump))

     resp, err := http.DefaultTransport.RoundTrip(req)
     if err != nil {
         return nil, fmt.Errorf("http.DefaultTransport.RoundTrip: %w", err)
     }

     // dump response
     respDump, err := httputil.DumpResponse(resp, true)
     if err != nil {
         return nil, fmt.Errorf("httputil.DumpResponse: %w", err)
     }
     log.Println(string(respDump))

     return resp, nil
}

bodyはログ出力用にバッファを分けることで、元リクエストには影響を与えないようにしています。
これを使って、以下のようにリクエストを送信するとリクエストとレスポンスの内容がログ出力されます。

main.go
client := &http.Client{
    Transport: &LoggingRoundTripper{},
}
body := map[string]string{
    "username": "user",
    "password": "password",
}
b, err := json.Marshal(body)
if err != nil {
    return err
}
req, err := http.NewRequestWithContext(context.Background(), "POST", "https://httpbin.org/post", bytes.NewReader(b))
if err != nil {
    return err
}
req.Header.Set("Content-Type", "application/json")
_, err = client.Do(req)

httpbin.org宛のリクエストと、その後にレスポンスのダンプが出力されていることが分かります。

$ go run .
2025/01/31 09:18:46 POST /post HTTP/1.1
Host: httpbin.org
User-Agent: Go-http-client/1.1
Content-Length: 41
Content-Type: application/json
Accept-Encoding: gzip

{"password":"password","username":"user"}
2025/01/31 09:18:47 HTTP/2.0 200 OK
Content-Length: 509
Access-Control-Allow-Credentials: true
Access-Control-Allow-Origin: *
Content-Type: application/json
Date: Fri, 31 Jan 2025 00:18:47 GMT
Server: gunicorn/19.9.0

{
  "args": {},
  "data": "{\"password\":\"password\",\"username\":\"user\"}",
  "files": {},
  "form": {},
  "headers": {
    "Accept-Encoding": "gzip",
    "Content-Length": "41",
    "Content-Type": "application/json",
    "Host": "httpbin.org",
    "User-Agent": "Go-http-client/2.0",
    "X-Amzn-Trace-Id": "Root=1-679c16e7-536069b67dfefd0539c87ed2"
  },
  "json": {
    "password": "password",
    "username": "user"
  },
  "origin": "217.178.16.153",
  "url": "https://httpbin.org/post"
}

機密情報をマスクする

先の例ではbodyにpasswordを含めていましたが、これは機密情報であるためログに残すべきではありません。ということで任意のキーに対してマスクを行う機能を追加してみます。

こちらは github.com/tidwall/gjsongithub.com/tidwall/sjson を使ってjsonのフィールドをマスクすることで実現してみます。
また何のフィールドをマスクするかはLoggingRoundTripperのフィールドとして指定できるようにしてみます。

4a5
>       "encoding/json"
9a11,13
>
>       "github.com/tidwall/gjson"
>       "github.com/tidwall/sjson"
12c16,18
< type LoggingRoundTripper struct{}
---
> type LoggingRoundTripper struct {
>       MaskFields []string
> }
28c34,38
<       clone.Body = io.NopCloser(bytes.NewReader(b))
---
>       maskedBody, err := maskJSONFields(b, lrt.MaskFields)
>       if err != nil {
>               return nil, fmt.Errorf("failed to mask request body: %w", err)
>       }
>       clone.Body = io.NopCloser(bytes.NewReader(maskedBody))
>       clone.ContentLength = int64(len(maskedBody))
>       clone.Header.Set("Content-Length", fmt.Sprint(len(maskedBody)))
48a59,78
>
> // maskJSONFields request bodyの指定されたフィールドをマスクする. bodyがJSONでない場合は何もしない
> func maskJSONFields(body []byte, fieldsToMask []string) ([]byte, error) {
>       if ok := json.Valid(body); !ok {
>               return body, nil
>       }
>
>       maskedBody := string(body)
>       var err error
>       for _, field := range fieldsToMask {
>               if !gjson.Get(maskedBody, field).Exists() {
>                       continue
>               }
>               maskedBody, err = sjson.Set(maskedBody, field, "***")
>               if err != nil {
>                       return nil, fmt.Errorf("failed to mask field: %w", err)
>               }
>       }
>       return []byte(maskedBody), nil
> }

ここで MaskFields にpasswordを指定してリクエストを送信すると、以下のようにpasswordがマスクされていることが分かります。

$ go run .
2025/01/31 09:28:16 Sending request
2025/01/31 09:28:16 POST /post HTTP/1.1
Host: httpbin.org
User-Agent: Go-http-client/1.1
Content-Length: 36
Content-Type: application/json
Accept-Encoding: gzip

{"password":"***","username":"user"}
...

まとめ

Goの http.RoundTripper を使って、リクエストとレスポンスの内容をログ出力するLoggingRoundTripperを実装しました。
また、特定のフィールドをマスクすることで、機密情報などの扱いに対応しました。

このようなカスタムRoundTripperを使うことで、外部APIとの連携においてObservability向上に役立てることができます。
実際にはotelhttpなどと組み合わせて利用しているので、Transportを差し込めるようにしていたりしますが、最低限の実装としては今回紹介した形で充分だと思います。

ログを出力するだけだと検索しづらいので、手前味噌ですが以下のような手法を使ってトレースIDと紐付けるのがオススメです。
https://zenn.dev/castingone_dev/articles/20231222-gcp_o11y

Discussion