net/http: data race when response is returned before the full request's body is written

[VirrageS]

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

$ go version
go version go1.12 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

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/januszm/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/januszm/.go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/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-build489382708=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run following script with: go run -race concept.go

package main

import (
	"crypto/rand"
	"fmt"
	"io"
	"io/ioutil"
	"net/http"
	"sync"
	"time"
)

const (
	addr1 = "localhost:8060"
	addr2 = "localhost:8061"
)

type customReader struct {
	iter int
	size int
}

func (r *customReader) Read(b []byte) (int, error) {
	maxRead := r.size - r.iter
	if maxRead == 0 {
		return 0, io.EOF
	}
	if maxRead > len(b) {
		maxRead = len(b)
	}
	n, err := rand.Read(b[:maxRead])
	r.iter += maxRead
	return n, err
}

func (r *customReader) Close() error {
	// Uncomment this for even more races :((
	// r.iter = 0
	return nil
}

func (r *customReader) Reset() {
	r.iter = 0
}

func second(w http.ResponseWriter, r *http.Request) {
	ioutil.ReadAll(r.Body)
}

func first(w http.ResponseWriter, r *http.Request) {
	http.Redirect(w, r, "http://"+addr2+"/second", http.StatusTemporaryRedirect)
}

func main() {
	mux1 := http.NewServeMux()
	mux1.HandleFunc("/first", first)
	srv1 := http.Server{
		Addr:    addr1,
		Handler: mux1,
	}
	go func() {
		err := srv1.ListenAndServe()
		fmt.Printf("err: %v", err)
	}()

	mux2 := http.NewServeMux()
	mux2.HandleFunc("/second", second)
	srv2 := http.Server{
		Addr:    addr2,
		Handler: mux2,
	}
	go func() {
		err := srv2.ListenAndServe()
		fmt.Printf("err: %v", err)
	}()

	time.Sleep(time.Second)
	client := http.DefaultClient

	wg := &sync.WaitGroup{}
	for i := 0; i < 1000; i++ {
		reader := &customReader{size: 900000}
		wg.Add(1)
		go func(r *customReader) {
			for {
				req, err := http.NewRequest(http.MethodPut, "http://"+addr1+"/first", r)
				if err != nil {
					fmt.Printf("%v", err)
				}
				req.GetBody = func() (io.ReadCloser, error) {
					return &customReader{size: 900000}, nil
				}

				if resp, err := client.Do(req); err != nil {
					// fmt.Printf("error: %v", err)
				} else if resp.StatusCode >= http.StatusBadRequest {
					// fmt.Printf("status code: %d", resp.StatusCode)
				}

				// Reset reader and try to reuse it in next request
				r.Reset()
			}

			wg.Done()
		}(reader)
	}

	wg.Wait() // infinite wait

	srv1.Close()
	srv2.Close()
}

What did you expect to see?

No races

What did you see instead?

Races:

==================
WARNING: DATA RACE
Write at 0x00c0003e00a0 by goroutine 87:
  main.main.func3()
      /home/januszm/concept.go:43 +0x55

Previous write at 0x00c0003e00a0 by goroutine 3899:
  [failed to restore the stack]

Goroutine 87 (running) created at:
  main.main()
      /home/januszm/concept.go:91 +0x3b0

Goroutine 3899 (finished) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1358 +0xb89
  net/http.(*Transport).getConn.func4()
      /usr/local/go/src/net/http/transport.go:1015 +0xd0
==================
==================
WARNING: DATA RACE
Write at 0x00c0002ca750 by goroutine 488:
  main.main.func3()
      /home/januszm/concept.go:43 +0x55

Previous write at 0x00c0002ca750 by goroutine 1951:
  main.(*customReader).Read()
      /home/januszm/concept.go:33 +0x156
  net/http.transferBodyReader.Read()
      /usr/local/go/src/net/http/transfer.go:62 +0x77
  io.copyBuffer()
      /usr/local/go/src/io/io.go:402 +0x143
  net/http.(*transferWriter).writeBody()
      /usr/local/go/src/io/io.go:364 +0x76e
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:655 +0x7c3
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:1961 +0x321

Goroutine 488 (running) created at:
  main.main()
      /home/januszm/concept.go:91 +0x3b0

Goroutine 1951 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1358 +0xb89
  net/http.(*Transport).getConn.func4()
      /usr/local/go/src/net/http/transport.go:1015 +0xd0
==================
==================
WARNING: DATA RACE
Write at 0x00c0002ca780 by goroutine 491:
  main.main.func3()
      /home/januszm/concept.go:43 +0x55

Previous write at 0x00c0002ca780 by goroutine 3360:
  ??()
      -:0 +0xffffffffffffffff
  fmt.(*fmt).fmtInteger()
      /usr/local/go/src/fmt/format.go:307 +0x441
  fmt.(*pp).fmtInteger()
      /usr/local/go/src/fmt/print.go:386 +0x297
  fmt.(*pp).printArg()
      /usr/local/go/src/fmt/print.go:662 +0xf13
  fmt.(*pp).doPrintf()
      /usr/local/go/src/fmt/print.go:1016 +0x315
  fmt.Fprintf()
      /usr/local/go/src/fmt/print.go:199 +0x7f
  net/http/internal.(*chunkedWriter).Write()
      /usr/local/go/src/net/http/internal/chunked.go:203 +0xd8
  io.copyBuffer()
      /usr/local/go/src/io/io.go:404 +0x282
  net/http.(*transferWriter).writeBody()
      /usr/local/go/src/io/io.go:364 +0x76e
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:655 +0x7c3
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:1961 +0x321

Goroutine 491 (running) created at:
  main.main()
      /home/januszm/concept.go:91 +0x3b0
==================

[mvdan]

Are you positive that the race is in net/http and not your use of it? If you're not sure, have you tried asking on one of the forums for help?

[VirrageS]

No, I'm not positive and I haven't ask on the forums. Though, there is nothing said in (c *Client) Do about this case so I concluded that this is unexpected

I will try to post on forums to ensure that this is not my fault. If it is, it would mean that one cannot change fields in Close method which are also used by Read in reader which seems odd. As a result we couldn't be able use *File as ReadCloser in Body for redirected requests since it does modify (on Close) descriptor which Read is using.

[orian]

https://groups.google.com/forum/#!topic/golang-nuts/1rst28pnlt8

The problem is not net/http but simultaneous use of a reader := &customReader{...} variable in 1000 goroutines. I believe the issue should be closed.

[VirrageS]

I'm sorry but could you point out where I use it simultaneously? I create new(!) reader for each goroutine.

If you want, you can remove this goroutine stuff and have single infinite for loop. The code will still have a races but you probably need to run it for a little bit longer to see them

Single thread race

package main

import (
	"crypto/rand"
	"fmt"
	"io"
	"io/ioutil"
	"net/http"
	"sync"
	"time"
)

const (
	addr1 = "localhost:8060"
	addr2 = "localhost:8061"
)

type customReader struct {
	iter int
	size int
}

func (r *customReader) Read(b []byte) (int, error) {
	maxRead := r.size - r.iter
	if maxRead == 0 {
		return 0, io.EOF
	}
	if maxRead > len(b) {
		maxRead = len(b)
	}
	n, err := rand.Read(b[:maxRead])
	r.iter += maxRead
	return n, err
}

func (r *customReader) Close() error {
	// Uncomment this for even more races :((
	// r.iter = 0
	return nil
}

func (r *customReader) Reset() {
	r.iter = 0
}

func second(w http.ResponseWriter, r *http.Request) {
	ioutil.ReadAll(r.Body)
}

func first(w http.ResponseWriter, r *http.Request) {
	http.Redirect(w, r, "http://"+addr2+"/second", http.StatusTemporaryRedirect)
}

