net/http: fix ordering & data race in TestTransportEventTrace_h2

Ordering fix: this CL swaps the order of the log write and the channel close
in WroteRequest. I could reproduce the bug by putting a sleep between the two
when the channel close was first. It needs to happen after the log.

Data race: use the log buffer's mutex when reading too. Not really
important once the ordering fix above is fixed (since nobody is
concurrently writing anymore), but for consistency.

Fixes #16414

Change-Id: If6657884e67be90b4455c8f5a6f7bc6981999ee4
Reviewed-on: https://go-review.googlesource.com/28078
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>

diff --git a/src/net/http/transport_test.go b/src/net/http/transport_test.go
index daf943e250dbbdbbc3a98a420434476b032be15f..fe915e840203af797b94f978041084c5febc9376 100644 (file)
--- a/src/net/http/transport_test.go
+++ b/src/net/http/transport_test.go
@@ -3257,7 +3257,7 @@ func testTransportEventTrace(t *testing.T, h2 bool, noHooks bool) {
 
        cst.tr.ExpectContinueTimeout = 1 * time.Second
 
-       var mu sync.Mutex
+       var mu sync.Mutex // guards buf
        var buf bytes.Buffer
        logf := func(format string, args ...interface{}) {
                mu.Lock()
@@ -3299,8 +3299,8 @@ func testTransportEventTrace(t *testing.T, h2 bool, noHooks bool) {
                Wait100Continue: func() { logf("Wait100Continue") },
                Got100Continue:  func() { logf("Got100Continue") },
                WroteRequest: func(e httptrace.WroteRequestInfo) {
-                       close(gotWroteReqEvent)
                        logf("WroteRequest: %+v", e)
+                       close(gotWroteReqEvent)
                },
        }
        if noHooks {
@@ -3332,7 +3332,10 @@ func testTransportEventTrace(t *testing.T, h2 bool, noHooks bool) {
                return
        }
 
+       mu.Lock()
        got := buf.String()
+       mu.Unlock()
+
        wantOnce := func(sub string) {
                if strings.Count(got, sub) != 1 {
                        t.Errorf("expected substring %q exactly once in output.", sub)
@@ -3371,7 +3374,7 @@ func TestTransportEventTraceRealDNS(t *testing.T) {
        defer tr.CloseIdleConnections()
        c := &Client{Transport: tr}
 
-       var mu sync.Mutex
+       var mu sync.Mutex // guards buf
        var buf bytes.Buffer
        logf := func(format string, args ...interface{}) {
                mu.Lock()
@@ -3395,7 +3398,10 @@ func TestTransportEventTraceRealDNS(t *testing.T) {
                t.Fatal("expected error during DNS lookup")
        }
 
+       mu.Lock()
        got := buf.String()
+       mu.Unlock()
+
        wantSub := func(sub string) {
                if !strings.Contains(got, sub) {
                        t.Errorf("expected substring %q in output.", sub)