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/httputil: data race in DumpRequestOut #37669

Closed
schreik opened this issue Mar 4, 2020 · 17 comments
Closed

net/http/httputil: data race in DumpRequestOut #37669

schreik opened this issue Mar 4, 2020 · 17 comments
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@schreik
Copy link

schreik commented Mar 4, 2020

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

1.12.17

Does this issue reproduce with the latest release?

yes

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

linux/amd64

What did you do?

I am using AWS Go SDK code has a call to

	b, err := httputil.DumpRequestOut(t.HTTPRequest, logBody)

Unit test are running with GORACE=1 and fail inside the DumpRequestOut.

From the look at the code, DumpRequestOut creates a Go routine at line 115, which reads from req.Body, and then immediately changes req.Body to "save" at line 128 without waiting for routine to finish

	// Wait for the request before replying with a dummy response:
	go func() {
		req, err := http.ReadRequest(bufio.NewReader(pr))
		if err == nil {
			// Ensure all the body is read; otherwise
			// we'll get a partial dump.
			io.Copy(ioutil.Discard, req.Body)
			req.Body.Close()
		}
		dr.c <- strings.NewReader("HTTP/1.1 204 No Content\r\nConnection: close\r\n\r\n")
	}()

	_, err := t.RoundTrip(reqSend)

	req.Body = save

What did you expect to see?

No data race.

What did you see instead?

WARNING: DATA RACE
Write at 0x00c00072a040 by goroutine 66:
  net/http/httputil.DumpRequestOut()
      /usr/local/go/src/net/http/httputil/dump.go:128 +0x72e
  github.com/aws/aws-sdk-go/aws/client.logRequest()
      go/src/github.com/aws/aws-sdk-go/aws/client/logger.go:59 +0x130
  ...

Previous read at 0x00c00072a040 by goroutine 146:
  net/http.newTransferWriter()
      /usr/local/go/src/net/http/transfer.go:96 +0x10b7
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:601 +0x623
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:1982 +0x321
@dmitshur dmitshur changed the title DATA RACE in httputil.DumpRequestOut() net/http/httputil: data race in DumpRequestOut Mar 4, 2020
@odeke-em
Copy link
Member

odeke-em commented Mar 5, 2020

Hello @schreik, thank you for filing this issue and welcome to the Go project!

So we got the same bug report in #32571, and @agnivade fixed it for Go1.14 with CL https://go-review.googlesource.com/c/go/+/182037 aka commit e7a4ab4. This issue had existed for a while.

Could you please try upgrading to Go1.14?

Thank you.

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Mar 5, 2020
@schreik
Copy link
Author

schreik commented Mar 5, 2020

@odeke-em Thanks for looking into it! Our build system is quite complicated and we have periodic schedule go upgrade rollout. It will take a bit of time for me to learn how to upgrade go for my test only. I will try to build an isolated test to repro the issue.

Looking at the commit you mentioned though, it does not look like it will solve the issue, since modification of req.Body at line 135 is not synchronized with reading the value in go routine at line 124-125.

Thanks

@nerd2
Copy link

nerd2 commented Apr 7, 2020

We see (I believe) the same issue with Go 1.14.1

==================
WARNING: DATA RACE
Read at 0x00c0024d7640 by goroutine 131:
  net/http.newTransferWriter()
      GOROOT/src/net/http/transfer.go:83 +0x15a6
  net/http.(*Request).write()
      GOROOT/src/net/http/request.go:631 +0x61e
  net/http.(*persistConn).writeLoop()
      GOROOT/src/net/http/transport.go:2280 +0x331

Previous write at 0x00c0024d7640 by goroutine 295:
  net/http/httputil.DumpRequestOut()
      GOROOT/src/net/http/httputil/dump.go:147 +0x7d5
  repo.jazznetworks.com/vaion/vaion/lib/http_client.(*loggingRoundTripper).RoundTrip()
      lib/http_client/http_logging_round_tripper.go:22 +0x5e4
  net/http.send()
      GOROOT/src/net/http/client.go:252 +0x6a3
  net/http.(*Client).send()
      GOROOT/src/net/http/client.go:176 +0x1ca
  net/http.(*Client).do()
      GOROOT/src/net/http/client.go:699 +0x2cc
  net/http.(*Client).Do()
      GOROOT/src/net/http/client.go:567 +0x587

@nerd2
Copy link

nerd2 commented Apr 7, 2020

Potential fix

@@ -96,10 +96,8 @@
 	// switch to http so the Transport doesn't try to do an SSL
 	// negotiation with our dumpConn and its bytes.Buffer & pipe.
 	// The wire format for https and http are the same, anyway.
-	reqSend := req
+	reqSend := *req
 	if req.URL.Scheme == "https" {
-		reqSend = new(http.Request)
-		*reqSend = *req
 		reqSend.URL = new(url.URL)
 		*reqSend.URL = *req.URL
 		reqSend.URL.Scheme = "http"
@@ -142,7 +140,7 @@
 		}
 	}()
 
-	_, err := t.RoundTrip(reqSend)
+	_, err := t.RoundTrip(&reqSend)
 
 	req.Body = save
 	if err != nil {

@bcmills bcmills added help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Apr 8, 2020
@bcmills bcmills added this to the Backlog milestone Apr 8, 2020
@bcmills
Copy link
Contributor

bcmills commented Apr 8, 2020

@nerd2, if you have a fix, please contribute it! 🙂

nerd2 pushed a commit to nerd2/go that referenced this issue Apr 9, 2020
nerd2 added a commit to nerd2/go that referenced this issue Apr 9, 2020
nerd2 added a commit to nerd2/go that referenced this issue Apr 9, 2020
@gopherbot
Copy link

Change https://golang.org/cl/227717 mentions this issue: net/http: fix request body race in httputil DumpRequestOut

@bcmills
Copy link
Contributor

bcmills commented Apr 9, 2020

@schreik, the race-detector output that you provided looks like it is on the server side, but DumpRequestOut is specifically intended for the client side. Have you opened an issue with https://github.com/aws/aws-sdk-go to verify that the usage on their side is correct?

@bcmills
Copy link
Contributor

bcmills commented Apr 9, 2020

@nerd2, I can't see the source code for repo.jazznetworks.com/vaion/vaion/lib/http_client. Are you sure that the race isn't being introduced there? (A standalone reproducer would be very helpful.)

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 9, 2020
@gopherbot
Copy link

Change https://golang.org/cl/227773 mentions this issue: net/http/httputil: test Dump functions with a real http.Client and http.RoundTripper

@fraenkel
Copy link
Contributor

This is the same issue as #38352.
One cannot call DumpRequestOut in the middle of the Request processing because the Body can be manipulated by the Transport and will be drained by DumpRequestOut.

@nerd2
Copy link

nerd2 commented Apr 11, 2020

Well that's fun! Unfortunately the race is inside DumpRequestOut itself, racing between the local transport and the cancellation of the request context.
I have updated https://github.com/nerd2/bugs/blob/master/37669/dump_test.go to remove the transport wrapping and actual request making which was unnecessary.

WARNING: DATA RACE
Read at 0x00c00018a540 by goroutine 217:
  net/http.newTransferWriter()
      /usr/local/go/src/net/http/transfer.go:83 +0x15a6
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:631 +0x61e
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:2281 +0x33e

Previous write at 0x00c00018a540 by goroutine 66:
  net/http/httputil.DumpRequestOut()
      /usr/local/go/src/net/http/httputil/dump.go:147 +0x7d5
  github.com/nerd2/bugs/37669.testDumpRoundTripRace()
      /home/sam/go/src/github.com/nerd2/bugs/37669/dump_test.go:52 +0x692
  github.com/nerd2/bugs/37669.TestDumpRoundTripRace.func1()
      /home/sam/go/src/github.com/nerd2/bugs/37669/dump_test.go:23 +0x52
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:992 +0x1eb

Goroutine 217 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1648 +0xc33
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1365 +0x14f

Goroutine 66 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1043 +0x660
  github.com/nerd2/bugs/37669.TestDumpRoundTripRace()
      /home/sam/go/src/github.com/nerd2/bugs/37669/dump_test.go:22 +0xc4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:992 +0x1eb
==================```

@gopherbot
Copy link

Change https://golang.org/cl/232799 mentions this issue: net/http: Fix data race due to writeLoop goroutine left running

@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@odeke-em
Copy link
Member

odeke-em commented May 9, 2020

Hasn’t yet been fixed.

@odeke-em odeke-em reopened this May 9, 2020
@odeke-em
Copy link
Member

odeke-em commented May 9, 2020

Gobot, this issue is still valid.

@odeke-em odeke-em added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels May 9, 2020
@odeke-em odeke-em reopened this May 9, 2020
@bcmills
Copy link
Contributor

bcmills commented Aug 25, 2020

Reverted the fix CL due to failing tests, so reopening.

@bcmills bcmills reopened this Aug 25, 2020
@gopherbot
Copy link

Change https://golang.org/cl/251858 mentions this issue: net/http: fix data race due to writeLoop goroutine left running

@dmitshur dmitshur modified the milestones: Backlog, Go1.16 May 22, 2021
@golang golang locked and limited conversation to collaborators May 22, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants