gin(golang)のリクエストボディを複数回読み取る方法

TL;DR

1. ginのリクエストボディはread用ストリームで提供されるため、1度読み出すと、再度読み取ることができなくなる
2. ミドルウェアで読み取った結果をginのcontextにセットしておくことで何度でも読み取ることができるようになる

経緯

ginでAPIサーバを実装していて、APIの結果をログに出していた。
gin-contrib/loggerを使ってAPIの本処理の後に呼ばれログを出力するミドルウェアを組み込むような実装をした。

このログにリクエストボディも出力したくなったので、gin.ContextのRequest.Bodyを読み取って出力しようとした。
合わせて、以下のような実装となった。
(なお、話を単純化するめにリクエストボディはJSON等のテキストである前提とする)

func GenerateSetLoggerMiddleware() gin.HandlerFunc {
	return logger.SetLogger(
		logger.WithUTC(true),
		logger.WithLogger(func(c *gin.Context, out io.Writer, latency time.Duration) zerolog.Logger {
			body, _ := io.ReadAll(c.Request.Body) // ここでリクエストボディを読み取り
			return zerolog.New(out).With().
				Timestamp().
				Int("status", c.Writer.Status()).
				Dur("latency", latency).
                // 中略
                Str("body", string(body)). // ここでログにセット
				Logger()
		}))
}

// ※補足: ginには以下のようにセットする想定
r := gin.New()
r.Use(middleware.GenerateSetLogger())

これでログに出力されるはず……と思ったのだが、結果としては"body"には常に空となり、実際のリクエストボディが出力されることはなかった。

原因

APIを実装する中で、通常(当たり前だが)リクエストボディを読み取る処理が入る。
例えば、単純にテキストとして読み取るのであれば次のような処理になる。

func ExtractRequestBodyText(ctx *gin.Context) (string, error) {
    body, err := io.ReadAll(ctx.Request.Body)
	if err != nil {
		return "", err
	}
    return string(body), nil
}

またJSONを読み取るのであれば、以下のような処理になる。
(ginのコードを見ると分かるのだが、ShouldBindJSONは内部的にはjsonパッケージのDecodeを使って、bodyのストリームを読み取っている)

type ReqBody struct {
	Foo string `json:"foo"`
	Bar string `json:"bar"`
}

func ParseRequestBody(ctx *gin.Context) (*ReqBody, error) {
	var body ReqBody
    // ※ginの提供する関数で、内部的にはctx.Request.Bodyのstreamから読み出してJSON化してくれるもの
	if err := ctx.ShouldBindJSON(&body); err != nil {
		return nil, err
	}
	return &body, nil
}

いずれにしても、Request.Bodyのストリームから読み取っているので、これ以降は単純にRequest.Bodyから読み取ろうとしても、実際のリクエストボディは取得できなくなる。
つまり、APIの本処理でリクエストボディを読み取ったことが、その後で呼び出されるミドルウェアからリクエストボディを読めない原因ということになる。

解決方法の模索

当然、ほとんどの場合APIの本処理でリクエストボディは読み取ることになる。
また、ログにリクエストボディを出力させたいというのは広くある要望だと思われる。
ということで、まずは同じような問題に直面した事例がないか調べてみた。

方法1: 読み取ったら再セットする

ginリポジトリのissueコメントに以下のようなコード例が示されていた。

issueコメントより抜粋

func RequestLoggerMiddleware() gin.HandlerFunc {
	return func(c *gin.Context) {
		var buf bytes.Buffer
		tee := io.TeeReader(c.Request.Body, &buf)
		body, _ := ioutil.ReadAll(tee)
		c.Request.Body = ioutil.NopCloser(&buf)
		log.Debug(string(body))
		log.Debug(c.Request.Header)
		c.Next()
	}
}

読み取ったら無くなってしまうので再セットすれば良い、という考え方である。
io.TeeReaderを使ってるのが特徴的。

ただ、これは本処理の前に呼び出されるミドルウェアなので良いが、後で呼び出される場合には適用できない。
もちろん、本処理で読み取る部分で同様のことをすれば良いが、それを各APIに強制したくはない。
(そもそも、直接リクエストボディを読み取るのではなく、前述の ShouldBindJSONのようなginの関数を使うことが多いので適用するのも難しい)

方法2: ミドルウェアでリクエストボディを再利用可能なものに差し替える

Read Go HTTP Request body multiple timesという、まさにやりたいことズバリというタイトルのブログで、再利用可能なReaderに差し替える方法が紹介されていた。
詳しくはブログを参照してもらえれば良いが、

1. 読み取り用のbufferとバックアップ用のbufferを用意する
2. 読み取り時にio.TeeReaderを使って、読み取り先とは別にバックアップ用のbufferにも出力する
3. EOFを検出した(つまり読み取りが完了した)時点でバックアップbufferを読み取り用bufferにコピーする

という仕組みになっている。

コード抜粋

type reusableReader struct {
    io.Reader
    readBuf *bytes.Buffer
    backBuf *bytes.Buffer
}

func ReusableReader(r io.Reader) io.Reader {
    readBuf := bytes.Buffer{}
    readBuf.ReadFrom(r) // error handling ignored for brevity
    backBuf := bytes.Buffer{}

    return reusableReader{
        io.TeeReader(&readBuf, &backBuf),
        &readBuf,
        &backBuf,
    }
}

func (r reusableReader) Read(p []byte) (int, error) {
    n, err := r.Reader.Read(p)
    if err == io.EOF {
        r.reset()
    }
    return n, err
}

func (r reusableReader) reset() {
    io.Copy(r.readBuf, r.backBuf) // nolint: errcheck
}

これはまさに求めていたものだと思ったのだが、ginでの利用にはフィットしないことが分かった。
ginではJSONのリクエストボディを読み取るのにBindJSON系のメソッドを使うことが多いが、これでリクエストボディを読み出す場合、EOFまで読まずにJSONの終端括弧までで読み取りを終了してしまう。
このため、バックアップから読み取り用bufferへのコピーが走らず、ReusableReaderは期待した通りの機能を果たさない。

補足: BindJSONではリクエストボディをEOFまで読み取らない

このセクションは本旨には関係が薄い詳細についての補足なので、興味がある人だけが読んでもらえればと思う。

• ginのBindJSON系ではjsonパッケージのDecoderが使われている
  • ginの該当コード
• json.DecoderではReaderをEOFまではなく、対応する括弧までを読む

ということを実証したコードを以下に示す。

func TestJsonDecode(t *testing.T) {
	const doubleJsonText = "{\"key1\":\"value1\"}\n{\"key2\":\"value2\"}"
	reader := strings.NewReader(doubleJsonText)
	decoder := json.NewDecoder(reader)
	var bound1 map[string]string
	err := decoder.Decode(&bound1)
	assert.NoError(t, err)
	part1 := map[string]string{"key1": "value1"}
	assert.Equal(t, part1, bound1) // 最初のJSONパートが読み取られる

	var bound2 map[string]string
	err = decoder.Decode(&bound2)
	assert.NoError(t, err)
	part2 := map[string]string{"key2": "value2"}
	assert.Equal(t, part2, bound2) // 2番目のJSONパートが読み取られる

	var bound3 map[string]string
	err = decoder.Decode(&bound2)
	assert.Error(t, err) // ここでEOFのerrorが出る
	assert.Nil(t, bound3)
}

テストに使ったJSONテキストイメージ

{“key1“:“value1“}
{“key2“:“value2“}

このようにJSON部分を読み出した段階ではEOFに到達しないため、先述のReusableReaderは機能しない。

(限定的な)解決策

以上のような調査や試行錯誤の結果、今回は以下のような解決策を取った。

1. 本処理の前に呼ばれるミドルウェアで Request.Body を読み取り、以下の処理を実施
   1. Request.Bodyに書き戻す
   2. gin.Contextにテキストとしてセット
2. 本処理では従来どおり、Request.Bodyから読み取る
3. 本処理の後のログ出力処理では、gin.Contextにセットしたテキストを使う

実装

まず、以下のようなリクエストボディを取り出すミドルウェアを用意する。

middleware.go

func GenerateRequestBodySaveMiddleware() gin.HandlerFunc {
	return func(c *gin.Context) {
		var buf bytes.Buffer
        // io.TeeReaderを使い、読み出し先とは別のbufferにもセットされるようにする
		tee := io.TeeReader(c.Request.Body, &buf)
		body, err := io.ReadAll(tee)
		if err != nil {
			c.AbortWithStatus(http.StatusInternalServerError)
			return
		}
		// リクエストボディは1度読み出すと空になるので、再度読み出せるようにする
		c.Request.Body = io.NopCloser(&buf)
		c.Set(keyRequestBodyBackup, string(body))
		c.Next()
	}
}

ログを出力するミドルウェアは以下のような実装になる。

middleware.go

func GenerateSetLoggerMiddleware() gin.HandlerFunc {
	return logger.SetLogger(
		logger.WithUTC(true),
		logger.WithLogger(func(c *gin.Context, out io.Writer, latency time.Duration) zerolog.Logger {
            // contextに保持したリクエストボディの文字列を取り出す
			requestBody, _ := c.Get(keyRequestBodyBackup)
			return zerolog.New(out).With().
				Timestamp().
				Int("status", c.Writer.Status()).
				Dur("latency", latency).
                // 中略
				Str("body", requestBody.(string)). // ここでログにセット
				Logger()

		}))
}

注意点

「限定的な解決策」としたが、この方法では、Readerとは別に文字列をオンメモリに保持することになる。
巨大なリクエストボディがある場合はこの方式は適切ではない可能性がある。

また、コード例ではテキストが入っていることを前提としているが、文字列化できないバイナリがリクエストボディに含まれることが想定されるケースでは、何らかの対応が必要になる。