RareJob Tech Blog

レアジョブテクノロジーズのエンジニア・デザイナーによる技術ブログです

GoでRequest/Response BodyをロギングするHTTPサーバから見えてくるnet/http serverの実装

Go

こんにちは。プラットフォームチームの池田です。

目だけは脱デジタルしようというきっかけでPodcast、radiko、Audibleなどの音声コンテンツに最近ずっとハマっており、そのおかげでつよつよ家事マシンになりつつあります。

今回はゆるりとGoのnet/httpパッケージの内容を記事にします。

【目次】

やりたいこと

本記事にてやりたいことは以下2点です。

  • エラーレスポンス時にロギングとしてRequest/Response Bodyを標準出力するHTTPサーバを作りたい。
  • 上記に関連するGoの標準パッケージのnet/httpのserverな実装を追ってみたい。

弊社プラットフォームチームのGoなAPIサーバではGinフレームワークを採用していますが、今回はピュアなGoのnet/httpパッケージ内部を見てみることも目的としているのでミドルウェアを挟み込めるシンプルなHTTPルータを自作しサードパーティには依存しないようにします。

本記事で後述するロギングミドルウェアの実装方法はGinフレームワークでも同様になることを確認しています。

実行環境

$ go version
go version go1.17.2 darwin/amd64

準備 ~自作シンプルHTTPルータ~

上述の理由からシンプルなHTTPルータを作ります。

// シンプルHTTPルータ
type Router struct {
    pathFuncMap map[string]func(http.ResponseWriter, *http.Request)
    middlewares []func(next http.Handler) http.Handler
}

func (r *Router) HandleFunc(path string, f func(http.ResponseWriter, *http.Request)) {
    if r.pathFuncMap == nil {
        r.pathFuncMap = make(map[string]func(http.ResponseWriter, *http.Request))
    }
    r.pathFuncMap[path] = f
}

func (r *Router) AddMiddleware(mf func(handler http.Handler) http.Handler) {
    r.middlewares = append(r.middlewares, mf)
}

func (r *Router) ServeHTTP(w http.ResponseWriter, req *http.Request) {
    // match path
    var handler http.Handler
    for p, f := range r.pathFuncMap {
        if p == req.URL.Path {
            handler = http.HandlerFunc(f)
        }
    }
    if handler == nil {
        handler = http.NotFoundHandler()
    } else {
        // set middleware
        for i := len(r.middlewares) - 1; i >= 0; i-- {
            handler = r.middlewares[i](handler)
        }
    }

    // serve http
    handler.ServeHTTP(w, req)
}

URLパスとアプリ用HTTPハンドラのペアをHandleFuncで、ミドルウェアをAddMiddlewareで登録させます。リクエスト時にServeHTTP内でリクエストURLパスマッチ処理と登録されたミドルウェアを当て込んだハンドラ生成をします。

設定されるミドルウェアはスタックな後入れ先実行になり、一般的なフレームワークと同様に利用者は実装するミドルウェア上で次のハンドラーを呼び出すnext.ServeHTTPをする必要があります。

ミドルウェア設定無しで動かす

はじめに、ロギングしない場合でのサーバ実装と出力を示します。helloはRequest Bodyの中身に従って200 OKか400 Badを返すアプリ処理想定の単純なHTTPハンドラです。

// ロギング用ミドルウェア
func LoggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        next.ServeHTTP(w, r)
    })
}

// アプリケーションHTTPサーバ
func hello(w http.ResponseWriter, r *http.Request) {
    b, _ := io.ReadAll(r.Body)
    if string(b) != `{"a": "b"}` {
        w.WriteHeader(http.StatusBadRequest)
        w.Write([]byte(`{"res": "No hello"}`))
        return
    }
    w.WriteHeader(http.StatusOK)
    w.Write([]byte(`{"res": "hello"}`))
}

func main() {
    // 自作ルータをセット
    r := &Router{}
    r.HandleFunc("/hello", hello)
    r.AddMiddleware(LoggingMiddleware)

    http.ListenAndServe(":8090", r)
}

上記サーバを立ち上げリクエストすると以下のような動作になります。

$ curl -i -XPOST http://localhost:8090/hello -d '{"a": "b"}'
HTTP/1.1 200 OK
{"res": "hello"}

$ curl -i -XPOST http://localhost:8090/hello -d '{"a": "X"}'
HTTP/1.1 400 Bad Request
{"res": "No hello"}

このときサーバ側の標準出力にはまだ何も出てきません。

Request Bodyを出力する

Request Bodyをログとして出すようにしてみます。ハマりどころとして以下のように単純にやると処理がうまくいかなくなります。

失敗してしまう書き方

func LoggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        bufOfRequestBody, _ := io.ReadAll(r.Body)

        var out io.Writer = os.Stdout
        fmt.Fprintln(out, "request body: ", string(bufOfRequestBody))

        // アプリケーション処理
        next.ServeHTTP(w, r)
    })
}

$ curl -i -XPOST http://localhost:8090/hello -d '{"a": "b"}' # 200 OKが返るべきリクエスト
HTTP/1.1 400 Bad Request

こうなってしまう原因はロギング後のアプリ側helloハンドラでの b, _ := io.ReadAll(r.Body) にて空の結果しか返らなくなってしまうためです。

空になる原因を深掘る

net/httpの標準ライブラリを追うとわかります。

http.Request.Bodyはio.ReadCloserインターフェース型であり実態であるインスタンスはnet/httpのtransfer.goにあるbody構造体です。今回関係するフィールドのみ抜粋すると以下になります。

ソースコードリンク

type body struct {
    src          io.Reader
    // ... 省略
    sawEOF     bool
    closed     bool
    // ... 省略
}

io.ReadAll(req.Body)にてhttp.Request.BodyのRead関数が呼ばれることになりますが、そこを追うと以下のコードがあります。

ソースコードリンク

func (b *body) Read(p []byte) (n int, err error) {
    b.mu.Lock()
    defer b.mu.Unlock()
    if b.closed {
        return 0, ErrBodyReadAfterClose
    }
    return b.readLocked(p)
}

