[インデックス 11276] ファイルの概要

このコミットは、Go言語の標準ライブラリである net/http パッケージにおける、HTTPハンドラがパニック（panic）を起こした際のログ出力と接続クローズの順序に関する修正です。具体的には、ハンドラ内で発生したパニックのログを、関連するHTTP接続が閉じられる前に確実に出力するように変更されています。これにより、デバッグ時により多くの情報が得られるようになります。

コミット

commit bb7eca177a8b23f85a143f987b02c377a78cefe7
Author: Brad Fitzpatrick <bradfitz@golang.org>
Date:   Thu Jan 19 14:19:59 2012 -0800

    net/http: log handler panic before closing HTTP connection
    
    Fix originally from rogpeppe in 5414048 but was rolled
    back due to test breakage.
    
    This CL makes the test more robust to order of operations.
    
    Fixes #2480 again.
    
    R=golang-dev, gri
    CC=golang-dev
    https://golang.org/cl/5536072

GitHub上でのコミットページへのリンク

https://github.com/golang/go/commit/bb7eca177a8b23f85a143f987b02c377a78cefe7

元コミット内容

このコミットは、以前 rogpeppe によってコミットハッシュ 5414048 で提案された修正の再適用です。元の修正は、テストの破損が原因でロールバックされました。この再適用では、テストの堅牢性を高めることで、以前の問題を回避しています。

Goの net/http パッケージは、Webサーバーを構築するための基盤を提供します。HTTPハンドラは、クライアントからのリクエストを処理するアプリケーションロジックをカプセル化します。Goでは、予期せぬエラーやプログラミング上のバグが発生した場合に panic を使用することがあります。panic が発生すると、通常のプログラムフローは中断され、defer ステートメントが実行された後、プログラムはクラッシュするか、recover によって捕捉されない限り終了します。

このコミットの背景にある問題は、HTTPハンドラ内で panic が発生した際に、そのパニック情報がログに出力される前に、関連するHTTP接続が閉じられてしまう可能性があったことです。接続が閉じられてしまうと、ログ出力が完了する前にリソースが解放され、結果としてパニックのスタックトレースや詳細情報が完全にログに記録されない、あるいは全く記録されないという問題が発生していました。これは、サーバーのデバッグや問題診断を困難にする要因となります。

Fixes #2480 という記述から、この問題はGoのIssueトラッカーで報告されていたことがわかります。元のIssue #2480は、HTTPハンドラがパニックを起こした際に、そのパニックが適切にログに記録されないという問題に関するものでした。このコミットは、その問題を再度、より堅牢な方法で解決しようとするものです。

前提知識の解説

Go言語の `panic` と `recover`

Go言語には、例外処理のメカニズムとして panic と recover があります。

panic: プログラムの実行を即座に停止させ、現在のゴルーチンをスタックアンワインド（関数の呼び出しスタックを逆順に辿る）させます。これは、回復不能なエラーやプログラミング上のバグを示すために使用されます。
defer: defer ステートメントは、それが含まれる関数がリターンする直前（panic が発生した場合も含む）に実行される関数をスケジュールします。これは、リソースの解放（ファイルのクローズ、ロックの解除など）によく使用されます。
recover: panic が発生したゴルーチン内で defer された関数の中から recover を呼び出すと、その panic を捕捉し、プログラムのクラッシュを防ぎ、通常の実行フローを再開させることができます。

このコミットでは、net/http の内部で defer と recover を利用して、HTTPハンドラ内で発生した panic を捕捉し、その情報をログに出力しています。

`net/http` パッケージの `Server` と `Handler`

net/http: Go言語でHTTPクライアントとサーバーを実装するための標準パッケージです。
http.Handler インターフェース: ServeHTTP(ResponseWriter, *Request) メソッドを持つインターフェースです。このインターフェースを実装する型がHTTPリクエストを処理するハンドラとなります。
http.Server: HTTPサーバーの構成と実行を管理する構造体です。クライアントからの接続を受け入れ、リクエストを適切なハンドラにディスパッチします。

HTTPサーバーは、各クライアント接続に対して新しいゴルーチンを起動し、そのゴルーチン内でリクエストの読み取り、ハンドラの呼び出し、レスポンスの書き込みを行います。ハンドラ内で panic が発生した場合、そのゴルーチン内で panic が伝播し、最終的にはサーバーの接続処理ロジック内で捕捉される必要があります。

`io.Pipe` とテストにおけるログの捕捉

io.Pipe は、Go言語でパイプを実装するための構造体です。io.PipeReader と io.PipeWriter のペアで構成され、PipeWriter に書き込まれたデータは PipeReader から読み取ることができます。これは、テストにおいて、通常は標準出力や標準エラーに出力されるログメッセージをプログラム的に捕捉し、その内容を検証するために非常に有用です。

このコミットのテストコードでは、log.SetOutput を使用して、標準ロガーの出力を io.PipeWriter にリダイレクトし、io.PipeReader からログメッセージを読み取ることで、ハンドラがパニックを起こした際に期待されるログメッセージが正しく出力されることを検証しています。

技術的詳細

このコミットの主要な変更点は、net/http/server.go 内の conn.serve() メソッドにおける defer ブロックのロジックです。conn.serve() メソッドは、個々のHTTP接続を処理するゴルーチン内で実行されます。このメソッドの冒頭には defer ステートメントがあり、接続処理中に panic が発生した場合に実行されるクリーンアップロジックを含んでいます。

変更前は、panic が捕捉された際に、まず c.rwc.Close() （HTTP接続のクローズ）が試みられ、その後にパニック情報（スタックトレースなど）が log.Print を使って出力されていました。

// 変更前
func (c *conn) serve() {
    defer func() {
        if err := recover(); err != nil {
            if c.rwc != nil { // may be nil if connection hijacked
                c.rwc.Close() // ここで接続が閉じられる
            }

            var buf bytes.Buffer
            fmt.Fprintf(&buf, "http: panic serving %v: %v\\n", c.remoteAddr, err)
            buf.Write(debug.Stack())
            log.Print(buf.String()) // その後ログ出力
        }
    }()
    // ...
}

この順序の問題は、c.rwc.Close() が実行されると、基となるネットワーク接続が閉じられ、それによって log.Print がログメッセージを書き込もうとした際に、関連するファイルディスクリプタやバッファが既に無効になっている可能性があったことです。特に、ログの出力先がネットワーク接続に依存している場合や、ログシステム自体が接続クローズの影響を受けるような状況では、ログメッセージが失われる可能性がありました。

このコミットでは、c.rwc.Close() の呼び出しを log.Print の後、つまりパニック情報がログに書き込まれた後に移動させています。

// 変更後
func (c *conn) serve() {
    defer func() {
        if err := recover(); err != nil {
            var buf bytes.Buffer
            fmt.Fprintf(&buf, "http: panic serving %v: %v\\n", c.remoteAddr, err)
            buf.Write(debug.Stack())
            log.Print(buf.String()) // まずログ出力

            if c.rwc != nil { // may be nil if connection hijacked
                c.rwc.Close() // その後接続が閉じられる
            }
        }
    }()
    // ...
}

この変更により、パニックが発生した場合でも、スタックトレースを含む詳細なログメッセージが確実にログシステムに渡され、記録されることが保証されます。その後、安全にHTTP接続が閉じられます。

また、src/pkg/net/http/serve_test.go のテストコードも変更されています。以前のテストでは、Get(ts.URL) の呼び出しとログの読み取りゴルーチンの開始順序が、テストの安定性に影響を与えていました。特に、ログを読み取るゴルーチンがログが書き込まれる前に終了してしまう可能性がありました。

新しいテストコードでは、ログを読み取るゴルーチンを先に起動し、そのゴルーチンがログの読み取りを完了するまで待機するチャネル (done) を使用しています。さらに、done チャネルをバッファ付きチャネル (make(chan bool, 1)) に変更し、pr.Read(buf) のバッファサイズを 1024 から 4<<10 (4KB) に増やすことで、より多くのログデータを一度に読み取れるようにし、テストの堅牢性を向上させています。これにより、ログの読み取りがHTTPリクエストの完了とパニックの発生に同期して行われるようになり、テストがより信頼性の高いものになっています。

コアとなるコードの変更箇所

`src/pkg/net/http/server.go`

--- a/src/pkg/net/http/server.go
+++ b/src/pkg/net/http/server.go
@@ -569,14 +569,15 @@ func (c *conn) serve() {
 	\tif err == nil {\n \t\t\treturn\n \t\t}\n-\t\tif c.rwc != nil { // may be nil if connection hijacked\n-\t\t\tc.rwc.Close()\n-\t\t}\n \n \t\tvar buf bytes.Buffer\n \t\tfmt.Fprintf(&buf, \"http: panic serving %v: %v\\n\", c.remoteAddr, err)\n \t\tbuf.Write(debug.Stack())\n \t\tlog.Print(buf.String())\n+\n+\t\tif c.rwc != nil { // may be nil if connection hijacked\n+\t\t\tc.rwc.Close()\n+\t\t}\n \t}()

この差分は、conn.serve() メソッド内の defer 関数ブロックにおける c.rwc.Close() の位置が、log.Print(buf.String()) の呼び出しの後に移動したことを示しています。

`src/pkg/net/http/serve_test.go`

--- a/src/pkg/net/http/serve_test.go
+++ b/src/pkg/net/http/serve_test.go
@@ -904,17 +904,13 @@ func testHandlerPanic(t *testing.T, withHijack bool) {
 \t\tpanic(\"intentional death for testing\")\n \t}))\n \tdefer ts.Close()\n-\t_, err := Get(ts.URL)\n-\tif err == nil {\n-\t\tt.Logf(\"expected an error\")\n-\t}\n \n \t// Do a blocking read on the log output pipe so its logging\n \t// doesn\'t bleed into the next test.  But wait only 5 seconds\n \t// for it.\n-\tdone := make(chan bool)\n+\tdone := make(chan bool, 1)\n \tgo func() {\n-\t\tbuf := make([]byte, 1024)\n+\t\tbuf := make([]byte, 4<<10)\n \t\t_, err := pr.Read(buf)\n \t\tpr.Close()\n \t\tif err != nil {\n@@ -922,6 +918,12 @@ func testHandlerPanic(t *testing.T, withHijack bool) {\n \t\t}\n \t\tdone <- true\n \t}()\n+\n+\t_, err := Get(ts.URL)\n+\tif err == nil {\n+\t\tt.Logf(\"expected an error\")\n+\t}\n+\n \tselect {\n \tcase <-done:\n \t\treturn

この差分は、テストコードにおける以下の変更を示しています。

Get(ts.URL) の呼び出しが、ログ読み取りゴルーチンの開始後に移動しました。
done チャネルがバッファなし (make(chan bool)) からバッファあり (make(chan bool, 1)) に変更されました。
ログ読み取りバッファのサイズが 1024 バイトから 4<<10 (4096) バイトに増加しました。

コアとなるコードの解説

`src/pkg/net/http/server.go` の変更

conn.serve() メソッドは、HTTPサーバーが個々のクライアント接続を処理する際の中心的なロジックを含んでいます。このメソッドの defer ブロックは、接続処理中に発生する可能性のある panic を捕捉し、適切に処理するためのものです。

変更前は、panic が捕捉された際に、まず c.rwc.Close() が呼び出され、その後でパニック情報がログに出力されていました。c.rwc は ReadWriteCloser インターフェースを実装しており、基となるネットワーク接続を表します。この順序では、接続が閉じられた後にログ出力が試みられるため、ログ出力が失敗する可能性がありました。

変更後は、log.Print(buf.String()) が c.rwc.Close() の前に移動されました。これにより、パニックが発生した場合でも、スタックトレースやエラーメッセージを含む完全なパニック情報が、接続が閉じられる前に確実にログに書き込まれるようになります。これは、サーバーの安定性とデバッグ可能性を向上させる上で非常に重要です。

`src/pkg/net/http/serve_test.go` の変更

このテストファイルは、net/http パッケージのサーバー機能、特にパニック処理の挙動を検証するためのものです。

Get(ts.URL) の移動: 以前のテストでは、HTTPリクエスト (Get(ts.URL)) がログ読み取りゴルーチンを開始する前に実行されていました。これにより、リクエストが完了し、ハンドラがパニックを起こし、ログが書き込まれる前に、ログ読み取りゴルーチンがまだ開始されていない、あるいはログを読み取る準備ができていないという競合状態が発生する可能性がありました。変更後は、ログ読み取りゴルーチンを先に開始し、その後にHTTPリクエストを送信することで、ログが書き込まれる準備が整った状態でパニックが発生するようにしています。
done チャネルのバッファリング: done := make(chan bool) から done := make(chan bool, 1) への変更は、チャネルをバッファなしからバッファあり（容量1）に変更したことを意味します。バッファなしチャネルは、送信側と受信側が同時に準備ができていないとブロックします。この場合、ログ読み取りゴルーチンが done <- true を実行した際に、メインゴルーチンがまだ select { case <-done: ... } に到達していないと、ログ読み取りゴルーチンがブロックされ、テストのタイムアウトを引き起こす可能性がありました。バッファ付きチャネルにすることで、ログ読み取りゴルーチンは done <- true を非ブロッキングで実行でき、メインゴルーチンが後で select に到達した際に値を受け取ることができます。これにより、テストのタイミング依存性が軽減され、より堅牢になります。
ログ読み取りバッファサイズの増加: buf := make([]byte, 1024) から buf := make([]byte, 4<<10) (4KB) への変更は、ログメッセージを読み取るためのバッファサイズを増やしたことを意味します。パニック時のスタックトレースは非常に長くなる可能性があるため、より大きなバッファを用意することで、ログメッセージ全体を一度に読み取り、テストの信頼性を高めています。

これらのテストの変更は、server.go で行われたパニック処理の変更が正しく機能することを、より信頼性の高い方法で検証するために不可欠です。

参考にした情報源リンク

Go言語の panic と recover について:
- A Tour of Go: https://go.dev/tour/moretypes/12
- Effective Go: https://go.dev/doc/effective_go#recover
Go言語の net/http パッケージについて:
- GoDoc: net/http package: https://pkg.go.dev/net/http
Go言語の io.Pipe について:
- GoDoc: io package: https://pkg.go.dev/io#Pipe
Go言語のチャネルについて:
- A Tour of Go: https://go.dev/tour/concurrency/2
- Effective Go: https://go.dev/doc/effective_go#channels

comemo