Skip to content

runtime/race: bogus race reports #15739

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.

Sign up for GitHub

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
Closed
mikioh opened this issue May 19, 2016 · 8 comments
Closed

runtime/race: bogus race reports #15739

mikioh opened this issue May 19, 2016 · 8 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. RaceDetector Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone
Go1.7

Comments

@mikioh
Copy link
Contributor

mikioh commented May 19, 2016

See https://build.golang.org/log/ec042c758132274722706baf832f2570629dd322

BenchmarkClientServerParallelTLS64-4            ==================
WARNING: DATA RACE
Read at 0x00c4202bcd00 by goroutine 161:
  net/http.(*Transport).getConn()
      /tmp/workdir/go/src/net/http/transport.go:871 +0x648
  net/http.(*Transport).RoundTrip()
      /tmp/workdir/go/src/net/http/transport.go:372 +0x4a7
  net/http.send()
      /tmp/workdir/go/src/net/http/client.go:256 +0x2e6
  net/http.(*Client).send()
      /tmp/workdir/go/src/net/http/client.go:146 +0x1b7
  net/http.(*Client).doFollowingRedirects()
      /tmp/workdir/go/src/net/http/client.go:528 +0x3a5
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:418 +0xd0
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

Previous write at 0x00c4202bcd00 by goroutine 23:
  net/http.NewRequest()
      /tmp/workdir/go/src/net/http/request.go:694 +0x27a
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:414 +0x63
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

Goroutine 161 (running) created at:
  testing.(*B).RunParallel()
      /tmp/workdir/go/src/testing/benchmark.go:599 +0x270
  net/http_test.benchmarkClientServerParallel()
      /tmp/workdir/go/src/net/http/serve_test.go:4237 +0x165
  net/http_test.BenchmarkClientServerParallelTLS64()
      /tmp/workdir/go/src/net/http/serve_test.go:4196 +0x3c
  testing.(*B).runN()
      /tmp/workdir/go/src/testing/benchmark.go:139 +0xec
  testing.(*B).launch()
      /tmp/workdir/go/src/testing/benchmark.go:277 +0x1a2

Goroutine 23 (running) created at:
  testing.(*B).RunParallel()
      /tmp/workdir/go/src/testing/benchmark.go:599 +0x270
  net/http_test.benchmarkClientServerParallel()
      /tmp/workdir/go/src/net/http/serve_test.go:4237 +0x165
  net/http_test.BenchmarkClientServerParallelTLS64()
      /tmp/workdir/go/src/net/http/serve_test.go:4196 +0x3c
  testing.(*B).runN()
      /tmp/workdir/go/src/testing/benchmark.go:139 +0xec
  testing.(*B).launch()
      /tmp/workdir/go/src/testing/benchmark.go:277 +0x1a2
==================
==================
WARNING: DATA RACE
Read at 0x00c4202bcd10 by goroutine 161:
  net/http.(*Transport).getConn()
      /tmp/workdir/go/src/net/http/transport.go:874 +0x673
  net/http.(*Transport).RoundTrip()
      /tmp/workdir/go/src/net/http/transport.go:372 +0x4a7
  net/http.send()
      /tmp/workdir/go/src/net/http/client.go:256 +0x2e6
  net/http.(*Client).send()
      /tmp/workdir/go/src/net/http/client.go:146 +0x1b7
  net/http.(*Client).doFollowingRedirects()
      /tmp/workdir/go/src/net/http/client.go:528 +0x3a5
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:418 +0xd0
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

Previous write at 0x00c4202bcd10 by goroutine 23:
  net/http.NewRequest()
      /tmp/workdir/go/src/net/http/request.go:694 +0x27a
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:414 +0x63
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

Goroutine 161 (running) created at:
  testing.(*B).RunParallel()
      /tmp/workdir/go/src/testing/benchmark.go:599 +0x270
  net/http_test.benchmarkClientServerParallel()
      /tmp/workdir/go/src/net/http/serve_test.go:4237 +0x165
  net/http_test.BenchmarkClientServerParallelTLS64()
      /tmp/workdir/go/src/net/http/serve_test.go:4196 +0x3c
  testing.(*B).runN()
      /tmp/workdir/go/src/testing/benchmark.go:139 +0xec
  testing.(*B).launch()
      /tmp/workdir/go/src/testing/benchmark.go:277 +0x1a2

Goroutine 23 (running) created at:
  testing.(*B).RunParallel()
      /tmp/workdir/go/src/testing/benchmark.go:599 +0x270
  net/http_test.benchmarkClientServerParallel()
      /tmp/workdir/go/src/net/http/serve_test.go:4237 +0x165
  net/http_test.BenchmarkClientServerParallelTLS64()
      /tmp/workdir/go/src/net/http/serve_test.go:4196 +0x3c
  testing.(*B).runN()
      /tmp/workdir/go/src/testing/benchmark.go:139 +0xec
  testing.(*B).launch()
      /tmp/workdir/go/src/testing/benchmark.go:277 +0x1a2
