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>

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})

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")
 	}
 }