Day 064 — 2026-10-04 | ミドルウェア設計パターン: 「panic を拾う」はずの Recover が拾えていない——補助関数の recover・送信後の 500・goroutine の panic・数えられない切断の 5 つのバグを 7 本のテストで直す

2026-10-04 🟡 上級者 / Phase 3 デバッグ・コードレビュー ミドルウェア設計パターン
フェーズ: 上級者 (Phase 3) | 問題タイプ: デバッグ・コードレビュー | テーマ: ミドルウェア設計パターン Day 063 の「扱わなかった範囲」に残した panic と集計の続き。Day 056・060 で済ませた「Recover の置き順」「ErrAbortHandler を握りつぶさない」は今日は正しい状態で渡す(同じ論点を繰り返さない)。直近 3 日が設計→実装→概念理解だったので、今日はデバッグ。

📚 背景知識

Go のハンドラが panic したとき、何が起きるかは誰が拾うかで決まります。

拾う人クライアントに見えるものサーバーのログ根拠
誰も拾わない(net/http 任せ)500 ではなく切断(EOF)http: panic serving ... とスタックnet/http/server.go 1936〜1940 行(Go 1.27.1)。R7 で実測
回復ミドルウェア(Recover)500 と本文Recover が書くもの今日の題材
goroutine の中の panicプロセスごと落ちる(全リクエストが巻き添え)panic: ... と終了コード 2R5 で実測(バグ版の子プロセスが exit status 2)

Recover を書くとき、言語仕様と net/http の約束が 4 つ効きます。どれも黙って壊れる種類です。

  1. recover は「defer された関数」が直接呼んだときだけ効く。Go 仕様(doc/go_spec.html 7953 行): "recover was not called directly by a deferred function" のときは nil を返す。defer func() { helper() }() の中の helper で呼んでも拾えない
  2. ステータスと本文の一部を送った後では 500 は送れない。WriteHeader は 2 回目が無視される(Day 063 の R5)。送信後に http.Error を呼ぶと、200 の本文の後ろに internal error が足されて「正常に終わった壊れた応答」になる。正しくは panic(http.ErrAbortHandler) で接続を切り、クライアントに不完全だと分かる形(chunked の途中切れ = unexpected EOF)で伝える
  3. goroutine の panic は、その goroutine の中でしか拾えない。ミドルウェアの defer はリクエストを処理している goroutine にしか効かない
  4. panic の値をそのままクライアントに返さない。DB ドライバのエラー文は DB のユーザー名・製品名を含む。CWE-209(Generation of Error Message Containing Sensitive Information)に当たる。詳細はサーバーのログへ、クライアントへは定型文

迷った他案と採らなかった理由

論点採った案採らなかった案と理由前提が変わったら
送信後の panicpanic(http.ErrAbortHandler) で切る何もしない(そのまま return): net/http は応答を正常終了させ、chunked の終端まで送る。クライアントは "partial" を完全な 200 として受け取る(実測: io.ReadAll のエラーが nil)。切ったほうが「壊れた」と分かるHTTP/2 では接続ではなくストリームの RST になる(server.go 83〜90 行の doc)。今回 HTTP/2 は測っていない
切断の数え方Observe が defer で数え、next が戻らなければ StatusAborted(= 0)Observe の中でも recover して数える: 数えた後に panic を止めてしまい、net/http が接続を切らない(M7 で R3・R6 が落ちる)。再 panic するなら成立するが、Recover と同じ判断が 2 か所に散る本物の Prometheus 等でラベルを決めるなら status="aborted" のような文字列。今日は Key.Status int に合わせて 0 にした
goroutine の panicGo(logger, f) という起動関数で必ず包むgo f() を書かせない lint: 標準では無い。golangci-lint 等の設定は今回調べていない仕事が多いなら errgroup(panic は拾わない。ドキュメントで要確認)や worker pool に寄せる
500 の本文http.StatusText(500) の定型文リクエスト ID だけ返す: 運用上は便利(ログと突き合わせられる)。今日は ID の受け渡し(Day 058)を混ぜないために見送ったRequestID があるなら本文かヘッダに ID を載せる

参照日 2026-10-04。一次資料は手元の Go 1.27.1(go version go1.27.1 darwin/arm64)のソース: net/http/server.go(83〜90・1905〜1909・1936〜1940 行)、doc/go_spec.html 7953 行、runtime/panic.go 779〜784 行(PanicNilError)、doc/godebug.md 75〜78 行(panicnil)。

世界の実物との位置づけ

  • 回復ミドルウェアの実物: go-chi/chi の middleware.Recoverer(Day 060 で recoverer.go:26 の ErrAbortHandler 判定を確認済み)。「送信済みかどうか」を見て 500 を諦める処理があるかは今回読んでいない(手元知識では無条件に WriteHeader(500) を呼ぶ形だが、未確認)
  • 今日扱う中核概念は 6 つ: recover が効く条件・送信前/後での振る舞いの分岐・ErrAbortHandler による切断・panic の集計(中断の数え方)・goroutine の panic・エラー文の漏えい。扱わないものは末尾に書いた

📝 問題

あなたは注文 API のレビューを頼まれました。作者は「Recover を入れたので panic しても 500 が返るし、Observe で全部数えている」と言っています。ステージングから次の報告が来ています。

  1. 「DB が落ちた日、500 ではなく接続エラーがクライアントに出た。ダッシュボードには 500 が 1 件も無い」
  2. 「エラー画面に pq: password authentication failed for user "app" と出た、と顧客から問い合わせ」
  3. 「大きな JSON の途中で panic したリクエストを、クライアントは正常な 200 として受け取って壊れた JSON をパースしようとした」
  4. 「通知送信の goroutine で nil 参照が起きた瞬間、サーバーごと再起動した」
  5. 「切断されたリクエストがメトリクスに出てこないので、障害の規模が分からない」

mw.go だけを直して、下の 7 本のテストを go test -race -count=1 ./... で全部通してください。main.go(積む順 Observe → Recover → mux を含む)と main_test.go は変えません。

準備

mkdir d64 && cd d64                         # 作業ディレクトリを作って入る
printf 'module d64\n\ngo 1.23\n' > go.mod     # モジュールを作る(Request.Pattern に Go 1.23 以上が必要)
# 下の main.go・mw.go(バグ入り)・main_test.go を保存する
go test -count=1 ./... 2>&1 | grep -c '^--- FAIL'   # バグ入りで落ちるテスト数を数える(6 になる)

ファイル 1: main.go(変えない)

package main

import (
	"errors"
	"fmt"
	"log"
	"net/http"
	"sync"
)

type Middleware func(http.Handler) http.Handler

// Chain は ms[0] が最も外側になるように h を包む。
func Chain(h http.Handler, ms ...Middleware) http.Handler {
	for i := len(ms) - 1; i >= 0; i-- {
		h = ms[i](h)
	}
	return h
}

// StatusAborted は「応答を完了できずに接続を切った」を表す集計用の値(HTTP のステータスではない)。
const StatusAborted = 0

type Key struct {
	Route  string
	Status int
}

type Stats struct {
	mu sync.Mutex
	m  map[Key]int
}

func NewStats() *Stats { return &Stats{m: map[Key]int{}} }

func (s *Stats) add(k Key) {
	s.mu.Lock()
	defer s.mu.Unlock()
	s.m[k]++
}

func (s *Stats) Snapshot() map[Key]int {
	s.mu.Lock()
	defer s.mu.Unlock()
	out := make(map[Key]int, len(s.m))
	for k, v := range s.m {
		out[k] = v
	}
	return out
}

// statusWriter は「最初に確定したステータス」を覚える(Day 063 の模範解答と同じ)。
type statusWriter struct {
	http.ResponseWriter
	status int // 0 = まだ何も送っていない
}

func (w *statusWriter) WriteHeader(code int) {
	if w.status == 0 {
		w.status = code
	}
	w.ResponseWriter.WriteHeader(code)
}

func (w *statusWriter) Write(b []byte) (int, error) {
	if w.status == 0 {
		w.status = http.StatusOK
	}
	return w.ResponseWriter.Write(b)
}

func (w *statusWriter) Unwrap() http.ResponseWriter { return w.ResponseWriter }

func (w *statusWriter) statusOr200() int {
	if w.status == 0 {
		return http.StatusOK
	}
	return w.status
}

var errDB = errors.New(`pq: password authentication failed for user "app"`)

// boom は DB 層のエラーをそのまま panic に載せる(よくある「ありえないはず」の分岐)。
func boom(w http.ResponseWriter, r *http.Request) {
	panic(fmt.Errorf("query users: %w", errDB))
}

// late は 200 と本文の一部を送ってから panic する(ストリーミング・大きな JSON の途中など)。
func late(w http.ResponseWriter, r *http.Request) {
	w.Write([]byte("partial"))
	http.NewResponseController(w).Flush()
	panic("late")
}

func NewApp(s *Stats, logger *log.Logger) http.Handler {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /ok", func(w http.ResponseWriter, r *http.Request) { w.Write([]byte("ok")) })
	mux.HandleFunc("GET /boom", boom)
	mux.HandleFunc("GET /late", late)
	mux.HandleFunc("GET /abort", func(w http.ResponseWriter, r *http.Request) { panic(http.ErrAbortHandler) })
	// 外→内: Observe(数える)→ Recover(500 にする)→ mux。この行は変えない。
	return Chain(mux, s.Observe, Recover(logger))
}

func main() {}

ファイル 2: mw.go(ここを直す。バグ入り)

package main

import (
	"fmt"
	"log"
	"net/http"
	"runtime/debug"
)

// Recover は handler の panic を 500 に変える。
func Recover(logger *log.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			sw := &statusWriter{ResponseWriter: w}
			defer func() { handlePanic(logger, sw, r) }()
			next.ServeHTTP(sw, r)
		})
	}
}

func handlePanic(logger *log.Logger, w *statusWriter, r *http.Request) {
	v := recover()
	if v == nil {
		return
	}
	if v == http.ErrAbortHandler {
		panic(v)
	}
	logger.Printf("panic: %v %s %s\n%s", v, r.Method, r.URL.Path, debug.Stack())
	http.Error(w, fmt.Sprint(v), http.StatusInternalServerError)
}

// Observe は ServeMux の外側で (r.Pattern, ステータス) を数える(Day 063 のまま)。
func (s *Stats) Observe(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		sw := &statusWriter{ResponseWriter: w}
		next.ServeHTTP(sw, r)
		route := r.Pattern
		if route == "" {
			route = "unmatched"
		}
		s.add(Key{route, sw.statusOr200()})
	})
}

// Go はリクエストの外で走らせたい仕事(通知・キャッシュ温め)を goroutine で動かす。
// 返す chan は f が終わったら閉じる。
func Go(logger *log.Logger, f func()) <-chan struct{} {
	done := make(chan struct{})
	go func() {
		f()
		close(done)
	}()
	return done
}

ファイル 3: main_test.go(変えない)

package main

import (
	"bytes"
	"fmt"
	"io"
	"log"
	"net/http"
	"net/http/httptest"
	"os"
	"os/exec"
	"strings"
	"sync"
	"testing"
	"time"
)

type syncBuf struct {
	mu sync.Mutex
	b  bytes.Buffer
}

func (s *syncBuf) Write(p []byte) (int, error) { s.mu.Lock(); defer s.mu.Unlock(); return s.b.Write(p) }
func (s *syncBuf) String() string              { s.mu.Lock(); defer s.mu.Unlock(); return s.b.String() }

// serve は h を 1 回呼び、h から漏れた panic の値も返す(net/http の代わりに受け止める)。
func serve(h http.Handler, path string) (rec *httptest.ResponseRecorder, escaped any) {
	rec = httptest.NewRecorder()
	defer func() { escaped = recover() }()
	h.ServeHTTP(rec, httptest.NewRequest("GET", path, nil))
	return rec, nil
}

func newApp() (http.Handler, *Stats, *syncBuf) {
	s, l := NewStats(), &syncBuf{}
	return NewApp(s, log.New(l, "", 0)), s, l
}

// B1: panic が 500 になり、ログには panic した関数(boom)のスタックが残る
func TestR1_PanicBecomes500WithStack(t *testing.T) {
	app, _, l := newApp()
	rec, escaped := serve(app, "/boom")
	if escaped != nil {
		t.Fatalf("panic escaped Recover: %v", escaped)
	}
	if rec.Code != 500 {
		t.Fatalf("code = %d, want 500", rec.Code)
	}
	if !strings.Contains(l.String(), ".boom(") {
		t.Fatalf("log has no stack frame of boom:\n%s", l.String())
	}
}

