runtime/race: false negative at tip

[bradfitz]

When running the race detector against x/net/http2 at rev 2fd7f15, Go 1.5.1 on OS X detects this race, but Go tip (rev ab7e82e) does not:

bradfitz@laptop http2$ go version
go version go1.5.1 darwin/amd64
bradfitz@laptop http2$ go test -v -race -run=TestServer_Response_RST_Unblocks_LargeWrite
=== RUN   TestServer_Response_RST_Unblocks_LargeWrite
==================
WARNING: DATA RACE
Read by goroutine 14:
  golang.org/x/net/http2.(*writeScheduler).take()
      /Users/bradfitz/src/golang.org/x/net/http2/writesched.go:123 +0x3af
  golang.org/x/net/http2.(*serverConn).scheduleFrameWrite()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:916 +0x3ab
  golang.org/x/net/http2.(*serverConn).writeFrame()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:802 +0xa2
  golang.org/x/net/http2.(*serverConn).serve()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:674 +0xb90
  golang.org/x/net/http2.(*Server).handleConn()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:282 +0xf93
  golang.org/x/net/http2.ConfigureServer.func1()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:193 +0xc4
  net/http.(*conn).serve()
      /private/var/folders/q8/bf_4b1ts2zj0l7b0p1dv36lr0000gp/T/workdir/go/src/net/http/server.go:1312 +0x9ce

Previous write by goroutine 28:
  golang.org/x/net/http2.(*responseWriterState).writeChunk()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1770 +0x4f4
  golang.org/x/net/http2.(*responseWriter).Flush()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1793 +0x140
  golang.org/x/net/http2.(*responseWriter).handlerDone()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1893 +0xc6
  golang.org/x/net/http2.(*serverConn).runHandler()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1526 +0x94

Goroutine 14 (running) created at:
  net/http.(*Server).Serve()
      /private/var/folders/q8/bf_4b1ts2zj0l7b0p1dv36lr0000gp/T/workdir/go/src/net/http/server.go:1910 +0x464

Goroutine 28 (finished) created at:
  golang.org/x/net/http2.(*serverConn).processHeaderBlockFragment()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1384 +0x6ad
  golang.org/x/net/http2.(*serverConn).processHeaders()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1328 +0x83a
  golang.org/x/net/http2.(*serverConn).processFrame()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:1048 +0x718
  golang.org/x/net/http2.(*serverConn).processFrameFromReader()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:998 +0xb96
  golang.org/x/net/http2.(*serverConn).serve()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:678 +0xd15
  golang.org/x/net/http2.(*Server).handleConn()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:282 +0xf93
  golang.org/x/net/http2.ConfigureServer.func1()
      /Users/bradfitz/src/golang.org/x/net/http2/server.go:193 +0xc4
  net/http.(*conn).serve()
      /private/var/folders/q8/bf_4b1ts2zj0l7b0p1dv36lr0000gp/T/workdir/go/src/net/http/server.go:1312 +0x9ce
==================
--- PASS: TestServer_Response_RST_Unblocks_LargeWrite (0.06s)
PASS
Found 1 data race(s)
exit status 66
FAIL    
golang.org/x/net/http2  2.499s

And the missed detection:

bradfitz@laptop http2$ go version
go version devel +ab7e82e Thu Oct 29 16:25:37 2015 +0000 darwin/amd64
bradfitz@laptop http2$ go test -v -race -run=TestServer_Response_RST_Unblocks_LargeWrite
=== RUN   TestServer_Response_RST_Unblocks_LargeWrite
--- PASS: TestServer_Response_RST_Unblocks_LargeWrite (0.06s)
PASS
ok      golang.org/x/net/http2  2.729s

Even with a large --count= value, in case it was scheduling or something.

[gopherbot]

CL https://golang.org/cl/16490 mentions this issue.

[dvyukov]

What is the revision of golang.org/x/net?

[bradfitz]

See first sentence of bug report.

[dvyukov]

The race is still detectable on tip, it's just detection rate significantly decreased. On 1.5 it is detected in 45 runs out of 100; on tip - in 3 runs out of 100.
On the positive side, detection of some other races should go up :) Race detector is best-effort in nature.

@aclements did something wrt scheduling changed since 1.5?

[aclements]

@dvyukov, GC scheduling behavior has changed a bit, but as far as I'm aware general goroutine scheduling hasn't changed. Would this be difficult to bisect?

[dvyukov]

Run bisect using

(cd src && ./make.bash) 1>/dev/null 2>&1
go test -c -race golang.org/x/net/http2
R=""
for i in {1..30}; do
    GORACE="atexit_sleep_ms=0" ./http2.test -test.run TestServer_Response_RST_Unblocks_LargeWrite 1>/dev/null 2>&1
    if [ $? -ne 0 ]; then
        R=$R"x"
    fi
done
N=${#R} 
if [[ $N -le 10 ]]; then
    echo BAD $N
    exit 1
fi
echo OK $N

Two times it pointed to:

commit a3156aaa121446c4136927f8c2139fefe05ba82c
Author: Brad Fitzpatrick <bradfitz@golang.org>
Date:   Tue Sep 29 14:26:48 2015 -0700

    net/http/httptest: change Server to use http.Server.ConnState for accounting

So, Brad, it was you :)

I guess it is just some parasitic synchronization and we need to bear with it.
Run you tests continuously and if you touch something related to synchronization, run the tests at least a hundred of times (golang.org/x/tools/cmd/stress is helpful here).