net/http: race using same long/infinite Request.Body after first is cut off by server

[rogpeppe]

This program:
http://play.golang.org/p/M1-UWKD33p
has the race condition below.

The reason is probably because the exit of the http.persistConn.writeLoop
goroutine is not waited for by the http request.

FWIW some of our current infrastructure relies heavily on being able
to make two successive requests using the same reader
(it seeks to the start before making the second request).

Reproduced with Go 1.4.3 and 1.5.1.

WARNING: DATA RACE
Read by goroutine 20:
  main.(*reader).Read()
      /home/alesstimec/Downloads/main.go:15 +0x44
  io/ioutil.(*nopCloser).Read()
      <autogenerated>:4 +0xa0
  io.ReadAtLeast()
      /usr/local/go/src/io/io.go:298 +0x118
  io.ReadFull()
      /usr/local/go/src/io/io.go:316 +0x76
  net/http.newTransferWriter()
      /usr/local/go/src/net/http/transfer.go:71 +0x11ce
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:435 +0xc8b
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:1015 +0x316

Previous write by goroutine 11:
  main.(*reader).Read()
      /home/alesstimec/Downloads/main.go:15 +0x5a
  io/ioutil.(*nopCloser).Read()
      <autogenerated>:4 +0xa0
  io.(*multiReader).Read()
      /usr/local/go/src/io/multi.go:13 +0x10c
  io.copyBuffer()
      /usr/local/go/src/io/io.go:381 +0x281
  io.Copy()
      /usr/local/go/src/io/io.go:351 +0x78
  net/http.(*transferWriter).WriteBody()
      /usr/local/go/src/net/http/transfer.go:218 +0x39f
  net/http.(*Request).write()
      /usr/local/go/src/net/http/request.go:462 +0xed7
  net/http.(*persistConn).writeLoop()
      /usr/local/go/src/net/http/transport.go:1015 +0x316

Goroutine 20 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:686 +0x11e4
  net/http.(*Transport).getConn.func4()
      /usr/local/go/src/net/http/transport.go:549 +0x73

Goroutine 11 (finished) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:686 +0x11e4
  net/http.(*Transport).getConn.func4()
      /usr/local/go/src/net/http/transport.go:549 +0x73
==================

[rogpeppe]

Also arguably related to this: the request body is not necessarily closed before Do returns.

[bradfitz]

Okay, this is more contrived than I originally thought. What's happening is that your reader in this case is infinite, or at least longer than the server's handler is reading. Because the server handler returns before reading to EOF, it sets "Connection: close" and interrupts the TCP connection while the client is still writing in writeLoop.

So, yes, we could wait for the writer to be done writing at body EOF (if there's a body) or before returning the body-less response headers.

[gopherbot]

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

[bradfitz]

The more I work on this, the less I think it's fixable. The change https://golang.org/cl/17312 kinda fixes it, at least for some cases, but ultimately it's not possible to cancel a blocked Read call, which means that without heuristics like "wait 100ms", RoundTrip can deadlock if the server replies before the request body is written and the request body is still being written from a forever-blocked Reader.

I think I'd prefer to fix this with documentation, updating the RoundTripper docs to say that the body may still be being Read and Closed after RoundTrip returns, and that callers who want to reuse the Body have to wait on it themselves. (e.g. with a wrapped ReadCloser noting when it's done and providing synchronization)

[rogpeppe]

FWIW this is worse than I thought originally. Just closing the body after the request is enough to trigger the race. For example, the race detector shows a data race in the following innocuous looking code which tries to PUT a body from an open file, then closes the file.

It's common defensive practice to "defer close" a file - this code looks alright even knowing that Post will close the file, because closing a file twice isn't a problem. The fact that net/http asynchronously closes the file after the Do has completed is unfortunate.

package main

import (
    "log"
    "net/http"
    "net/http/httptest"
    "os"
)

const largeFile = "/mnt/syn/rog/movies/TheLongHope.mov"

func main() {
    srv := httptest.NewServer(http.HandlerFunc(http.NotFound))
    f, err := os.Open(largeFile)
    if err != nil {
        log.Fatal(err)
    }
    defer f.Close()
    resp, err := http.Post(srv.URL, "text/plain", f)
    if err != nil {
        log.Fatal(err)
    }
    log.Printf("resp: %v", resp.Status)
}