// B5: クライアントへ内部のエラー文を返さない(CWE-209)
func TestR2_NoInternalDetailsToClient(t *testing.T) {
	app, _, l := newApp()
	rec, _ := serve(app, "/boom")
	if got := rec.Body.String(); got != "Internal Server Error\n" {
		t.Fatalf("body = %q", got)
	}
	if !strings.Contains(l.String(), "password authentication failed") {
		t.Fatalf("server log must keep the cause:\n%s", l.String())
	}
}

// B3: 200 を送った後の panic は 500 を足さずに接続を切る(ErrAbortHandler で返す)
func TestR3_LatePanicAborts(t *testing.T) {
	app, _, l := newApp()
	rec, escaped := serve(app, "/late")
	if escaped != http.ErrAbortHandler {
		t.Fatalf("escaped = %v, want http.ErrAbortHandler", escaped)
	}
	if got := rec.Body.String(); got != "partial" {
		t.Fatalf("body = %q, want only %q", got, "partial")
	}
	if !strings.Contains(l.String(), "panic: late") {
		t.Fatalf("late panic must still be logged:\n%s", l.String())
	}
}

// B4: panic したリクエストも数える。切った応答は StatusAborted
func TestR4_MetricsCountPanics(t *testing.T) {
	app, s, _ := newApp()
	for _, p := range []string{"/ok", "/boom", "/late", "/abort"} {
		serve(app, p)
	}
	want := map[Key]int{
		{"GET /ok", 200}:              1,
		{"GET /boom", 500}:            1,
		{"GET /late", StatusAborted}:  1,
		{"GET /abort", StatusAborted}: 1,
	}
	if fmt.Sprint(s.Snapshot()) != fmt.Sprint(want) {
		t.Fatalf("got  %v\nwant %v", s.Snapshot(), want)
	}
}

// B2: goroutine の panic でプロセスが落ちない(子プロセスで確かめる)
func TestR5_GoroutinePanicDoesNotKillProcess(t *testing.T) {
	if os.Getenv("D64_CHILD") == "1" {
		done := Go(log.New(os.Stderr, "", 0), func() { panic("bg") })
		select {
		case <-done:
			os.Exit(0)
		case <-time.After(2 * time.Second):
			os.Exit(3)
		}
	}
	cmd := exec.Command(os.Args[0], "-test.run=^TestR5_", "-test.count=1")
	cmd.Env = append(os.Environ(), "D64_CHILD=1")
	out, err := cmd.CombinedOutput()
	if err != nil {
		first, _, _ := strings.Cut(string(out), "\n\n")
		t.Fatalf("child process died: %v\n%s", err, first)
	}
	if !strings.Contains(string(out), "panic in goroutine: bg") {
		t.Fatalf("child did not log the panic:\n%s", out)
	}
}

func newServer(t *testing.T, h http.Handler) (*httptest.Server, *syncBuf) {
	errLog := &syncBuf{}
	srv := httptest.NewUnstartedServer(h)
	srv.Config.ErrorLog = log.New(errLog, "", 0)
	srv.Start()
	t.Cleanup(srv.Close)
	return srv, errLog
}

// 実サーバーで: 500 は本文つきで届き、途中 panic と abort は「切断」として届く
func TestR6_RealServer(t *testing.T) {
	app, _, _ := newApp()
	srv, errLog := newServer(t, app)
	c := srv.Client()

	resp, err := c.Get(srv.URL + "/boom")
	if err != nil || resp.StatusCode != 500 {
		t.Fatalf("/boom: resp=%v err=%v", resp, err)
	}
	resp.Body.Close()

	resp, err = c.Get(srv.URL + "/late")
	if err != nil || resp.StatusCode != 200 {
		t.Fatalf("/late: resp=%v err=%v", resp, err)
	}
	body, err := io.ReadAll(resp.Body)
	resp.Body.Close()
	if err != io.ErrUnexpectedEOF || string(body) != "partial" {
		t.Fatalf("/late: body=%q err=%v, want %q + unexpected EOF", body, err, "partial")
	}

	if _, err := c.Get(srv.URL + "/abort"); err == nil {
		t.Fatal("/abort: want a transport error")
	}

	resp, err = c.Get(srv.URL + "/ok")
	if err != nil || resp.StatusCode != 200 {
		t.Fatalf("/ok after panics: resp=%v err=%v", resp, err)
	}
	resp.Body.Close()

	if strings.Contains(errLog.String(), "panic serving") {
		t.Fatalf("net/http logged a stack; Recover should own logging:\n%s", errLog.String())
	}
}

// 基準線(バグとは無関係。どの実装でも通る): Recover が無いと 500 ではなく切断になる
func TestR7_BaselineWithoutRecover(t *testing.T) {
	mux := http.NewServeMux()
	mux.HandleFunc("GET /boom", boom)
	srv, errLog := newServer(t, mux)
	if _, err := srv.Client().Get(srv.URL + "/boom"); err == nil {
		t.Fatal("want a transport error, not a 500")
	}
	if !strings.Contains(errLog.String(), "panic serving") {
		t.Fatalf("net/http should log the stack:\n%s", errLog.String())
	}
}

受け入れ条件

  • バグ入りの mw.go で 7 本中 6 本が落ちる(R7 は基準線で、どの実装でも通る)
  • 直した後、go test -race -count=1 ./... が全部通る(5 回連続)
  • 報告 1〜5 のそれぞれが、どのバグ(B1〜B5)とどのテストに対応するかを説明できる

💡 ヒント

ヒント1(方向性)

バグ入りで最初に落ちる R1 の失敗文は panic escaped Recover です。Recover は defer しているのに、なぜ panic が外へ漏れるのか。recover を誰が呼んでいるかを見てください。B1 を直すと、残りのバグが見えるようになります(B1 は他を隠す)。

ヒント2(アプローチ)
  • B1: recover() を defer func() { ... }() の本体で直接呼ぶ。あるいは defer handlePanic(...) のように補助関数そのものを defer する
  • B3: statusWriter.status != 0 なら「もう送った」。そのときは panic(http.ErrAbortHandler)
  • B4: Observe の集計を defer に移す。next が戻ったかどうかはフラグで分かる(recover はしない)
  • B2: Go の中の goroutine で defer func() { recover() ... }()。close(done) も defer にする
  • B5: 本文は http.StatusText(500)、詳細はログ
ヒント3(コード骨格)
defer func() {
	v := recover()
	if v == nil {
		return
	}
	if v == http.ErrAbortHandler {
		panic(v)
	}
	logger.Printf(/* 値・メソッド・パス・debug.Stack() */)
	if sw.status != 0 {
		panic(http.ErrAbortHandler)
	}
	http.Error(sw, http.StatusText(500), 500)
}()

✅ 模範解答

直した mw.go(まずバグの一覧を自分で書いてから開く)
package main

import (
	"log"
	"net/http"
	"runtime/debug"
)

// Recover は handler の panic を 500 に変える。
func Recover(logger *log.Logger) Middleware {
	return func(next http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			sw := &statusWriter{ResponseWriter: w}
			// B1: recover は「defer された関数」が直接呼ばないと効かない。
			defer func() {
				v := recover()
				if v == nil {
					return
				}
				if v == http.ErrAbortHandler {
					panic(v) // 意図的な切断。ログも出さずに net/http へ返す
				}
				logger.Printf("panic: %v %s %s\n%s", v, r.Method, r.URL.Path, debug.Stack())
				// B3: もう 200 と本文の一部を送っている。500 は送れないので、接続を切って「壊れた」と伝える
				if sw.status != 0 {
					panic(http.ErrAbortHandler)
				}
				// B5: panic の中身(DB のエラー文)をクライアントへ返さない
				http.Error(sw, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
			}()
			next.ServeHTTP(sw, r)
		})
	}
}

// Observe は ServeMux の外側で (r.Pattern, ステータス) を数える。
// B4: 数えるのを defer に移し、panic で抜けたときは StatusAborted として数える(回収はしない)。
func (s *Stats) Observe(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		sw := &statusWriter{ResponseWriter: w}
		completed := false
		defer func() {
			st := sw.statusOr200()
			if !completed {
				st = StatusAborted
			}
			route := r.Pattern
			if route == "" {
				route = "unmatched"
			}
			s.add(Key{route, st})
		}()
		next.ServeHTTP(sw, r)
		completed = true
	})
}

// Go はリクエストの外で走らせたい仕事(通知・キャッシュ温め)を goroutine で動かす。
// 返す chan は f が終わったら(panic しても)閉じる。
// B2: goroutine の panic はどのミドルウェアにも届かず、プロセスごと落とす。goroutine 自身で拾う。
func Go(logger *log.Logger, f func()) <-chan struct{} {
	done := make(chan struct{})
	go func() {
		defer close(done)
		defer func() {
			if v := recover(); v != nil {
				logger.Printf("panic in goroutine: %v\n%s", v, debug.Stack())
			}
		}()
		f()
	}()
	return done
}

バグと報告・テストの対応

バグ報告症状検出するテスト直し方
B1 recover を補助関数の中で呼ぶ1panic が Recover を素通りし、net/http が切断する。500 が 1 件も無いR1(R2〜R4・R6 も連鎖で落ちる)defer した関数の本体で直接 recover()
B2 goroutine の panic を拾っていない4プロセスが exit status 2 で落ちるR5(子プロセスで確認)Go の goroutine に defer recover、close(done) も defer
B3 送信後も http.Error を呼ぶ3本文が "partialInternal..." のような正常終了の 200R3・R6sw.status != 0 なら panic(http.ErrAbortHandler)
B4 Observe が defer で数えていない1・5panic・切断のリクエストが集計から消えるR4集計を defer に。戻らなければ StatusAborted
B5 panic の値を本文に返す2DB のユーザー名・製品名がクライアントに出るR2本文は定型文、詳細はログ

実測の数字(Go 1.27.1、Apple M1 8 コア)

項目値出所
バグ入りで落ちるテスト7 本中 6 本(R7 だけ通る)実測
直した後-race で 5 回連続 PASS、1 回 約 2.3 秒(うち R5 の子プロセスが約 1.0 秒。-race なしなら 0.01 秒)実測
実サーバーで /late を受けたクライアントstatus=200、Transfer-Encoding: chunked、本文 "partial"、io.ReadAll が unexpected EOF実測(httptest.NewServer)
実サーバーで /abortGet ...: EOF。サーバーへの到達は 1 回(GET でもクライアントが再送しなかった)実測(到達回数を数えるハンドラで確認)
Recover なしで /boom(基準線)クライアントは EOF、サーバーのログに http: panic serving実測(R7)
Observe+Recover の追加コスト(panic なし)82〜110 ns/op、48 B、2 allocs(3 回の幅)実測(go test -bench、ヌル ResponseWriter。素のハンドラは 0.42〜0.48 ns でインライン化されており比較の基準にならない)
panic を 500 に変える 1 回の費用18.0〜20.0 µs/op、3,697 B、13 allocs実測(同上。大半は debug.Stack() と書式化と推定。内訳は測っていない)
panic(nil)go.mod が go 1.23 なら *runtime.PanicNilError として拾われ 500。GODEBUG=panicnil=1 だと recover が nil を返し、200 の空応答・ログなし実測(両方の設定で 1 回ずつ)

🪜 Step-by-Step 解説

Step 1: B1 — recover は「誰が呼ぶか」で効いたり効かなかったりする

defer func() { handlePanic(logger, sw, r) }() // handlePanic の中の recover() は nil を返す

仕様は「defer された関数が直接呼んだとき」だけ recover を有効にします。ここで defer されているのは無名関数で、handlePanic はそこから呼ばれた別の関数です。なので recover() は nil を返し、panic はそのまま上へ抜けます。コンパイラも go vet も何も言いません(今回 go vet ./... は警告 0 件で通った)。

直し方は 2 通りあり、どちらも正しい:

  • defer func() { v := recover(); ... }() — 本体で直接呼ぶ(模範解答)
  • defer handlePanic(logger, sw, r) — 補助関数そのものを defer する。ただし引数は defer の時点で評価される点に注意

Step 2: B1 を直すと B3・B5・B4 が見える

