Day 056 — 2026-09-26 | ミドルウェア設計パターン: レビュー依頼の4本のミドルウェアと Chain に潜む5つのバグ——順序・return 抜け・ResponseWriter のラップ・本文の消費をテストで炙り出す

📚 背景知識（読んでから問題へ）

今日からテーマ15「ミドルウェア設計パターン」です（2026-09-25 に暦日ルールで切り替わり、次の切り替えは 2026-10-25）。Day 055 で書いた gRPC サーバーの ServeHTTP の前半（POST と content-type の検査）は、まさにミドルウェアへ切り出す部分でした。今日はその「切り出した後」に何が壊れるかを、レビューの形で扱います。

Go のミドルウェアは「Handler を受け取って Handler を返す関数」だけ

📋 コピーtype Middleware func(http.Handler) http.Handler

標準ライブラリにミドルウェアの仕組みはありません。http.Handler が1メソッドのインターフェースなので、「前処理 → next.ServeHTTP(w, r) → 後処理」を書いた Handler で包むだけで済みます。玉ねぎの皮のように、外側のミドルウェアほど先に呼ばれ、最後に戻ってきます。

📋 コピーリクエスト → RequestID → Logging → Recover → RequireAuth → mux（本体）
レスポンス ← RequestID ← Logging ← Recover ← RequireAuth ←
             （後処理は逆順に走る。Logging の「ログを書く」は Recover の後）

このため、世界で広く使われているルーター・補助ライブラリはどれも「並べた順＝外から内」という約束を持っています（star は 2026-09-26 に gh api repos/... で取得）:

chi の chain.go（2026-09-26 に gh api で取得）の該当部分:

📋 コピー// Wrap the end handler with the middleware chain
h := middlewares[len(middlewares)-1](endpoint)
for i := len(middlewares) - 2; i >= 0; i-- {
	h = middlewares[i](h)
}

ResponseWriter を包むと「能力」が消える

アクセスログにステータスコードを出すには、http.ResponseWriter を包んで WriteHeader を横取りする必要があります。ところが本物の ResponseWriter は http.Flusher（SSE・ストリーミング）、http.Hijacker（WebSocket）なども実装しています。構造体に http.ResponseWriter を埋め込むと、インターフェースに書かれた3メソッドしか昇格しないので、それ以外の能力は包んだ瞬間に消えます。

httpsnoop の README は、この問題を理由に作られたと書いています。原文: "everything I've seen so far has a high chance of breaking your application"（felixge/httpsnoop README、2026-09-26 取得）。

Go 1.20 で入った http.NewResponseController は、包んだ側が Unwrap() を持っていれば元の ResponseWriter まで辿ってくれます。go doc net/http.NewResponseController（Go 1.27.1）の記述:

📋 コピーThe ResponseWriter should be the original value passed to the
Handler.ServeHTTP method, or have an Unwrap method returning the original
ResponseWriter.
...
If the ResponseWriter does not support a method, ResponseController returns
an error matching ErrNotSupported.

Handler の約束ごと（go doc net/http.Handler）

• "Except for reading the body, handlers should not modify the provided Request."（本文を読む以外に、受け取った Request を書き換えない）
• ハンドラが panic すると、サーバーはその接続（HTTP/2 ならストリーム）を切る。http.ErrAbortHandler で panic すると、クライアントには中断として見え、サーバーのログにはスタックが出ない

この2つは、今日のバグのうち2つの「正しい直し方」を決める根拠になります。

📝 問題

あなたは注文 API のコードレビューを頼まれました。作者のコメントでは「外側から RequestID → Logging → Recover → RequireAuth → mux の順に通す」つもりです。ステージング環境から次の3件の報告が来ています。

1. 「認証エラー（401）のアクセスログが1行も出ていない。panic したリクエストのログにも request ID が空で出る」
2. 「SSE の /events が、300ms 後にまとめて届く。サーバーの標準エラーに flush failed err="feature not supported" が出る」
3. 「POST /orders が常に 400 empty body になる」

加えて、セキュリティ担当から「トークン無しで GET /orders/42 を叩くと、注文データが見える」と指摘がありました。

課題

1. 予測: 下の main_test.go の6つのテストのうち、どれが落ちるかを、実行する前に書き出してください。落ちる理由を1行ずつ添えます
2. バグの特定と修正: main.go のバグを5つ見つけ、それぞれ最小の差分で直してください。直し方が複数ある箇所は、採った案と採らなかった案を1行ずつ書きます
3. 順序の設計: Logging と Recover はどちらを外側に置くべきですか。逆にしたとき、panic したリクエストのアクセスログの status に何が出るかを予測してください
4. レビューの追加指摘: Recover は http.ErrAbortHandler をどう扱うべきですか。握りつぶしたとき、途中まで書いたレスポンスを受け取ったクライアントには何が見えますか

準備

📋 コピーmkdir day056 && cd day056
# 下の go.mod・main.go・main_test.go・testutil_test.go を置く
go test -count=1 -v ./...        # 6つのテストを実行する
go run .                          # :8080 でサーバーを起動する（手で curl したいとき）

go.mod:

📋 コピーmodule day056

go 1.24

main.go（レビュー対象。バグ入り）

📋 コピー// 注文 API のミドルウェア群。レビュー依頼で届いたコード（バグ入り）。
// 意図: 外側から RequestID → Logging → Recover → RequireAuth → mux の順に通す。
package main

import (
	"context"
	"crypto/rand"
	"encoding/hex"
	"fmt"
	"io"
	"log/slog"
	"net/http"
	"os"
	"time"
)

type Middleware func(http.Handler) http.Handler

// Chain は mws を「先に書いたものが外側」になるように h に被せる……つもり。
func Chain(h http.Handler, mws ...Middleware) http.Handler {
	for _, m := range mws {
		h = m(h)
	}
	return h
}

type ctxKey struct{}

func RequestID(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		id := r.Header.Get("X-Request-Id")
		if id == "" {
			b := make([]byte, 8)
			_, _ = rand.Read(b)
			id = hex.EncodeToString(b)
		}
		w.Header().Set("X-Request-Id", id)
		next.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), ctxKey{}, id)))
	})
}

func requestIDFrom(ctx context.Context) string {
	id, _ := ctx.Value(ctxKey{}).(string)
	return id
}

// statusRecorder はステータスコードと書いたバイト数を記録する。
type statusRecorder struct {
	http.ResponseWriter
	status int
	bytes  int
}

func (s *statusRecorder) WriteHeader(code int) {
	s.status = code
	s.ResponseWriter.WriteHeader(code)
}

func (s *statusRecorder) Write(b []byte) (int, error) {
	n, err := s.ResponseWriter.Write(b)
	s.bytes += n
	return n, err
}

func Logging(logger *slog.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			start := time.Now()
			rec := &statusRecorder{ResponseWriter: w}
			body, _ := io.ReadAll(r.Body) // 監査用にリクエストの大きさも残したい
			next.ServeHTTP(rec, r)
			logger.Info("request",
				"id", requestIDFrom(r.Context()),
				"method", r.Method,
				"path", r.URL.Path,
				"status", rec.status,
				"bytes", rec.bytes,
				"req_bytes", len(body),
				"dur_ms", time.Since(start).Milliseconds(),
			)
		})
	}
}

func Recover(logger *slog.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			defer func() {
				if v := recover(); v != nil {
					logger.Error("panic", "id", requestIDFrom(r.Context()), "value", fmt.Sprint(v))
					http.Error(w, "internal error", http.StatusInternalServerError)
				}
			}()
			next.ServeHTTP(w, r)
		})
	}
}

func RequireAuth(token string) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			if r.Header.Get("Authorization") != "Bearer "+token {
				http.Error(w, "unauthorized", http.StatusUnauthorized)
			}
			next.ServeHTTP(w, r)
		})
	}
}

func newMux() *http.ServeMux {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /orders/{id}", func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		fmt.Fprintf(w, `{"id":%q,"customer":"ACME","total":12800}`, r.PathValue("id"))
	})
	mux.HandleFunc("POST /orders", func(w http.ResponseWriter, r *http.Request) {
		b, err := io.ReadAll(r.Body)
		if err != nil || len(b) == 0 {
			http.Error(w, "empty body", http.StatusBadRequest)
			return
		}
		w.WriteHeader(http.StatusCreated)
		fmt.Fprintf(w, `{"received_bytes":%d}`, len(b))
	})
	mux.HandleFunc("GET /events", func(w http.ResponseWriter, r *http.Request) {
		rc := http.NewResponseController(w)
		w.Header().Set("Content-Type", "text/event-stream")
		for i := range 3 {
			fmt.Fprintf(w, "data: tick %d\n\n", i)
			if err := rc.Flush(); err != nil && i == 0 {
				// 止めはしない。届くのが最後にまとめてになるだけ
				slog.Warn("flush failed", "err", err)
			}
			time.Sleep(100 * time.Millisecond)
		}
	})
	mux.HandleFunc("GET /panic", func(w http.ResponseWriter, r *http.Request) {
		var m map[string]int
		m["boom"]++ // nil map への書き込み
	})
	return mux
}

