net/http: direct server logs to test output in tests

Set a logger in newClientServerTest that directs the server
log output to the testing.T's log, so log output gets properly
associated with the test that caused it.

Change-Id: I13686ca35c3e21adae16b2fc37ce36daea3df9d5
Reviewed-on: https://go-review.googlesource.com/c/go/+/452075
Run-TryBot: Damien Neil <dneil@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>

diff --git a/src/net/http/clientserver_test.go b/src/net/http/clientserver_test.go
index 87e34cef8555840525aed8ca17d163d4b987e51e..da5671d9b9f7ea55c4dd892a25ab0ea3f5e489b8 100644 (file)
--- a/src/net/http/clientserver_test.go
+++ b/src/net/http/clientserver_test.go
@@ -170,6 +170,10 @@ func newClientServerTest(t testing.TB, mode testMode, h Handler, opts ...any) *c
                }
        }
 
+       if cst.ts.Config.ErrorLog == nil {
+               cst.ts.Config.ErrorLog = log.New(testLogWriter{t}, "", 0)
+       }
+
        switch mode {
        case http1Mode:
                cst.ts.Start()
@@ -198,6 +202,15 @@ func newClientServerTest(t testing.TB, mode testMode, h Handler, opts ...any) *c
        return cst
 }
 
+type testLogWriter struct {
+       t testing.TB
+}
+
+func (w testLogWriter) Write(b []byte) (int, error) {
+       w.t.Logf("server log: %v", strings.TrimSpace(string(b)))
+       return len(b), nil
+}
+
 // Testing the newClientServerTest helper itself.
 func TestNewClientServerTest(t *testing.T) {
        run(t, testNewClientServerTest, []testMode{http1Mode, https1Mode, http2Mode})

diff --git a/src/net/http/serve_test.go b/src/net/http/serve_test.go
index 8adccc82a6d66447f546909a5fb16a80a4f93951..ecf681d79ca6667136c40a71438b2628f7507779 100644 (file)
--- a/src/net/http/serve_test.go
+++ b/src/net/http/serve_test.go
@@ -2777,29 +2777,19 @@ func TestHandlerPanicWithHijack(t *testing.T) {
        // Only testing HTTP/1, and our http2 server doesn't support hijacking.
        run(t, func(t *testing.T, mode testMode) {
                testHandlerPanic(t, true, mode, nil, "intentional death for testing")
-       }, testNotParallel, []testMode{http1Mode})
+       }, []testMode{http1Mode})
 }
 
 func testHandlerPanic(t *testing.T, withHijack bool, mode testMode, wrapper func(Handler) Handler, panicValue any) {
-       // Unlike the other tests that set the log output to io.Discard
-       // to quiet the output, this test uses a pipe. The pipe serves three
-       // purposes:
+       // Direct log output to a pipe.
        //
-       //   1) The log.Print from the http server (generated by the caught
-       //      panic) will go to the pipe instead of stderr, making the
-       //      output quiet.
+       // We read from the pipe to verify that the handler actually caught the panic
+       // and logged something.
        //
-       //   2) We read from the pipe to verify that the handler
-       //      actually caught the panic and logged something.
-       //
-       //   3) The blocking Read call prevents this TestHandlerPanic
-       //      function from exiting before the HTTP server handler
-       //      finishes crashing. If this text function exited too
-       //      early (and its defer log.SetOutput(os.Stderr) ran),
-       //      then the crash output could spill into the next test.
+       // We use a pipe rather than a buffer, because when testing connection hijacking
+       // server shutdown doesn't wait for the hijacking handler to return, so the
+       // log may occur after the server has shut down.
        pr, pw := io.Pipe()
-       log.SetOutput(pw)
-       defer log.SetOutput(os.Stderr)
        defer pw.Close()
 
        var handler Handler = HandlerFunc(func(w ResponseWriter, r *Request) {
@@ -2815,11 +2805,11 @@ func testHandlerPanic(t *testing.T, withHijack bool, mode testMode, wrapper func
        if wrapper != nil {
                handler = wrapper(handler)
        }
-       cst := newClientServerTest(t, mode, handler)
+       cst := newClientServerTest(t, mode, handler, func(ts *httptest.Server) {
+               ts.Config.ErrorLog = log.New(pw, "", 0)
+       })
 
-       // Do a blocking read on the log output pipe so its logging
-       // doesn't bleed into the next test. But wait only 5 seconds
-       // for it.
+       // Do a blocking read on the log output pipe.
        done := make(chan bool, 1)
        go func() {
                buf := make([]byte, 4<<10)
@@ -2840,10 +2830,16 @@ func testHandlerPanic(t *testing.T, withHijack bool, mode testMode, wrapper func
                return
        }
 
+       var delay time.Duration
+       if deadline, ok := t.Deadline(); ok {
+               delay = time.Until(deadline)
+       } else {
+               delay = 5 * time.Second
+       }
        select {
        case <-done:
                return
-       case <-time.After(5 * time.Second):
+       case <-time.After(delay):
                t.Fatal("expected server handler to log an error")
        }
 }