Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime/race: false negative at tip #13097

Closed
bradfitz opened this issue Oct 29, 2015 · 6 comments
Closed

runtime/race: false negative at tip #13097

bradfitz opened this issue Oct 29, 2015 · 6 comments
Labels
FrozenDueToAge
Milestone
Go1.6

Comments

@bradfitz
Copy link
Contributor

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.
@bradfitz bradfitz added this to the Go1.6 milestone Oct 29, 2015
@gopherbot
Copy link

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

bradfitz added a commit to golang/net that referenced this issue Oct 30, 2015
@bradfitz
http2: fix Server race with ResponseWriter.curWrite re-use
c95266f 
Kill off that field and simplify the code. Also update some docs.

Thanks to Totoro W for the diagnosis in https://golang.org/cl/16465

Sadly this race was never detected due to golang/go#13097

Fixes golang/go#13089

Change-Id: Ia5400ea6733c7824e872affc3c6720bd436911fe
Reviewed-on: https://go-review.googlesource.com/16490
Reviewed-by: Blake Mizerany <blake.mizerany@gmail.com>
@dvyukov
Copy link
Member

dvyukov commented Oct 30, 2015

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

@bradfitz
Copy link
Contributor Author

See first sentence of bug report.

@dvyukov
Copy link
Member

dvyukov commented Nov 4, 2015

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
Copy link
Member

@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
Copy link
Member

dvyukov commented Nov 4, 2015

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

@dvyukov dvyukov closed this as completed Nov 4, 2015
@golang golang locked and limited conversation to collaborators Nov 4, 2016
@rsc rsc unassigned dvyukov Jun 23, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.6
Development

No branches or pull requests
4 participants
@bradfitz @dvyukov @aclements @gopherbot