Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

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

このコミットは、Go言語の標準ライブラリである net/http パッケージのテストコードにおけるログ出力のノイズを削減し、同時に一部のログ出力が正しく行われていることをテストするための変更です。具体的には、不要な t.Logf の呼び出しを抑制し、log パッケージの出力をキャプチャしてその内容をテストすることで、テストの実行時の出力をよりクリーンに保ちつつ、重要なログメッセージが期待通りに生成されることを保証しています。

コミット

commit 2ccc9a965b11e27f3df843d36ccdecc6efbd1b52
Author: Brad Fitzpatrick <bradfitz@golang.org>
Date:   Thu Dec 26 13:03:30 2013 -0800

    net/http: quiet distracting test spam
    
    Capture log output (and test it while at it),
    and quiet unnecessary t.Logf.
    
    R=golang-codereviews, iant
    CC=golang-codereviews
    https://golang.org/cl/45850043

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

https://github.com/golang/go/commit/2ccc9a965b11e27f3df843d36ccdecc6efbd1b52

元コミット内容

net/http: quiet distracting test spam

Capture log output (and test it while at it),
and quiet unnecessary t.Logf.

変更の背景

Go言語のテストフレームワーク testing パッケージには、テスト中に情報を出力するための t.Logf 関数があります。これはデバッグや情報提供に便利ですが、テストが成功した場合でも常に大量のログが出力されると、テスト結果の確認が困難になったり、CI/CDパイプラインのログが肥大化したりする問題が発生します。

このコミットの背景には、net/http パッケージのテストが生成するログ出力が過剰であり、それが「テストスパム (test spam)」として開発者の注意を散漫にさせていたという問題があります。特に、エラーが発生した場合にのみ意味を持つ情報や、デバッグ目的で一時的に追加された t.Logf がそのまま残っているケースが考えられます。

また、一部のテストでは、特定の条件で log パッケージ（標準ロギングライブラリ）が警告やエラーメッセージを出力することを期待している場合があります。しかし、これらのログが単に標準出力や標準エラー出力に流れるだけでは、そのメッセージが期待通りに出力されたかどうかを自動的に検証することができませんでした。

このコミットは、これらの問題を解決し、テストの出力をよりクリーンで意味のあるものにすることを目的としています。

前提知識の解説

Go言語の testing パッケージ

Go言語のテストは、標準ライブラリの testing パッケージを使用して記述されます。

  • func TestXxx(t *testing.T) の形式でテスト関数を定義します。
  • t *testing.T はテストの状態を管理し、テストの失敗を報告したり、ログを出力したりするためのメソッドを提供します。
  • t.Logf(format string, args ...interface{}): フォーマットされた文字列をテストログに出力します。デフォルトでは、テストが失敗した場合にのみ出力されますが、go test -v オプションを付けると常に表示されます。
  • t.Errorf(format string, args ...interface{}): テストを失敗としてマークし、フォーマットされたエラーメッセージをログに出力します。

Go言語の log パッケージ

log パッケージは、Go言語の標準ロギングライブラリです。

  • log.Printf(format string, args ...interface{}): フォーマットされた文字列をデフォルトのロガーに出力します。
  • log.SetOutput(w io.Writer): ロガーの出力先を設定します。デフォルトでは os.Stderr (標準エラー出力) です。
  • bytes.Buffer: bytes パッケージに含まれる型で、可変長のバイトバッファを実装します。io.Writer インターフェースを満たすため、log.SetOutput の出力先として使用することで、ログ出力をメモリ上にキャプチャすることができます。

net/http パッケージ

net/http パッケージは、HTTPクライアントとサーバーの実装を提供するGo言語の標準ライブラリです。ウェブアプリケーションやAPIの構築に不可欠な機能を提供します。このコミットは、このパッケージのテストコードに焦点を当てています。

技術的詳細

このコミットは、主に以下の3つのアプローチでテストのログ出力を改善しています。

  1. 不要な t.Logf の削除または条件付き化: client_test.go と transport_test.go において、常に実行されていた t.Logf の呼び出しが、特定の失敗条件（例: クッキーの数が一致しない、ゴルーチンの増加が閾値を超える）が満たされた場合にのみ出力されるように変更されました。これにより、テストが成功した場合には余分なログが出力されなくなり、テスト出力がより簡潔になります。

  2. log パッケージ出力のキャプチャとテスト: cookie_test.go では、log パッケージが特定の警告メッセージ（例: 無効なドメイン属性の破棄、無効なバイトの破棄）を出力することを期待するテストケースがあります。これらのテストでは、以下の手順でログ出力をキャプチャし、その内容を検証しています。

    • var logbuf bytes.Buffer: bytes.Buffer 型の変数を宣言し、ログ出力を一時的に格納するためのバッファとして使用します。
    • log.SetOutput(&logbuf): log パッケージの出力先を、デフォルトの os.Stderr から logbuf に一時的にリダイレクトします。これにより、テスト中に log.Printf などで出力されたメッセージは logbuf に書き込まれます。
    • defer log.SetOutput(os.Stderr): defer ステートメントを使用し、テスト関数が終了する際に log パッケージの出力先を元の os.Stderr に戻すように設定します。これは、他のテストに影響を与えないための重要なクリーンアップ処理です。
    • if got, sub := logbuf.String(), "expected substring"; !strings.Contains(got, sub) { ... }: テストの実行後、logbuf.String() でキャプチャされたログの内容を取得し、strings.Contains を使用して期待される警告メッセージのサブストリングが含まれているかを検証します。これにより、特定のログメッセージが正しく出力されたことをテストとして保証できます。

  3. コメントアウトされたテストの削除: client_test.go から TestRedirectCookiesOnRequest 関数が完全に削除されました。このテストは以前からコメントアウトされており、RFC6265 (HTTP State Management Mechanism) に関連するTODOコメントが付いていました。未完成または問題のあるテストを削除することで、コードベースのクリーンアップと、潜在的なノイズ源の排除が行われました。

これらの変更により、テストの実行時の出力が大幅に改善され、開発者はより重要な情報に集中できるようになります。また、ログ出力自体をテストの一部として組み込むことで、ロギングの振る舞いに関する回帰を防ぐことができます。

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

src/pkg/net/http/client_test.go

--- a/src/pkg/net/http/client_test.go
+++ b/src/pkg/net/http/client_test.go
@@ -373,24 +373,6 @@ func (j *TestJar) Cookies(u *url.URL) []*Cookie {
 	return j.perURL[u.Host]
 }
 
-func TestRedirectCookiesOnRequest(t *testing.T) {
-	defer afterTest(t)
-	var ts *httptest.Server
-	ts = httptest.NewServer(echoCookiesRedirectHandler)
-	defer ts.Close()
-	c := &Client{}
-	req, _ := NewRequest("GET", ts.URL, nil)
-	req.AddCookie(expectedCookies[0])
-	// TODO: Uncomment when an implementation of a RFC6265 cookie jar lands.
-	_ = c
-	// resp, _ := c.Do(req)
-	// matchReturnedCookies(t, expectedCookies, resp.Cookies())
-
-	req, _ = NewRequest("GET", ts.URL, nil)
-	// resp, _ = c.Do(req)
-	// matchReturnedCookies(t, expectedCookies[1:], resp.Cookies())
-}
-
 func TestRedirectCookiesJar(t *testing.T) {
 	defer afterTest(t)
 	var ts *httptest.Server
@@ -410,8 +392,8 @@ func TestRedirectCookiesJar(t *testing.T) {
 }
 
 func matchReturnedCookies(t *testing.T, expected, given []*Cookie) {
-\tt.Logf("Received cookies: %v", given)\n \tif len(given) != len(expected) {\n+\t\tt.Logf("Received cookies: %v", given)\n \t\tt.Errorf("Expected %d cookies, got %d", len(expected), len(given))\n \t}\n \tfor _, ec := range expected {

src/pkg/net/http/cookie_test.go

--- a/src/pkg/net/http/cookie_test.go
+++ b/src/pkg/net/http/cookie_test.go
@@ -5,9 +5,13 @@
 package http
 
 import (
+\t"bytes"
 	"encoding/json"
 	"fmt"
+\t"log"
+\t"os"
 	"reflect"
+\t"strings"
 	"testing"
 	"time"
 )
@@ -51,12 +55,20 @@ var writeSetCookiesTests = []struct {
 }\n \n func TestWriteSetCookies(t *testing.T) {\n+\tdefer log.SetOutput(os.Stderr)\n+\tvar logbuf bytes.Buffer\n+\tlog.SetOutput(&logbuf)\n+\n \tfor i, tt := range writeSetCookiesTests {\n \t\tif g, e := tt.Cookie.String(), tt.Raw; g != e {\n \t\t\tt.Errorf("Test %d, expecting:\\n%s\\nGot:\\n%s\\n", i, e, g)\n \t\t\tcontinue\n \t\t}\n \t}\n+\n+\tif got, sub := logbuf.String(), "dropping domain attribute"; !strings.Contains(got, sub) {\n+\t\tt.Errorf("Expected substring %q in log output. Got:\\n%s", sub, got)\n+\t}\n }\n \n type headerOnlyResponseWriter Header\n@@ -244,6 +256,10 @@ func TestReadCookies(t *testing.T) {\n }\n \n func TestCookieSanitizeValue(t *testing.T) {\n+\tdefer log.SetOutput(os.Stderr)\n+\tvar logbuf bytes.Buffer\n+\tlog.SetOutput(&logbuf)\n+\n \ttests := []struct {\n \t\tin, want string\n \t}{\n@@ -257,9 +273,17 @@ func TestCookieSanitizeValue(t *testing.T) {\n \t\t\tt.Errorf("sanitizeCookieValue(%q) = %q; want %q", tt.in, got, tt.want)\n \t\t}\n \t}\n+\n+\tif got, sub := logbuf.String(), "dropping invalid bytes"; !strings.Contains(got, sub) {\n+\t\tt.Errorf("Expected substring %q in log output. Got:\\n%s", sub, got)\n+\t}\n }\n \n func TestCookieSanitizePath(t *testing.T) {\n+\tdefer log.SetOutput(os.Stderr)\n+\tvar logbuf bytes.Buffer\n+\tlog.SetOutput(&logbuf)\n+\n \ttests := []struct {\n \t\tin, want string\n \t}{\n@@ -272,4 +296,8 @@ func TestCookieSanitizePath(t *testing.T) {\n \t\t\tt.Errorf("sanitizeCookiePath(%q) = %q; want %q", tt.in, got, tt.want)\n \t\t}\n \t}\n+\n+\tif got, sub := logbuf.String(), "dropping invalid bytes"; !strings.Contains(got, sub) {\n+\t\tt.Errorf("Expected substring %q in log output. Got:\\n%s", sub, got)\n+\t}\n }\n```

### `src/pkg/net/http/transport_test.go`

```diff
--- a/src/pkg/net/http/transport_test.go
+++ b/src/pkg/net/http/transport_test.go
@@ -798,8 +798,8 @@ func TestTransportPersistConnLeak(t *testing.T) {\n \n \t// We expect 0 or 1 extra goroutine, empirically.  Allow up to 5.\n \t// Previously we were leaking one per numReq.\n-\tt.Logf("goroutine growth: %d -> %d -> %d (delta: %d)", n0, nhigh, nfinal, growth)\n \tif int(growth) > 5 {\n+\t\tt.Logf("goroutine growth: %d -> %d -> %d (delta: %d)", n0, nhigh, nfinal, growth)\n \t\tt.Error("too many new goroutines")\n \t}\n }\n```

## コアとなるコードの解説

### `client_test.go` の変更点

-   `TestRedirectCookiesOnRequest` 関数が完全に削除されました。このテストは以前からコメントアウトされており、機能していなかったため、コードベースから取り除かれました。
-   `matchReturnedCookies` 関数内の `t.Logf` の呼び出しが、`if len(given) != len(expected)` ブロックの内側に移動されました。これにより、クッキーの数が期待値と異なる場合にのみ「Received cookies: ...」というログが出力されるようになり、テストが成功した場合にはこのログは表示されなくなります。

### `cookie_test.go` の変更点

このファイルでは、`log` パッケージの出力をキャプチャし、その内容をテストするメカニズムが導入されました。
-   `import` 文に `bytes`, `log`, `os`, `strings` が追加されました。
-   `TestWriteSetCookies`, `TestCookieSanitizeValue`, `TestCookieSanitizePath` の各テスト関数内で、以下のパターンが適用されています。
    -   `defer log.SetOutput(os.Stderr)`: テスト関数が終了する際に、`log` パッケージの出力先を標準エラー出力 (`os.Stderr`) に戻すための `defer` ステートメントです。これにより、このテストによる `log` 出力先のリダイレクトが他のテストに影響を与えないようにします。
    -   `var logbuf bytes.Buffer`: `bytes.Buffer` 型の変数 `logbuf` が宣言され、`log` パッケージの出力を一時的に保持するためのメモリバッファとして機能します。
    -   `log.SetOutput(&logbuf)`: `log` パッケージの出力先が `logbuf` に設定されます。これにより、テスト中に `log` パッケージを通じて出力されるすべてのメッセージが `logbuf` に書き込まれます。
    -   `if got, sub := logbuf.String(), "expected substring"; !strings.Contains(got, sub) { ... }`: テストのロジックが実行された後、`logbuf.String()` を呼び出してキャプチャされたログの内容を取得します。そして、`strings.Contains` を使用して、特定の警告メッセージ（例: "dropping domain attribute" や "dropping invalid bytes"）がログに含まれているかを検証します。これにより、特定の条件で `log` パッケージが期待通りの警告を出力していることをテストとして確認できます。

### `transport_test.go` の変更点

-   `TestTransportPersistConnLeak` 関数内の `t.Logf` の呼び出しが、`if int(growth) > 5` ブロックの内側に移動されました。これにより、ゴルーチンの増加が許容範囲を超えた場合にのみ「goroutine growth: ...」というログが出力されるようになり、テストが成功した場合にはこのログは表示されなくなります。

これらの変更は、テストの実行時の出力をより意味のあるものにし、デバッグや問題の特定を容易にすることを目的としています。特に `cookie_test.go` での `log` 出力キャプチャは、ロギングの振る舞い自体をテスト対象とすることで、コードの堅牢性を高める良い例です。

## 関連リンク

-   Go言語 `testing` パッケージのドキュメント: [https://pkg.go.dev/testing](https://pkg.go.dev/testing)
-   Go言語 `log` パッケージのドキュメント: [https://pkg.go.dev/log](https://pkg.go.dev/log)
-   Go言語 `bytes` パッケージのドキュメント: [https://pkg.go.dev/bytes](https://pkg.go.dev/bytes)
-   Go言語 `net/http` パッケージのドキュメント: [https://pkg.go.dev/net/http](https://pkg.go.dev/net/http)

## 参考にした情報源リンク

-   Go Code Review Comments - Test: [https://go.dev/wiki/CodeReviewComments#test](https://go.dev/wiki/CodeReviewComments#test)
-   Go Wiki - Testing: [https://go.dev/wiki/Testing](https://go.dev/wiki/Testing)
-   Go: How to capture log output in tests: [https://stackoverflow.com/questions/10473800/how-to-capture-go-logging-output-in-a-test](https://stackoverflow.com/questions/10473800/how-to-capture-go-logging-output-in-a-test) (一般的なログキャプチャのテクニックに関するStack Overflowの議論)
-   RFC 6265 - HTTP State Management Mechanism: [https://datatracker.ietf.org/doc/html/rfc6265](https://datatracker.ietf.org/doc/html/rfc6265) (`TestRedirectCookiesOnRequest` のTODOコメントで言及されていたRFC)