// このメソッドを呼ぶときはb.muをロックしておかなければならない。
func (b *body) readLocked(p []byte) (n int, err error) {
    if b.sawEOF { // ② 読み込み済みならば即EOFを返す
        return 0, io.EOF
    }
    n, err = b.src.Read(p)

    if err == io.EOF { 
        b.sawEOF = true // ① 読み込み終わったらbodyにあるsawEOFフラグをtrueにする
        // Chunked case. Read the trailer.
        if b.hdr != nil {
            if e := b.readTrailer(); e != nil {
// ... 省略

上記の①②の箇所のようにbody.sawEOFフラグにより読み取り済みかそうでないかを制御しておりこれにより2回目以降は空の結果しか返らないことがわかります。

なぜRequest Bodyを読み切る制御をしているのか深掘る

結論として、クライアントとのTCP接続にてコネクションを再利用するかしないかの判定材料の1つにRequest Bodyを読み切ったかがあるためです。

以下の箇所はレスポンスヘッダー書き込みをする処理であり、この処理時にRequest BodyがClosedにも関わらずsawEOFがfalseのままである場合は接続自体が不良という判断になり、net/httpでのHTTP Responseの実態であるresponse構造体のcloseAfterReplyをtrueにします。

ソースコードリンク

func (cw *chunkWriter) writeHeader(p []byte) {
// ... 省略
            case bdy.closed:
                if !bdy.sawEOF {
                    // Body was closed in handler with non-EOF error.
                    w.closeAfterReply = true
                }

そして以下のようにcloseAfterReplyはServe処理の最後でTCP接続を保ち続けるか切るかの判断に使われます。

ソースコードリンク

func (w *response) shouldReuseConnection() bool {
    if w.closeAfterReply {
        // The request or something set while executing the
        // handler indicated we shouldn't reuse this
        // connection.
        return false
    }
// ... 省略

※ net/http内のコメントアウトを読む限りこれはHTTP1.1の仕様由来のようですが私の方ではRFCドキュメント内でそのような記述は確認できませんした。

成功する書き方

正しい書き方として、以下のようにio.NopCloserで消費されてしまったRequest Bodyを補修する必要があります。下記のような処理はリクエスト内容を出力するnet/http/httputil でのDumpRequestなどでも同様に実装されています。

       bufOfRequestBody, _ := io.ReadAll(r.Body)

+       // [For Request Body] 消費されてしまったRequest Bodyを補修する
+       r.Body = io.NopCloser(bytes.NewBuffer(bufOfRequestBody))

        var out io.Writer = os.Stdout
        fmt.Fprintln(out, "request body: ", string(bufOfRequestBody))

Response Bodyを出力する

Response Bodyを出力する場合も少し工夫が必要になります。というのもhttp.ResponseWriterインターフェースにはResponse Bodyにアクセスするメソッドが無いためです。

以下のようにGoの構造体への埋め込み(Embedding)を用いてhttp.ResponseWriterインターフェースの実態をハック(intercept)します。

type interceptWriter struct {
    http.ResponseWriter
    status int
    body   *bytes.Buffer
}

// Writeをハックする
func (w *interceptWriter) Write(b []byte) (int, error) {
    w.body.Write(b)
    return w.ResponseWriter.Write(b) // 埋め込み元を呼ぶことで元の動作を保証する
}

// WriteHeaderをハックする
func (w *interceptWriter) WriteHeader(statusCode int) {
    w.status = statusCode
    w.ResponseWriter.WriteHeader(statusCode)
}

// ロギング用ミドルウェア
func LoggingMiddleware(next http.Handler) http.Handler {
    return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        bufOfRequestBody, _ := io.ReadAll(r.Body)
        // [For Request Body] 消費されてしまったRequest Bodyを修復する
        r.Body = io.NopCloser(bytes.NewBuffer(bufOfRequestBody))

        // [For Response Body] ResponseWriterへ割り込む (interceptする)
        iw := &interceptWriter{
            body:           bytes.NewBufferString(""),
            ResponseWriter: w, // 元のwriterインスタンスを埋め込む
        }
        w = iw

        // アプリケーション処理
        next.ServeHTTP(w, r)

        // レスポンスがエラーの場合、ログ出力する
        if iw.status >= 400 {
            var w io.Writer = os.Stdout
            fmt.Fprintln(w, "error status: ", iw.status)
            fmt.Fprintln(w, "request body: ", bytes.NewBuffer(bufOfRequestBody))
            fmt.Fprintln(w, "response body:", iw.body.String())
        }
    })
}

Go公式の以下にあるように埋め込み先の構造体で同名フィールドまたはメソッドを作った場合、そちらが優先される仕様になっています。

Embedding types introduces the problem of name conflicts but the rules to resolve them are simple. First, a field or method X hides any other item X in a more deeply nested part of the type.

埋め込み元としてのResponseWriterの実態はRequestの話にも出たresponse構造体です。以下リンクのWriteメソッドのコメントアウトの説明で最終的にコネクションのバッファに書き込まれる流れが記載されています。

ソースコードリンク

ログを確認する

ここまでのサーバを立ち上げ、エラーになるリクエストすると以下のようにサーバログ結果が確認できました。

クライアント側

curl -i -XPOST http://localhost:8090/hello -d '{"a": "X"}'
HTTP/1.1 400 Bad Request
{"res": "No hello"}

サーバ側ログ

error status:  400
request body:  {"a": "X"}
response body: {"res": "No hello"}

参考にさせていただいた記事

https://zenn.dev/imamura_sh/articles/retry-46aa586aeb5c3c28244e

https://tutuz-tech.hatenablog.com/entry/2020/03/23/162831