==================
@mikioh mikioh added this to the Go1.7 milestone May 19, 2016
@mikioh mikioh changed the title net/http: data race in BenchmarkClientServerParallelTLS64 net/http: data race in BenchmarkClientServerParallel{4,TLS64} May 19, 2016
@mikioh
Copy link
Contributor Author

mikioh commented May 19, 2016 •
edited
Loading

On freebsd-amd64-race builder: https://build.golang.org/log/74ead1f381092682cd2985b9c91ccf448568f60c

@bradfitz
Copy link
Contributor

Those first two stacks make no sense to me:

BenchmarkClientServerParallelTLS64-4            ==================
WARNING: DATA RACE
Read at 0x00c4202bcd00 by goroutine 161:
  net/http.(*Transport).getConn()
      /tmp/workdir/go/src/net/http/transport.go:871 +0x648
  net/http.(*Transport).RoundTrip()
      /tmp/workdir/go/src/net/http/transport.go:372 +0x4a7
  net/http.send()
      /tmp/workdir/go/src/net/http/client.go:256 +0x2e6
  net/http.(*Client).send()
      /tmp/workdir/go/src/net/http/client.go:146 +0x1b7
  net/http.(*Client).doFollowingRedirects()
      /tmp/workdir/go/src/net/http/client.go:528 +0x3a5
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:418 +0xd0
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

Previous write at 0x00c4202bcd00 by goroutine 23:
  net/http.NewRequest()
      /tmp/workdir/go/src/net/http/request.go:694 +0x27a
  net/http.(*Client).Get()
      /tmp/workdir/go/src/net/http/client.go:414 +0x63
  net/http_test.benchmarkClientServerParallel.func2()
      /tmp/workdir/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /tmp/workdir/go/src/testing/benchmark.go:598 +0x150

I'm not sure how to debug this. @dvyukov? Is this correct?

@bradfitz bradfitz added RaceReport RaceDetector Testing An issue that has been verified to require only test changes, not just a test failure. labels May 19, 2016
@bradfitz
Copy link
Contributor

I got another bogus one,
https://storage.googleapis.com/go-build-log/f48ca822/linux-amd64-race_04ff3748.log

Here's why it's bogus:

The race says:

Previous write at 0x00c42054ce20 by goroutine 235:
  net/http.readRequest()
      /tmp/workdir/go/src/net/http/request.go:827 +0x402
  net/http.(*conn).readRequest()
      /tmp/workdir/go/src/net/http/server.go:765 +0x233
  net/http.(*conn).serve()
      /tmp/workdir/go/src/net/http/server.go:1508 +0x3ff

But here's the code, with line 827 at the bottom highlighted:

func readRequest(b *bufio.Reader, deleteHostHeader bool) (req *Request, err error) {
        tp := newTextprotoReader(b)
        req = new(Request)

        // First line: GET /index.html HTTP/1.0                                                                                                     
        var s string
        if s, err = tp.ReadLine(); err != nil {
                return nil, err
        }
        defer func() {
                putTextprotoReader(tp)
                if err == io.EOF {
                        err = io.ErrUnexpectedEOF
                }
        }()

        var ok bool
        req.Method, req.RequestURI, req.Proto, ok = parseRequestLine(s)
        if !ok {
                return nil, &badStringError{"malformed HTTP request", s}
        }
        rawurl := req.RequestURI
        if req.ProtoMajor, req.ProtoMinor, ok = ParseHTTPVersion(req.Proto); !ok {
                return nil, &badStringError{"malformed HTTP version", req.Proto}
        }

        // CONNECT requests are used two different ways, and neither uses a full URL:                                                               
        // The standard use is to tunnel HTTPS through an HTTP proxy.                                                                               
        // It looks like "CONNECT www.google.com:443 HTTP/1.1", and the parameter is                                                                
        // just the authority section of a URL. This information should go in req.URL.Host.                                                         
        //                                                                                                                                          
        // The net/rpc package also uses CONNECT, but there the parameter is a path                                                                 
        // that starts with a slash. It can be parsed with the regular URL parser,                                                                  
        // and the path will end up in req.URL.Path, where it needs to be in order for                                                              
        // RPC to work.                                                                                                                             
        justAuthority := req.Method == "CONNECT" && !strings.HasPrefix(rawurl, "/")
        if justAuthority {
                rawurl = "http://" + rawurl
        }

        if req.URL, err = url.ParseRequestURI(rawurl); err != nil {   // <----- LINE 827
                return nil, err
        }

That is all in a single goroutine, and it creates the memory (on the second line of the function), before assigning to it.

It can't race with anything yet, because that memory hasn't even escaped.

@dvyukov, up to you to debug.

@bradfitz bradfitz changed the title net/http: data race in BenchmarkClientServerParallel{4,TLS64} runtime/race: bogus race reports May 20, 2016
@bradfitz bradfitz mentioned this issue May 20, 2016
Closed
@quentinmit quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 26, 2016
@rsc
Copy link
Contributor

rsc commented May 27, 2016

@aclements, did this start at the same time as #15747 (with Keith's leak fix)?

@aclements
Copy link
Member

@rsc, hard to say (and hard to grep for). I only see two on the dashboard since the beginning of the year:

2016-05-18T20:44:00-075880a/linux-amd64-race
2016-05-19T03:51:11-255e206/freebsd-amd64-race

@dvyukov
Copy link
Member

dvyukov commented May 29, 2016

Here:
https://storage.googleapis.com/go-build-log/f48ca822/linux-amd64-race_04ff3748.log
the benchmark itself failed with:

--- BENCH: BenchmarkClientServerParallelTLS64-4
    serve_test.go:4237: Get: Get /: http: Request.RequestURI can't be set in client requests.

right after race reports on URI object. That's concerning. It may be a bug affecting non-race build. Do we still have any unfixed memory corruptions?

@dvyukov
Copy link
Member

dvyukov commented May 29, 2016

I've tried to reproduce it on
commit 2499683
Date: Sat May 28 02:33:23 2016 -0600
for several hours with no success.

Then I checked out
commit 075880a
Date: Wed May 18 13:28:48 2016 -0700
(revision on which a buildbot failed). And got 4 crashes in 15 minutes. Two are similar data races. But two are paging faults.

I think this is a bug unrelated to race mode which was fixed recently.

WARNING: DATA RACE
Read at 0x00c4209613c0 by goroutine 489:
  net/http.(*Client).doFollowingRedirects()
      /home/dvyukov/src/go/src/net/http/client.go:440 +0x8c
  net/http.(*Client).Get()
      /home/dvyukov/src/go/src/net/http/client.go:418 +0xd0
  net/http_test.benchmarkClientServerParallel.func2()
      /home/dvyukov/src/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()
      /home/dvyukov/src/go/src/testing/benchmark.go:598 +0x150

Previous write at 0x00c4209613c0 by goroutine 665:
  net/http.NewRequest()
      /home/dvyukov/src/go/src/net/http/request.go:694 +0x27a
  net/http.(*Client).Get()
      /home/dvyukov/src/go/src/net/http/client.go:414 +0x63
  net/http_test.benchmarkClientServerParallel.func2()
      /home/dvyukov/src/go/src/net/http/serve_test.go:4221 +0x243
  testing.(*B).RunParallel.func1()

fatal error: fault
[signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x40a7e4]

goroutine 5750 [running]:
runtime.throw(0x9a8de6, 0x5)
    /home/dvyukov/src/go/src/runtime/panic.go:566 +0x8b fp=0xc421799630 sp=0xc421799618
runtime.sigpanic()
    /home/dvyukov/src/go/src/runtime/sigpanic_unix.go:27 +0x27e fp=0xc421799680 sp=0xc421799630
runtime.mapiternext(0xc4217999a8)
    /home/dvyukov/src/go/src/runtime/hashmap.go:731 +0x174 fp=0xc421799728 sp=0xc421799680
runtime.mapiterinit(0x986c80, 0xc420d74810, 0xc4217999a8)
    /home/dvyukov/src/go/src/runtime/hashmap.go:679 +0x185 fp=0xc421799770 sp=0xc421799728
net/http.(*Transport).RoundTrip(0xc4216f83c0, 0xc420413ef0, 0xc4216f83c0, 0x0, 0x0)
    /home/dvyukov/src/go/src/net/http/transport.go:327 +0xbe2 fp=0xc421799a10 sp=0xc421799770

@mikioh
Copy link
Contributor Author

mikioh commented Jun 2, 2016

I think this is a bug unrelated to race mode which was fixed recently.

Likely, perhaps around liveliness check and/or consumer stack handling, not sure. Closing as the original reporter. I've checked go1.7beta1-race on freebsd-vm too and didn't see any race report.

@mikioh mikioh closed this as completed Jun 2, 2016
@golang golang locked and limited conversation to collaborators Jun 2, 2017
@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 NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. RaceDetector Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Milestone
Go1.7
Development

No branches or pull requests
7 participants
@bradfitz @mikioh @rsc @quentinmit @dvyukov @aclements @gopherbot