func newServer(logger *slog.Logger, token string) http.Handler {
	return Chain(newMux(),
		RequestID,
		Logging(logger),
		Recover(logger),
		RequireAuth(token),
	)
}

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info("listening", "addr", ":8080")
	if err := http.ListenAndServe(":8080", newServer(logger, "secret-token")); err != nil {
		logger.Error("server", "err", err)
	}
}

main_test.go（これが全部通れば完了）

📋 コピーpackage main

import (
	"bufio"
	"bytes"
	"encoding/json"
	"net/http"
	"net/http/httptest"
	"strings"
	"testing"
	"time"
)

const token = "secret-token"

// logLines は JSON ログを1行ずつ map にして返す。
func logLines(t *testing.T, buf *bytes.Buffer) []map[string]any {
	t.Helper()
	var out []map[string]any
	for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
		if line == "" {
			continue
		}
		var m map[string]any
		if err := json.Unmarshal([]byte(line), &m); err != nil {
			t.Fatalf("log line is not JSON: %q", line)
		}
		out = append(out, m)
	}
	return out
}

func requestLog(t *testing.T, buf *bytes.Buffer) map[string]any {
	t.Helper()
	for _, m := range logLines(t, buf) {
		if m["msg"] == "request" {
			return m
		}
	}
	return nil
}

func do(t *testing.T, h http.Handler, method, path, body string, auth bool) *httptest.ResponseRecorder {
	t.Helper()
	req := httptest.NewRequest(method, path, strings.NewReader(body))
	if auth {
		req.Header.Set("Authorization", "Bearer "+token)
	}
	rec := httptest.NewRecorder()
	h.ServeHTTP(rec, req)
	return rec
}

// B1: 認証で弾かれたリクエストもアクセスログに残り、X-Request-Id が付くこと。
func TestUnauthorizedIsLogged(t *testing.T) {
	var buf bytes.Buffer
	h := newServer(newTestLogger(&buf), token)
	rec := do(t, h, "GET", "/orders/42", "", false)
	if rec.Result().Header.Get("X-Request-Id") == "" {
		t.Errorf("401 response has no X-Request-Id")
	}
	m := requestLog(t, &buf)
	if m == nil {
		t.Fatalf("no access log for rejected request; logs=%s", buf.String())
	}
	if m["status"] != float64(401) {
		t.Errorf("logged status = %v, want 401", m["status"])
	}
}

// B2: 認証に失敗したら、本文に注文データが出ないこと。
func TestUnauthorizedDoesNotLeak(t *testing.T) {
	var buf bytes.Buffer
	h := newServer(newTestLogger(&buf), token)
	rec := do(t, h, "GET", "/orders/42", "", false)
	if rec.Code != http.StatusUnauthorized {
		t.Errorf("code = %d, want 401", rec.Code)
	}
	if strings.Contains(rec.Body.String(), "ACME") {
		t.Errorf("order data leaked to unauthenticated client: %q", rec.Body.String())
	}
}

// B3: WriteHeader を呼ばずに Write したハンドラは 200 としてログに残ること。
func TestImplicit200IsLogged(t *testing.T) {
	var buf bytes.Buffer
	h := newServer(newTestLogger(&buf), token)
	do(t, h, "GET", "/orders/42", "", true)
	m := requestLog(t, &buf)
	if m == nil {
		t.Fatalf("no access log; logs=%s", buf.String())
	}
	if m["status"] != float64(200) {
		t.Errorf("logged status = %v, want 200", m["status"])
	}
}

// B4: SSE の1件目が、ハンドラが終わる前に届くこと（本物のサーバーで測る）。
func TestSSEFirstEventIsNotBuffered(t *testing.T) {
	var buf bytes.Buffer
	srv := httptest.NewServer(newServer(newTestLogger(&buf), token))
	defer srv.Close()

	req, _ := http.NewRequest("GET", srv.URL+"/events", nil)
	req.Header.Set("Authorization", "Bearer "+token)
	start := time.Now()
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		t.Fatal(err)
	}
	defer resp.Body.Close()
	line, err := bufio.NewReader(resp.Body).ReadString('\n')
	if err != nil {
		t.Fatal(err)
	}
	first := time.Since(start)
	t.Logf("first event %q after %v", strings.TrimSpace(line), first.Round(time.Millisecond))
	if first > 80*time.Millisecond {
		t.Errorf("first event arrived after %v; flush did not reach the connection", first.Round(time.Millisecond))
	}
}

// B5: POST の本文がハンドラまで届き、ログに大きさが残ること。
func TestPostBodyReachesHandler(t *testing.T) {
	var buf bytes.Buffer
	h := newServer(newTestLogger(&buf), token)
	body := `{"customer":"ACME","items":[{"sku":"A-1","qty":2}]}`
	rec := do(t, h, "POST", "/orders", body, true)
	if rec.Code != http.StatusCreated {
		t.Errorf("code = %d, body = %q, want 201", rec.Code, rec.Body.String())
	}
	m := requestLog(t, &buf)
	if m == nil {
		t.Fatalf("no access log; logs=%s", buf.String())
	}
	if m["req_bytes"] != float64(len(body)) {
		t.Errorf("logged req_bytes = %v, want %d", m["req_bytes"], len(body))
	}
}

// 順序の設計: panic したリクエストも 500 としてアクセスログに1行残ること。
func TestPanicIsLoggedAs500(t *testing.T) {
	var buf bytes.Buffer
	h := newServer(newTestLogger(&buf), token)
	rec := do(t, h, "GET", "/panic", "", true)
	if rec.Code != http.StatusInternalServerError {
		t.Errorf("code = %d, want 500", rec.Code)
	}
	m := requestLog(t, &buf)
	if m == nil {
		t.Fatalf("no access log for panicking request; logs=%s", buf.String())
	}
	if m["status"] != float64(500) {
		t.Errorf("logged status = %v, want 500", m["status"])
	}
}

testutil_test.go

📋 コピーpackage main

import (
	"bytes"
	"log/slog"
)

func newTestLogger(buf *bytes.Buffer) *slog.Logger {
	return slog.New(slog.NewJSONHandler(buf, nil))
}

💡 ヒント（クリックで開く）

📋 コピー// 1. 末尾から被せる
for i := len(mws) - 1; i >= 0; i-- { h = mws[i](h) }

// 2. http.Error の後に return

// 3. Write で status が 0 なら 200 にする。WriteHeader は最初の1回だけ記録する

// 4. func (s *statusRecorder) Unwrap() http.ResponseWriter { return s.ResponseWriter }

// 5. 読んだ量を数えるだけの io.ReadCloser を作り、浅いコピーした Request に付けて渡す
r2 := r.WithContext(r.Context())
r2.Body = &countingBody{ReadCloser: r.Body}

// 課題4
if v == http.ErrAbortHandler { panic(v) }

✅ 模範解答

📋 コピー// 注文 API のミドルウェア群（修正版）。
// 外側から RequestID → Logging → Recover → RequireAuth → mux の順に通す。
package main

import (
	"context"
	"crypto/rand"
	"encoding/hex"
	"fmt"
	"io"
	"log/slog"
	"net/http"
	"os"
	"time"
)

type Middleware func(http.Handler) http.Handler

// Chain は mws を「先に書いたものが外側」になるように h に被せる。
// 内側から被せるので、後ろから回す（chi の chain() と同じ向き）。
func Chain(h http.Handler, mws ...Middleware) http.Handler {
	for i := len(mws) - 1; i >= 0; i-- {
		h = mws[i](h)
	}
	return h
}

type ctxKey struct{}

func RequestID(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		id := r.Header.Get("X-Request-Id")
		if id == "" {
			b := make([]byte, 8)
			_, _ = rand.Read(b)
			id = hex.EncodeToString(b)
		}
		w.Header().Set("X-Request-Id", id)
		next.ServeHTTP(w, r.WithContext(context.WithValue(r.Context(), ctxKey{}, id)))
	})
}