func main() {
	mux1 := http.NewServeMux()
	mux1.HandleFunc("/first", first)
	srv1 := http.Server{
		Addr:    addr1,
		Handler: mux1,
	}
	go func() {
		err := srv1.ListenAndServe()
		fmt.Printf("err: %v", err)
	}()

	mux2 := http.NewServeMux()
	mux2.HandleFunc("/second", second)
	srv2 := http.Server{
		Addr:    addr2,
		Handler: mux2,
	}
	go func() {
		err := srv2.ListenAndServe()
		fmt.Printf("err: %v", err)
	}()

	time.Sleep(time.Second)
	client := http.DefaultClient

	reader := &customReader{size: 900000}
	for {
		req, err := http.NewRequest(http.MethodPut, "http://"+addr1+"/first", r)
		if err != nil {
			fmt.Printf("%v", err)
		}
		req.GetBody = func() (io.ReadCloser, error) {
			return &customReader{size: 900000}, nil
		}

		if resp, err := client.Do(req); err != nil {
			// fmt.Printf("error: %v", err)
		} else if resp.StatusCode >= http.StatusBadRequest {
			// fmt.Printf("status code: %d", resp.StatusCode)
		}

		// Reset reader and try to reuse it in next request
		r.Reset()
	}

	srv1.Close()
	srv2.Close()
}

[fraenkel]

The problem is with your reader. iter is being updated in multiple goroutines, via Read() and Reset(). The underlying http transport is not guaranteed to use a single goroutine to handle your request/response.

Although on my machine, I never got a data race detection, but call me lucky in this case.

[VirrageS]

The problem is with your reader. iter is being updated in multiple goroutines, via Read() and Reset().

But how is that possible? Reset is called AFTER client.Do so I would expect all Reads/Writes or whatever, are done and I can still use my reader. Is that bad assumption? If so, the client.Do documentation should state that it is not safe to use reader (passed to req.Body) after client.Do.

The underlying http transport is not guaranteed to use a single goroutine to handle your request/response.

And I don't expect it to use single goroutine. It can use two or million of goroutines. I don't care as long as it does it safely. If safety is on my (user) side then I would expect that 99.9% implementations that use readers in req.Body are unsafe and prone to races since they do not use locks or any synchronization mechanism.

[orian]

I'm sorry for incorrect claim.

I've run your code in debugger and read net/http package, as far as I understand there is a goroutine per connection writing/reading data. The communication between the routines is done over channel and I believe that client.Do will never return before everything is done.

The relevant code responsible for processing request/response is in transport: https://github.com/golang/go/blame/master/src/net/http/transport.go#L2164

@bradfitz done a lot of changes in transport and probably can tell you more, especially confirm or deny my implicit assumption about the client.Do.

[bradfitz]

You haven't closed your Response.Body, so the Transport is still handling (thus, owning) the request when you Reset its Body.

[orian]

Closing Response.Body doesn't solve the problem.

Brad, I've read the code in transport.go. There's a select on L2177. I cannot find a sync mechanism in place between writing request / reading response.
I believe that in the above code the exact case described in comment on L2156 happens (cause the simple first HandleFunc just responds with code 307):

// Write the request concurrently with waiting for a response,
// in case the server decides to reply before reading our full
// request body.

and the case on L2205 is executed causing to return before the writeLoop fails.

Because VirrageS is reusing the io.Reader the race detector finds the data race, but this indeed is either a bug or undocumented behaviour.

I've also simplified the example provided by VirrageS:

package main

import (
	"crypto/rand"
	"io"
	"log"
	"net/http"
)

type customReader struct {
	iter int
	size int
}

func (r *customReader) Read(b []byte) (int, error) {
	maxRead := r.size - r.iter
	if maxRead == 0 {
		return 0, io.EOF
	}
	if maxRead > len(b) {
		maxRead = len(b)
	}
	n, err := rand.Read(b[:maxRead])
	r.iter += maxRead
	return n, err
}

func (r *customReader) Close() error {
	// Uncomment this for even more races :((
	// r.iter = 0
	return nil
}

func (r *customReader) Reset() {
	r.iter = 0
}

func main() {
	http.HandleFunc("/", func(_ http.ResponseWriter, _ *http.Request) {})
	go func() {
		if err := http.ListenAndServe("localhost:8060", nil); err != nil {
			log.Panicf("err: %v", err)
		}
	}()

	client := http.DefaultClient
	r := &customReader{size: 900000}

	req, err := http.NewRequest(http.MethodPut, "http://localhost:8060", r)
	if err != nil {
		log.Printf("%v", err)
	}

	resp, err := client.Do(req)
	if err != nil {
		log.Printf("error: %v", err)
	} else if resp.StatusCode != http.StatusOK {
		log.Printf("status code: %d", resp.StatusCode)
	}
	resp.Body.Close()

	r.Reset()
}

The error appeared on redirection but it's not the clue of the problem. To duplicate the issue writing the body must take more time the response from server, manipulating the size of the body helps.

If cannot replicate, just put time.Sleep(5*time.Second) in the customReader.Read.

[VirrageS]

@bradfitz: as @orian mentioned, adding resp.Body.Close() does not solve the problem. Races are still possible (and reproducible) between Read and Close/Reset.

[fraenkel]

@bradfitz I believe the issue may be that there is no guarantee that the writeLoop is finished. The writeLoopDone channel is only checked on a broken connection.
Just a hunch.

[orian]

I've verified. The issue is reproducible in 1.12.6.

The io.Copy function, causing the writeLoop to take keep the req.Body resource:

go/src/net/http/transfer.go

Line 358 in 2012227

_, err = io.Copy(cw, body)

was encapsulated:

go/src/net/http/transfer.go

Line 348 in 88548d0

_, err = t.doBodyCopy(cw, body)

However, the io.Copy cannot be easily interrupted and therefore causing race condition.

I've checked writeLoopDone, this is per connection variable and I think it should not be modified when a response is returned before the full request's body has been written.

The solutions I see are:

1. Document the current behaviour and leave as it is. I think this is undesired behavior to have a goroutine modify data in the background. At least for me it is unintuitive.
2. Block readLoop until the writeLoop finishes writing the Request.Body. (I've implemented it using per request channel to block a return from roundTrip: https://github.com/orian/go/tree/issue-30597). This breaks context.Deadline.
3. Same as 2. but with extra mechanism to interrupt the writeLoop from copying all Body data. I think this is undesirable.

@bradfitz I'm happy to contribute the fix, but someone must make decision.

[VirrageS]

@orian Thanks for looking into this issue!

Another thing that worried me a little in writeBody function is that reader passed in request is wrapped into transferBodyReader. This becomes an issue when the reader implements WriteTo method and can be sent without extra buffering (io.Copy should catch that). But since transferBodyReader does not implement this it will only use the Read method. And also eg. we are streaming something through single request the problem is that we will use default 32KB buffer, provided in io.Copy implementation and there is no way to make it bigger or smaller what could potentially have impact on performance.

But this probably needs another issue and separate discussion.

[orian]

@andybons could you change the bug name to "net/http: data race when response is returned before the full request's body is written" or something similar?

Also, I think the Go' client implementation does not follow RFC2616 "8.2.2 Monitoring Connections for Error Status Messages" (https://www.w3.org/Protocols/rfc2616/rfc2616-sec8.html):

An HTTP/1.1 (or later) client sending a message-body SHOULD monitor the network connection for an error status while it is transmitting the request. If the client sees an error status, it SHOULD immediately cease transmitting the body.

@VirrageS a master' version of writeBody doesn't wrap the reader therefore the problem should be gone by Go 1.13.

[VirrageS]

Was there any decision made regarding this issue?

[ianlancetaylor]

Ping @bradfitz regarding #30597 (comment) .

[MissingRoberto]

this is also happening when trying to use the DumpRequestOut: https://golang.org/pkg/net/http/httputil/#DumpRequestOut

[VirrageS]

ping @bradfitz