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

net/http: race in http2Transport #31192

Closed
vadmeste opened this issue Apr 1, 2019 · 32 comments
Closed

net/http: race in http2Transport #31192

vadmeste opened this issue Apr 1, 2019 · 32 comments

Comments

@vadmeste
Copy link

@vadmeste vadmeste commented Apr 1, 2019

What version of Go are you using (go version)?

go version go1.12.1 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/vadmeste/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/vadmeste/work/gospace"
GOPROXY=""
GORACE=""
GOROOT="/home/vadmeste/work/go"
GOTMPDIR=""
GOTOOLDIR="/home/vadmeste/work/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build457736797=/tmp/go-build -gno-record-gcc-switches"

What did you do?

  1. Generate a self signed certificate:
$ openssl req -newkey rsa:2048 -nodes -keyout private.key -x509 -days 365 -out public.crt -subj "/C=US/ST=state/L=location/O=organization/CN=localhost"
  1. Ask the OS to trust the generated self signed certificate
$ # Tested under Ubuntu
$ sudo cp public.crt /usr/local/share/ca-certificates/
$ sudo update-ca-certificates
  1. Run the following test code: https://play.golang.org/p/mxV6_0TW-Ji
$ go run -race testcode.go

What did you expect to see?

No race detector warning

What did you see instead?

WARNING: DATA RACE
Write at 0x00c00180d1b8 by goroutine 17:
  main.main.func2()
      /home/vadmeste/work/go/src/bytes/buffer.go:102 +0x186

Previous write at 0x00c00180d1b8 by goroutine 203:
  bytes.(*Buffer).Read()
      /home/vadmeste/work/go/src/bytes/buffer.go:310 +0x266
  io/ioutil.(*nopCloser).Read()
      <autogenerated>:1 +0x87
  net/http.(*http2clientStream).writeRequestBody()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:7664 +0x64d
  net/http.(*http2Transport).getBodyWriterState.func1()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:8878 +0x13d

Goroutine 17 (running) created at:
  main.main()
      /home/vadmeste/x/testcode.go:48 +0x277

Goroutine 203 (running) created at:
  net/http.http2bodyWriterState.scheduleBodyWrite()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:8925 +0x12f
  net/http.(*http2ClientConn).roundTrip()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:7465 +0x90f
  net/http.(*http2Transport).RoundTripOpt()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:6867 +0x23d
  net/http.http2noDialH2RoundTripper.RoundTrip()
      /home/vadmeste/work/go/src/net/http/h2_bundle.go:6829 +0x4c
  net/http.(*Transport).roundTrip()
      /home/vadmeste/work/go/src/net/http/transport.go:430 +0x14d9
  net/http.(*Transport).RoundTrip()
      /home/vadmeste/work/go/src/net/http/roundtrip.go:17 +0x42
  net/http.send()
      /home/vadmeste/work/go/src/net/http/client.go:250 +0x6a9
  net/http.(*Client).send()
      /home/vadmeste/work/go/src/net/http/client.go:174 +0x1cb
  net/http.(*Client).do()
      /home/vadmeste/work/go/src/net/http/client.go:641 +0x4ef
  main.main.func2()
      /home/vadmeste/work/go/src/net/http/client.go:509 +0x4e0
@dgryski
Copy link
Contributor

@dgryski dgryski commented Apr 1, 2019