B1 は他のバグを隠すバグです。panic が素通りしている間は、500 の本文(B5)も送信後の扱い(B3)も一度も実行されません。デバッグでは「最初に落ちるテストから直し、直すたびに全体を流し直す」。

Step 3: B3 — 送信した後は「切る」しか正しく伝える方法が無い

/late は "partial" を Flush してから panic します。この時点でクライアントは 200 とヘッダを受け取っています。ここで http.Error を呼ぶと:

  • WriteHeader(500) は無視される(net/http は superfluous として記録する。今回ログの文面は確かめていない)
  • 本文の後ろに 500 の本文が追記される(実測: クライアントが受け取った本文は "partialInternal Server Error\n"、io.ReadAll のエラーは nil)
  • ハンドラが正常に戻るので net/http は chunked の終端を送る → クライアントは完全な 200 だと思う

「何も書かずに return するだけ」も試した。本文は "partial"、エラーは nil で、やはり完全な 200 に見える(実測)。

panic(http.ErrAbortHandler) で net/http に返すと、終端を送らずに接続を閉じます。クライアントは unexpected EOF を受け取り、壊れたと分かる(R6 で実測)。ログはその前に Recover が書いているので、原因は失われません。

Step 4: B4 — 「数える」は defer、「止める」はしない

Observe は next.ServeHTTP の後に数えていたので、/late と /abort(Recover が再 panic するもの)は集計を飛ばして抜けていました。直し方は「数えるのを defer に移す」だけ。ただし Observe で recover() してはいけません(M7: 切断が止まり、/abort が 200 の空応答になる)。

r.Pattern は defer の中でも読めます。ServeMux はハンドラを呼ぶ前に書き込むので、panic で戻ってきても値は残っています(Day 063 の Step 2 の続き)。

Step 5: B2 — goroutine の panic は誰も拾ってくれない

ミドルウェアの defer は、そのリクエストを処理している goroutine のスタックにしかありません。ハンドラの中で go notify() した先で panic すると、Go のランタイムはプロセス全体を終了します(R5: バグ版の子プロセスは exit status 2)。同時に処理していた他のリクエストもすべて落ちます。

対策は「go を直接書かず、必ず拾う起動関数を通す」。close(done) を defer にしておかないと、panic を拾った後も done が閉じず、待つ側が永久に止まります。

Step 6: B5 — エラー文は「誰に」見せるかで分ける

fmt.Sprint(v) の中身は query users: pq: password authentication failed for user "app"。DB の種類(PostgreSQL ドライバ pq の書式)とユーザー名が分かります。クライアントへは Internal Server Error だけ、詳細はサーバーのログへ。ログには原因が残っていることも R2 で確かめています(定型文にしただけで原因まで捨てる、という逆の失敗を防ぐ)。

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

  • Go は「例外で制御しない」。panic は「この goroutine の前提が壊れた」という合図で、ふつうのエラーは error で返す。Recover は「1 リクエストの前提が壊れても、他のリクエストは巻き込まない」ための隔離の境界であって、エラー処理の代わりではない
  • net/http の既定(切断)は保守的。panic したハンドラが何を書いたか分からないので、500 を「勝手に」返さない。Recover を置くのは「まだ何も送っていないなら 500 にしてよい」とアプリが判断できるから。送った後は判断できないので、既定の「切断」に戻す——これが B3 の直し方の理屈
  • goroutine に親子関係が無い。Java の Thread.UncaughtExceptionHandler のような「プロセス全体の受け皿」が Go には無い(go 文で起動した goroutine はどの goroutine の子でもない)。だから拾う責任は起動する側にある

🌐 他言語との比較

言語・FWハンドラの例外バックグラウンドの例外今日との違い
Go net/http既定は切断+ログ。Recover を置けば 500プロセスが落ちるgoroutine ごとに拾う必要がある
Java(Spring MVC)@ExceptionHandler / 既定で 500スレッドが終わるだけ(UncaughtExceptionHandler で受けられる)。プロセスは落ちない手元知識・未確認
Node.js(Express)同期の throw はエラーハンドラへ。Express 4 では async の reject は拾われないunhandledRejection は Node 15 以降、既定でプロセス終了手元知識・未確認。「バックグラウンドで落ちるとプロセスごと」は Go と近い
Python(FastAPI/Starlette)例外ミドルウェアが 500asyncio のタスク例外はログに出るだけ("Task exception was never retrieved")手元知識・未確認

🛠️ 実務での使いどころ

  • Recover は 1 か所(最も内側の集計の内側)。積む順は Day 060 の結論のまま Observe → Recover → mux
  • 送信済み判定はストリーミング応答(SSE・大きな JSON・CSV ダウンロード)で効く。小さな JSON を一括で書く API では、panic は書き込み前に起きることが多い
  • StatusAborted を別の系列で数えると、障害時に「500 が少ないのに顧客は困っている」状況(切断が多い)が見える
  • バックグラウンド処理は Go(logger, f) のような起動関数を 1 つ持ち、レビューで素の go を指摘する
  • 500 の本文は定型文。社内向け API でも同じ(ログ基盤の権限とクライアントの権限は別)

⚠️ よくある誤解・ミス

誤解・ミスなぜ起こるか正しい理解
「Recover を defer しているから拾える」補助関数に切り出すのはふつうのリファクタリングrecover は defer された関数が直接呼ぶときだけ効く(B1)
「panic したら必ず 500 を返す」例外処理の習慣送信済みなら 500 は届かない。切断して不完全だと伝える(B3)
「ミドルウェアがあれば全部拾える」panic は「上に伝わる」というイメージ伝わるのは同じ goroutine のスタックだけ(B2)
「Observe でも recover しておけば安全」二重の防御は安全そう止めると net/http が切断できない(M7)
「エラー文を返すとデバッグが楽」開発中の便利さ本番でも同じ文が出る。CWE-209(B5)
GODEBUG=panicnil=1 を残したままGo 1.20 以前の互換のためpanic(nil) が200 の空応答・ログなしになる(実測)

🧬 変異テスト

直した mw.go を 1 か所ずつ壊し、どのテストが落ちるかを数えた(go test -count=1)。9 通りすべて検出。

壊し方落ちたテスト
M1 recover を補助関数の中で呼ぶ(B1 を戻す)R1・R2・R3・R4・R6
M2 panic の値をそのまま本文に(B5 を戻す)R2
M3 送信済みでも 500 を書く(B3 を戻す)R3・R4・R6
M4 Observe を defer しない(B4 を戻す)R4
M5 goroutine で recover しない(B2 を戻す)R5
M6 ErrAbortHandler を握りつぶすR4・R6
M7 Observe が panic を回収するR3・R6
M8 切断を statusOr200 で数える(StatusAborted にしない)R4
M9 ログにスタックを残さないR1

R7(Recover なしの基準線)は mw.go に依存しないので、変異の検出には使っていない。

🚧 扱わなかった範囲と理由

  • HTTP/2: httptest.NewServer は HTTP/1.1。HTTP/2 では切断ではなくストリームの RST になると doc にあるが、測っていない
  • log/slog での構造化ログ: 今日は log.Logger で済ませた。スタックをどの属性に入れるかは別の判断
  • panic の回数でのアラート・サーキットブレーカー: 集計は作ったが、閾値は決めていない
  • errgroup や worker pool との比較: Go 起動関数だけ。errgroup が panic をどう扱うかは今回調べていない
  • chi の Recoverer の送信済み判定: ソースを読んでいない(上の「世界の実物」参照)
  • debug.Stack() の費用の内訳: 1 回 18〜20 µs のうち何割がスタック取得かは切り分けていない

🚀 次のステップ

  • 発展: Recover にリクエスト ID(Day 058)を渡し、500 の本文と X-Request-Id ヘッダに載せる。ログと突き合わせられるかを R2 と同じ形のテストで確かめる
  • 発展: httptest.NewUnstartedServer で EnableHTTP2 を立て、/late がクライアントにどう見えるか(stream error か)を測る
  • 次回予告: 同テーマ(10/25 まで据え置き)。次は「設計」軸で、ここまでの守り(認証・レート制限・本文上限・タイムアウト・集計・回復)を 1 本の積む順として決め、その順序を壊したときに落ちるテストを 1 表にまとめる

🎯 自己評価

見つけたバグ(ヒントを見る前に何個)

自分の回答

気づき・メモ