func requestIDFrom(ctx context.Context) string {
	id, _ := ctx.Value(ctxKey{}).(string)
	return id
}

// statusRecorder はステータスコードと書いたバイト数を記録する。
type statusRecorder struct {
	http.ResponseWriter
	status int
	bytes  int
}

func (s *statusRecorder) WriteHeader(code int) {
	if s.status == 0 { // 2回目以降は net/http も無視する（superfluous）。記録も最初の値に揃える
		s.status = code
	}
	s.ResponseWriter.WriteHeader(code)
}

func (s *statusRecorder) Write(b []byte) (int, error) {
	if s.status == 0 { // WriteHeader を呼ばずに Write すると net/http は 200 を送る
		s.status = http.StatusOK
	}
	n, err := s.ResponseWriter.Write(b)
	s.bytes += n
	return n, err
}

// Unwrap は http.ResponseController に「元の ResponseWriter」を教える。
// これが無いと Flush・SetWriteDeadline・Hijack が ErrNotSupported になる。
func (s *statusRecorder) Unwrap() http.ResponseWriter { return s.ResponseWriter }

// countingBody はハンドラが読んだバイト数だけを数える。溜め込まない。
type countingBody struct {
	io.ReadCloser
	n int64
}

func (c *countingBody) Read(p []byte) (int, error) {
	n, err := c.ReadCloser.Read(p)
	c.n += int64(n)
	return n, err
}

func Logging(logger *slog.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			start := time.Now()
			rec := &statusRecorder{ResponseWriter: w}
			body := &countingBody{ReadCloser: r.Body}
			r2 := r.WithContext(r.Context()) // 浅いコピー。受け取った *Request は書き換えない（http.Handler の doc）
			r2.Body = body
			defer func() { // 内側で panic が抜けてきても1行は残す
				logger.Info("request",
					"id", requestIDFrom(r.Context()),
					"method", r.Method,
					"path", r.URL.Path,
					"status", rec.status,
					"bytes", rec.bytes,
					"req_bytes", body.n,
					"dur_ms", time.Since(start).Milliseconds(),
				)
			}()
			next.ServeHTTP(rec, r2)
		})
	}
}

func Recover(logger *slog.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			defer func() {
				if v := recover(); v != nil {
					if v == http.ErrAbortHandler {
						panic(v) // 接続を切るための意図的な panic。握りつぶさない
					}
					logger.Error("panic", "id", requestIDFrom(r.Context()), "value", fmt.Sprint(v))
					http.Error(w, "internal error", http.StatusInternalServerError)
				}
			}()
			next.ServeHTTP(w, r)
		})
	}
}

func RequireAuth(token string) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			if r.Header.Get("Authorization") != "Bearer "+token {
				http.Error(w, "unauthorized", http.StatusUnauthorized)
				return
			}
			next.ServeHTTP(w, r)
		})
	}
}

func newMux() *http.ServeMux {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /orders/{id}", func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		fmt.Fprintf(w, `{"id":%q,"customer":"ACME","total":12800}`, r.PathValue("id"))
	})
	mux.HandleFunc("POST /orders", func(w http.ResponseWriter, r *http.Request) {
		b, err := io.ReadAll(r.Body)
		if err != nil || len(b) == 0 {
			http.Error(w, "empty body", http.StatusBadRequest)
			return
		}
		w.WriteHeader(http.StatusCreated)
		fmt.Fprintf(w, `{"received_bytes":%d}`, len(b))
	})
	mux.HandleFunc("GET /events", func(w http.ResponseWriter, r *http.Request) {
		rc := http.NewResponseController(w)
		w.Header().Set("Content-Type", "text/event-stream")
		for i := range 3 {
			fmt.Fprintf(w, "data: tick %d\n\n", i)
			if err := rc.Flush(); err != nil && i == 0 {
				// 止めはしない。届くのが最後にまとめてになるだけ
				slog.Warn("flush failed", "err", err)
			}
			time.Sleep(100 * time.Millisecond)
		}
	})
	mux.HandleFunc("GET /panic", func(w http.ResponseWriter, r *http.Request) {
		var m map[string]int
		m["boom"]++ // nil map への書き込み
	})
	return mux
}

func newServer(logger *slog.Logger, token string) http.Handler {
	return Chain(newMux(),
		RequestID,
		Logging(logger),
		Recover(logger),
		RequireAuth(token),
	)
}

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info("listening", "addr", ":8080")
	if err := http.ListenAndServe(":8080", newServer(logger, "secret-token")); err != nil {
		logger.Error("server", "err", err)
	}
}

📋 コピー--- FAIL: TestUnauthorizedIsLogged (0.00s)
    main_test.go:60: 401 response has no X-Request-Id
    main_test.go:67: logged status = 0, want 401
--- FAIL: TestUnauthorizedDoesNotLeak (0.00s)
    main_test.go:80: order data leaked to unauthenticated client: "unauthorized\n{\"id\":\"42\",\"customer\":\"ACME\",\"total\":12800}"
--- FAIL: TestImplicit200IsLogged (0.00s)
    main_test.go:94: logged status = 0, want 200
--- FAIL: TestSSEFirstEventIsNotBuffered (0.30s)
    main_test.go:117: first event "data: tick 0" after 303ms
    main_test.go:119: first event arrived after 303ms; flush did not reach the connection
--- FAIL: TestPostBodyReachesHandler (0.00s)
    main_test.go:130: code = 400, body = "empty body\n", want 201
--- FAIL: TestPanicIsLoggedAs500 (0.00s)
    main_test.go:151: no access log for panicking request; logs={"time":"...","level":"ERROR","msg":"panic","id":"","value":"assignment to entry in nil map"}

📋 コピー--- PASS: TestUnauthorizedIsLogged (0.00s)
--- PASS: TestUnauthorizedDoesNotLeak (0.00s)
--- PASS: TestImplicit200IsLogged (0.00s)
    main_test.go:117: first event "data: tick 0" after 0s
--- PASS: TestSSEFirstEventIsNotBuffered (0.30s)
--- PASS: TestPostBodyReachesHandler (0.00s)
--- PASS: TestPanicIsLoggedAs500 (0.00s)
ok  	day056	0.885s

📋 コピーLogging→Recover（採用）: client=500 logged_status=500
Recover→Logging（逆）:   client=500 logged_status=0
w.(http.Flusher) ok=false / ResponseController.Flush err=<nil>
ReadAll して戻す: TotalAlloc/req = 22.4 MiB     （本文 10 MiB × 5 回の平均）
数えるだけ:       TotalAlloc/req = 0.0 MiB
握りつぶす:                 status=200 body="partial...internal error\n" readErr=<nil>
投げ直す（修正版 Recover）: status=200 body="partial..." readErr=unexpected EOF

📋 コピーpackage main

import (
	"bytes"
	"io"
	"net/http"
	"net/http/httptest"
	"runtime"
	"strings"
	"testing"
)

// M1: Recover を Logging の外に出すと、panic のログに何が残るか
func TestMeasureOrderSwap(t *testing.T) {
	for _, tc := range []struct {
		name string
		mws  func(*bytes.Buffer) []Middleware
	}{
		{"Logging→Recover（採用）", func(b *bytes.Buffer) []Middleware {
			l := newTestLogger(b)
			return []Middleware{RequestID, Logging(l), Recover(l), RequireAuth(token)}
		}},
		{"Recover→Logging（逆）", func(b *bytes.Buffer) []Middleware {
			l := newTestLogger(b)
			return []Middleware{RequestID, Recover(l), Logging(l), RequireAuth(token)}
		}},
	} {
		var buf bytes.Buffer
		h := Chain(newMux(), tc.mws(&buf)...)
		rec := do(t, h, "GET", "/panic", "", true)
		m := requestLog(t, &buf)
		t.Logf("%s: client=%d logged_status=%v", tc.name, rec.Code, m["status"])
	}
}

// M2: 型アサーションで Flusher を探す古いコードには Unwrap が効かない
func TestMeasureTypeAssertion(t *testing.T) {
	rec := &statusRecorder{ResponseWriter: httptest.NewRecorder()}
	_, ok := any(rec).(http.Flusher)
	err := http.NewResponseController(rec).Flush()
	t.Logf("w.(http.Flusher) ok=%v / ResponseController.Flush err=%v", ok, err)
}

// M3: 本文 10 MiB を「ReadAll して戻す」方式と「数えるだけ」方式でのヒープ割当
func TestMeasureBodyAlloc(t *testing.T) {
	const size = 10 << 20
	payload := strings.Repeat("x", size)
	sink := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { io.Copy(io.Discard, r.Body) })
	readAllRestore := func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			b, _ := io.ReadAll(r.Body)
			r.Body = io.NopCloser(bytes.NewReader(b))
			next.ServeHTTP(w, r)
		})
	}
	counting := func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			r.Body = &countingBody{ReadCloser: r.Body}
			next.ServeHTTP(w, r)
		})
	}
	for _, tc := range []struct {
		name string
		mw   Middleware
	}{{"ReadAll して戻す", readAllRestore}, {"数えるだけ", counting}} {
		h := tc.mw(sink)
		var before, after runtime.MemStats
		runtime.GC()
		runtime.ReadMemStats(&before)
		for range 5 {
			req := httptest.NewRequest("POST", "/", strings.NewReader(payload))
			h.ServeHTTP(httptest.NewRecorder(), req)
		}
		runtime.ReadMemStats(&after)
		t.Logf("%s: TotalAlloc/req = %.1f MiB", tc.name, float64(after.TotalAlloc-before.TotalAlloc)/5/(1<<20))
	}
}

📋 コピーpackage main

import (
	"bytes"
	"fmt"
	"io"
	"net/http"
	"net/http/httptest"
	"testing"
)

// M4: http.ErrAbortHandler を握りつぶす Recover と、投げ直す Recover の違い（本物のサーバー）
func TestMeasureAbort(t *testing.T) {
	abort := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "text/plain")
		w.WriteHeader(200)
		fmt.Fprint(w, "partial...")
		w.(http.Flusher).Flush()
		panic(http.ErrAbortHandler) // 途中で失敗したので、正常終了に見せたくない
	})
	swallow := func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			defer func() {
				if v := recover(); v != nil {
					http.Error(w, "internal error", 500)
				}
			}()
			next.ServeHTTP(w, r)
		})
	}
	var buf bytes.Buffer
	for _, tc := range []struct {
		name string
		h    http.Handler
	}{{"握りつぶす", swallow(abort)}, {"投げ直す（修正版 Recover）", Recover(newTestLogger(&buf))(abort)}} {
		srv := httptest.NewServer(tc.h)
		srv.Config.ErrorLog = nil
		resp, err := http.Get(srv.URL)
		if err != nil {
			t.Logf("%s: Get err=%v", tc.name, err)
			srv.Close()
			continue
		}
		b, rerr := io.ReadAll(resp.Body)
		resp.Body.Close()
		t.Logf("%s: status=%d body=%q readErr=%v", tc.name, resp.StatusCode, b, rerr)
		srv.Close()
	}
}

🪜 Step-by-Step 解説

Step 1: B1 — Chain の向きは「内側から被せる」

h = m(h) は、今の h の外側に m を被せる操作です。前から回すと、最初に被せた RequestID が一番内側になります。「並べた順＝外から内」にしたいなら、内側（末尾）から被せます。chi・alice も同じ向きです。

レビューでの見つけ方: Chain の単体テストを書くより、「401 はアクセスログに出るか」「panic ログに request ID が付くか」のように、順序の結果として観測できる性質をテストにする方が、順序を入れ替える将来の変更にも効きます。

Step 2: B2 — http.Error は return しない

http.Error はヘッダと本文を書くだけの関数です。後ろの next.ServeHTTP はそのまま走り、mux は同じ w に注文 JSON を書き足します。net/http は2回目の WriteHeader を無視する（ログに superfluous と出す）だけで、本文の追記は止めません。結果が "unauthorized\n{\"id\":\"42\",...}" です。

Node.js の Express で同じことをすると ERR_HTTP_HEADERS_SENT で例外になりますが、Go ではエラーにならずに漏れます。認証ミドルウェアには、この形のテスト（401 の本文に機密が含まれない）を必ず1本置きます。

Step 3: B3 — 「WriteHeader を呼ばない」は 200 の意味

http.ResponseWriter の doc の通り、WriteHeader を呼ばずに Write すると net/http は WriteHeader(http.StatusOK) を暗黙に呼びます。ラッパーは本物と同じ規則で記録する必要があります。2回目の WriteHeader も本物は無視するので、記録も最初の値だけにします（直さなくてもテストは通りますが、ログと実際の応答がずれる原因になります）。

Step 4: B4 — 包むなら Unwrap を付ける

statusRecorder が埋め込んでいるのは http.ResponseWriter というインターフェース型なので、昇格するのは Header・Write・WriteHeader の3つだけです。中身が Flusher でも、外から見えなくなります。Unwrap() を足すと、http.NewResponseController(w) が中身まで辿って Flush を呼べます。同じ仕組みで SetWriteDeadline（ハンドラごとの書き込み期限）や Hijack（WebSocket）も通ります。

Step 5: B5 — 本文は「読んで戻す」より「数える」

直し方は3つ考えられます。

受け取った *Request の Body を直接書き換えず、r.WithContext(r.Context()) で浅いコピーを作って差し替えるのは、http.Handler の doc の "handlers should not modify the provided Request" に従うためです。

🧭 設計思想・なぜこう書くのか

Go が標準ライブラリにミドルウェアの枠組みを入れていないのは、http.Handler という1メソッドのインターフェースと関数だけで合成できるからです。その代わり、枠組みが守ってくれない約束（順序・return・ResponseWriter の能力・Request を書き換えない）は、書く人が守る必要があります。今日の5つは、いずれも「コンパイルは通り、go vet も何も言わない」種類のバグでした（go vet ./... はバグ入りの版でも無出力。実測）。

迷った点と採らなかった案

🌐 他言語との比較

🏭 実務での使いどころ

• アクセスログの status が 0 の行を見たら: まず B3（暗黙の 200 を記録していない）か、panic がログのミドルウェアを素通りしている（課題3）を疑います。どちらも本番のダッシュボードで「0 の割合」として観測できます
• SSE や gRPC-Web・大きなファイルのダウンロードが「最後にまとめて届く」: 途中のミドルウェアの ResponseWriter ラッパーが Flush を落としています（B4）。gzip ミドルウェアや計測用ミドルウェアを足した直後に起きやすい
• WebSocket の Upgrade が feature not supported / http: Hijack is not supported: 同じ原因で Hijacker が消えています
• 認証ミドルウェアのレビュー: http.Error の直後に return があるかは、目視よりテスト（401 の本文に機密が無い）で守ります
• OpenTelemetry の otelhttp など既製の計測ミドルウェアも同じ問題に向き合っており、otelhttp は httpsnoop を使って ResponseWriter を包んでいます（go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp の依存。テーマ18「構造化ログ・Observability」で扱います）

⚠️ よくある誤解・ミス

🚧 扱わなかった範囲

• ヘッダ送信済みかどうかを Recover が知る方法: 課題4で見たとおり、ヘッダを送った後の panic では 500 に差し替えられません。chi の Recoverer も区別せず WriteHeader(500) しています。送信済みなら何もせず接続を切る（panic(http.ErrAbortHandler) に変換する）設計もありえますが、今日は測っていません
• タイムアウト（http.TimeoutHandler）: 応答をバッファに溜めるため Flush できません。ミドルウェアでの期限の設計は、テーマ19「graceful shutdown」と合わせて扱います
• トークン比較の定数時間化: RequireAuth の != は比較時間から一致した長さが漏れうるので、実務では crypto/subtle.ConstantTimeCompare を使います。今日の5つには数えていません
• gzip などの本文を書き換えるミドルウェア: Content-Length の扱いと Flush の伝播がさらに難しくなります
• HTTP/2 での Hijack: HTTP/2 では Hijack はそもそも使えません（今日の SSE テストは HTTP/1.1 の httptest サーバーで測っています）

🚀 次のステップ

• 発展: 最外に置く Recover を1つ足し、Logging 自体が panic したとき（ロガーのハンドラが panic するなど）にもサーバーが接続を切らずに 500 を返すようにしてみましょう。そのとき、アクセスログが二重に出ないことをテストで確かめます
• 次回予告: 同じテーマ15のまま、切り口を「設計」に替えます。ルートごとに違うミドルウェア（/admin だけ認証を変える、/healthz はログを出さない）を、Go 1.22 以降の http.ServeMux のパターンだけで組む設計と、chi の r.Group で組む設計を比べます

🎯 自己評価

自分の回答

気づき・メモ