@bradfitz bradfitz changed the title x/net/http2 client call causing a race detector warning x/net/http2: client call causing a race detector warning Apr 2, 2019
vadmeste added a commit to vadmeste/minio that referenced this issue Apr 2, 2019
A race is detected between a bytes.Buffer generated with cmd/rpc.Pool
and http2 module. An issue is raised in golang (golang/go#31192).

Meanwhile, this commit disables Pool in RPC code and it generates a
new 1kb of bytes.Buffer for each RPC call.
kannappanr added a commit to minio/minio that referenced this issue Apr 2, 2019
A race is detected between a bytes.Buffer generated with cmd/rpc.Pool
and http2 module. An issue is raised in golang (golang/go#31192).

Meanwhile, this commit disables Pool in RPC code and it generates a
new 1kb of bytes.Buffer for each RPC call.
@andybons andybons added this to the Go1.13 milestone Apr 3, 2019
@bcmills bcmills changed the title x/net/http2: client call causing a race detector warning net/http: race in http2Transport Apr 9, 2019
@fraenkel
Copy link
Contributor

@fraenkel fraenkel commented Apr 10, 2019

@bradfitz This might be the same issue with http. There is no guarantee that the bodyWriter is complete when roundtrip exits.

@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@odeke-em
Copy link
Member

@odeke-em odeke-em commented Oct 12, 2019

Here is a standalone adapted from @vadmeste's original program but here one doesn't have to manually create certificates but also it is reduced down

package main

import (
	"bytes"
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httptest"

	"golang.org/x/net/http2"
)

func main() {
	cst := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintf(w, "Pong")
	}))
	if err := http2.ConfigureServer(cst.Config, new(http2.Server)); err != nil {
		log.Fatalf("Failed to configure http2 server: %v", err)
	}
	cst.TLS = cst.Config.TLSConfig

	tr := &http.Transport{TLSClientConfig: cst.Config.TLSConfig}
	if err := http2.ConfigureTransport(tr); err != nil {
		log.Fatalf("Failed to configure http2 transport: %v", err)
	}
	tr.TLSClientConfig.InsecureSkipVerify = true
	cst.StartTLS()
	defer cst.Close()

	// Then finally create the HTTP client with the HTTP/2 transport.
	client := &http.Client{Transport: tr}

	for i := 0; i < 3; i++ {
		// Fill buf with data
		buf := bytes.NewBuffer(bytes.Repeat([]byte("A"), 128*1024))

		// Make a POST http call and read and discard response
		req, err := http.NewRequest("POST", cst.URL, buf)
		resp, err := client.Do(req)
		if err != nil {
			log.Fatalln(err)
		}
                if _, err := io.Copy(ioutil.Discard, resp.Body); err != nil {
			log.Fatalln(err)
		}
		resp.Body.Close()

		// Accessing buf here causes a RACE WARNING
		buf.Reset()
		fmt.Printf(".")
	}
}
@pmalek
Copy link

@pmalek pmalek commented Jun 14, 2020

@fraenkel Modifying @odeke-em 's example to use http like so:

package main

import (
	"bytes"
	"fmt"
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httptest"
)

func main() {
	srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintf(w, "Pong")
	}))
	defer srv.Close()

	client := srv.Client()

	for i := 0; i < 100; i++ {
		// Fill buf with data
		buf := bytes.NewBuffer(bytes.Repeat([]byte("A"), 128*1024))

		// Make a POST http call, read and discard response
		req, err := http.NewRequest("POST", srv.URL, buf)
		resp, err := client.Do(req)
		if err != nil {
			log.Fatalln(err)
		}
		if _, err := io.Copy(ioutil.Discard, resp.Body); err != nil {
			log.Fatalln(err)
		}
		resp.Body.Close()

		buf.Reset()
		fmt.Printf(".")
	}
}

I do not observe a data race.

The original issue is still present in gotip from go version devel +bd486c3 Sat Jun 13 16:03:19 2020 +0000 linux/amd64 and in 1.14.2.

There is no guarantee that the bodyWriter is complete when roundtrip exits.
I'm wondering what might be the fix for this. Could we make it so that the bodyWriter is complete when roundtrip exits?

@odeke-em
Copy link
Member

@odeke-em odeke-em commented Jun 14, 2020

@pmalek
Copy link

@pmalek pmalek commented Jun 14, 2020

@odeke-em My bad. But the TLS is also required to trigger this bug so both ts.EnableHTTP2 = true and ts.StartTLS() instead of ts.Start() in my simplified example will trigger the data race.

@fraenkel
Copy link
Contributor

@fraenkel fraenkel commented Jun 14, 2020

It took me a bit to reproduce the issue and then find the statement that covers this situation.

https://golang.org/pkg/net/http/#RoundTripper
callers wanting to reuse the body for subsequent requests must arrange to wait for the Close call before doing so.

The body isn't closed until net/http.(*http2clientStream).writeRequestBody() returns.

@pmalek
Copy link

@pmalek pmalek commented Jun 15, 2020

...must arrange to wait for the Close call...

That's interesting because as far as I can see there's no way of telling outside of the e.g. http.Post or http.Do call, whether the Close was called and that it returned.

@fraenkel
Copy link
Contributor

@fraenkel fraenkel commented Sep 6, 2020

Looking at this further, the issue is when a GOAWAY is sent from the server all outstanding streams are sent a response errClientConnGotGoAway. However, cs.writeRequestBody() may still be executing.

@fraenkel
Copy link
Contributor

@fraenkel fraenkel commented Sep 6, 2020

Good news, its easy to fix. Just have to create a test that always fails.

@gopherbot
Copy link

@gopherbot gopherbot commented Sep 7, 2020

Change https://golang.org/cl/253259 mentions this issue: net/http2: wait until the request body has been written

@answer1991
Copy link

@answer1991 answer1991 commented Sep 10, 2020

@andybons

Could you please add this fix to next milestone, as Kubernetes affected.

@answer1991
Copy link

@answer1991 answer1991 commented Sep 23, 2020

Could you please add this fix to next milestone, as Kubernetes affected.

@rsc

@networkimprov
Copy link

@networkimprov networkimprov commented Sep 23, 2020

@odeke-em are you available to review the above CL?

@ianlancetaylor ianlancetaylor modified the milestones: Backlog, Go1.16 Sep 24, 2020
@toothrot
Copy link
Contributor

@toothrot toothrot commented Oct 15, 2020

/cc @neild

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 31, 2020

We had a request to backport this, as it impacts Kubernetes, per @answer1991.

@odeke-em
Copy link
Member

@odeke-em odeke-em commented Oct 31, 2020

@dmitshur what do you think about the requested backport from @answer1991 and @networkimprov per #31192 (comment)?

@answer1991
Copy link

@answer1991 answer1991 commented Nov 2, 2020

Glad to see the fix merged.
As Kubernetes now is using golang 1.15.x, it would be fine if we backport the fix to 1.15.

@dmitshur
Copy link
Contributor

@dmitshur dmitshur commented Nov 2, 2020

I don't have enough information to know the severity of impact caused by this problem and whether there's a reasonable workaround. We need that information to balance it against the risk of backporting a commit when making a decision.

@answer1991 The process for requesting a backport is described at https://golang.org/wiki/MinorReleases. If after reading it you think this issue should be considered for backporting, please use gopherbot to make a request and provide a brief rationale for it. I know you've said this impacts Kubernetes, but please provide a little more detail about how serious it is. Thanks.

CC @golang/release.

@answer1991
Copy link

@answer1991 answer1991 commented Nov 12, 2020

Kubernetes team had already announced GOAWAY feature in Kubernetes v1.19 release notes. However, if Kubernetes enable GOAWAY feature, the client will receive unexpected 500 status code errors which I described at #41234, and there is no workaround. I think backport to golang 1.15 is necessary.

@gopherbot please backport, as Kubernetes is affected and there is no workaround.

@gopherbot
Copy link

@gopherbot gopherbot commented Nov 12, 2020

Backport issue(s) opened: #42539 (for 1.15).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

@networkimprov
Copy link

@networkimprov networkimprov commented Nov 12, 2020

@dmitshur @toothrot I think this needs backport to 1.14 as well?

@dmitshur
Copy link
Contributor

@dmitshur dmitshur commented Nov 12, 2020

Yep, since the issue affects both Go 1.15 and 1.14, it needs to be considered for backport to both, or neither. (We typically double-check that as part reviewing backport requests, but it's helpful to also catch it earlier.)

@answer1991
Copy link

@answer1991 answer1991 commented Nov 13, 2020

I don't know why the bot didn't create a cherry-pick to Go 1.14. Because I mentioned 1.15 in my comment? Re-try

@answer1991
Copy link

@answer1991 answer1991 commented Nov 13, 2020

Kubernetes team had already announced GOAWAY feature in Kubernetes v1.19 release notes. However, if Kubernetes enable GOAWAY feature, the client will receive unexpected 500 status code errors which I described at #41234, and there is no workaround. I think backport is necessary.

@gopherbot please backport, as Kubernetes is affected and there is no workaround.

@dmitshur
Copy link
Contributor

@dmitshur dmitshur commented Nov 13, 2020

Backport issue opened: #42586 (for 1.14).

(Follow up requests are not supported, so they need to be created manually until #25574 is resolved.)

@answer1991
Copy link

@answer1991 answer1991 commented Nov 13, 2020

thanks!

@dmitshur
Copy link
Contributor

@dmitshur dmitshur commented Nov 20, 2020

Reopening as the net/http issue isn't fixed in Go 1.16 yet.

This issue got closed because CL 253259 was submitted with the phrase "Fixes #31192". However that CL is for x/net. The bundled copy of golang.org/x/net/http2 inside net/http still needs to be updated to include the fix.

Doing the bundle update was attempted, but it caused an existing net/http test to fail. This is #42498. That issue needs to be resolved.

@dmitshur dmitshur reopened this Nov 20, 2020
@neild
Copy link
Contributor

@neild neild commented Dec 4, 2020

#42498 has been resolved (I believe), and should no longer block doing the bundle update.

@answer1991
Copy link

@answer1991 answer1991 commented Dec 4, 2020

Should we backport #42498 too?

@gopherbot
Copy link

@gopherbot gopherbot commented Dec 4, 2020

Change https://golang.org/cl/275446 mentions this issue: all: update dependencies with changes in scope for Go 1.16 freeze

@gopherbot
Copy link

@gopherbot gopherbot commented Dec 10, 2020

Change https://golang.org/cl/277012 mentions this issue: std: update golang.org/x/net to 20201209123823-ac852fbbde11

@gopherbot gopherbot closed this in e5522c8 Dec 10, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet