Go proxy race.

README.md

Repro

1. Start the server and proxy. Run the proxy with the race detector enabled:
   • go build -o server server.go && ./server
   • go build -race -o proxy proxy.go && ./proxy
2. Start the client:
   • go build -o client && ./client
3. You should see the proxy race almost immediately. See sample below.

The question is: am I doing something racy or is this a net/http bug? The race is related to how I'm timing out the requests myself -- if I remove the transport.CancelRequest line, it doesn't seem to race. Is it the case that after cancelling the request, the transport's goroutines can still be messing with the response body?

Here is one of the race messages I get:

2013/12/20 13:24:22 Now listening on localhost:7575
==================
WARNING: DATA RACE
Read by goroutine 43:
  net/http.(*body).Read()
      /home/caleb/apps/go/src/pkg/net/http/transfer.go:531 +0x51
  io.(*LimitedReader).Read()
      /home/caleb/apps/go/src/pkg/io/io.go:398 +0x13e
  io/ioutil.devNull.ReadFrom()
      /home/caleb/apps/go/src/pkg/io/ioutil/ioutil.go:144 +0xbd
  io.Copy()
      /home/caleb/apps/go/src/pkg/io/io.go:348 +0x139
  io.CopyN()
      /home/caleb/apps/go/src/pkg/io/io.go:317 +0xf1
  net/http.(*chunkWriter).writeHeader()
      /home/caleb/apps/go/src/pkg/net/http/server.go:787 +0x1b08
  net/http.(*chunkWriter).Write()
      /home/caleb/apps/go/src/pkg/net/http/server.go:246 +0xb2
  bufio.(*Writer).flush()
      /home/caleb/apps/go/src/pkg/bufio/bufio.go:494 +0x15a
  bufio.(*Writer).Flush()
      /home/caleb/apps/go/src/pkg/bufio/bufio.go:483 +0x34
  net/http.(*response).finishRequest()
      /home/caleb/apps/go/src/pkg/net/http/server.go:999 +0x9d
  net/http.(*conn).serve()
      /home/caleb/apps/go/src/pkg/net/http/server.go:1171 +0xc31

Previous write by goroutine 235:
  net/http.(*body).Close()
      /home/caleb/apps/go/src/pkg/net/http/transfer.go:634 +0xc1
  net/http.(*transferWriter).WriteBody()
      /home/caleb/apps/go/src/pkg/net/http/transfer.go:207 +0x2e0
  net/http.(*Request).write()
      /home/caleb/apps/go/src/pkg/net/http/request.go:400 +0xa38
  net/http.(*persistConn).writeLoop()
      /home/caleb/apps/go/src/pkg/net/http/transport.go:797 +0x210

Goroutine 43 (running) created at:
  net/http.(*Server).Serve()
      /home/caleb/apps/go/src/pkg/net/http/server.go:1644 +0x2c1
  net/http.(*Server).ListenAndServe()
      /home/caleb/apps/go/src/pkg/net/http/server.go:1612 +0xc0
  main.main()
      /home/caleb/test/race-repro/proxy.go:77 +0x206

Goroutine 235 (finished) created at:
  net/http.(*Transport).dialConn()
      /home/caleb/apps/go/src/pkg/net/http/transport.go:529 +0x8d5
  net/http.func·014()
      /home/caleb/apps/go/src/pkg/net/http/transport.go:419 +0x76
==================

I noticed this bug because I was seeing this HTTP protocol error being printed by net/http:

2013/12/20 11:55:21 Unsolicited response received on idle HTTP channel starting with "H"; err=<nil>

client.go

package main

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

const (
	N         = 100
	targetURL = "http://localhost:7575"
)

func main() {
	transport := &http.Transport{
		MaxIdleConnsPerHost: N,
	}
	client := &http.Client{Transport: transport}
	for i := 0; i < N; i++ {
		go func() {
			for {
				buf := bytes.NewBufferString("foobar")
				resp, err := client.Post(targetURL, "foo/bar", buf)
				if err != nil {
					continue
				}
				io.Copy(ioutil.Discard, resp.Body)
				resp.Body.Close()
			}
		}()
	}
	fmt.Println("Making requests...")
	select {}
}

proxy.go

// This is similar to net/http/httputil.ReverseProxy, except that I'm timing out backend requests manually in
// addition to setting a MaxIdleConnsPerHost on my transport. (This is just a repro case -- in my real
// application I have to set a different timeout per request.)
//
// Something about how I'm doing the timeout triggers a race.

package main

import (
	"io"
	"log"
	"net"
	"net/http"
	"runtime"
	"strings"
	"time"
)

const (
	addr     = "localhost:7575"
	backend  = "localhost:8091"
	maxConns = 100
	timeout  = 100 * time.Millisecond
	timeout2 = 30 * time.Millisecond
)

var (
	transport = &http.Transport{
		MaxIdleConnsPerHost:   maxConns,
		ResponseHeaderTimeout: timeout,
	}
)

func Handle(w http.ResponseWriter, r *http.Request) {
	proxyReq := CreateProxyRequest(r)
	timer := time.NewTimer(timeout2)
	var resp *http.Response
	var err error
	timedOut := false
	finished := make(chan bool)

	go func() {
		resp, err = transport.RoundTrip(proxyReq)
		finished <- true
	}()
	select {
	case <-finished:
		timer.Stop()
	case <-timer.C:
		transport.CancelRequest(proxyReq)
		<-finished
		timedOut = true
	}

	if err == nil {
		defer resp.Body.Close()
	}

	if err != nil || timedOut {
		http.Error(w, "error -- timeout or other", http.StatusBadGateway)
		return
	}

	CopyHeader(w.Header(), resp.Header)
	w.WriteHeader(resp.StatusCode)
	io.Copy(w, resp.Body)
}

func main() {
	runtime.GOMAXPROCS(4) // GOMAXPROCS > 1 necessary to trip race detector for me

	server := &http.Server{
		Addr:    addr,
		Handler: http.HandlerFunc(Handle),
	}
	log.Println("Now listening on", addr)
	log.Fatal(server.ListenAndServe())
}

// ####
// Everything below here is basically copied from net/http/httputil.ReverseProxy
// ####

func CopyHeader(dst, src http.Header) {
	for k, vv := range src {
		for _, v := range vv {
			dst.Add(k, v)
		}
	}
}

var hopHeaders = []string{
	"Connection",
	"Keep-Alive",
	"Proxy-Authenticate",
	"Proxy-Authorization",
	"Te", // canonicalized version of "TE"
	"Trailers",
	"Transfer-Encoding",
	"Upgrade",
}

// CreateProxyRequest synthesizes a new http.Request by applying the configuration to an inbound request.
func CreateProxyRequest(r *http.Request) *http.Request {
	out := &http.Request{}
	*out = *r // Note this shallow copies maps

	// Apply configuration
	out.URL.Host = backend

	if r.TLS == nil {
		out.URL.Scheme = "http"
	} else {
		out.URL.Scheme = "https"
	}

	// Change other settings suitable for reverse proxies
	out.Proto = "HTTP/1.1"
	out.ProtoMajor = 1
	out.ProtoMinor = 1
	out.Close = false

	// Remove hop-by-hop headers to the backend. Especially important is "Connection" because we want a
	// persistent connection, regardless of what the client sent to us. This is modifying the same underlying
	// map from r (shallow copied above) so we only copy it if necessary.
	copiedHeaders := false
	for _, h := range hopHeaders {
		if out.Header.Get(h) != "" {
			if !copiedHeaders {
				out.Header = make(http.Header)
				CopyHeader(out.Header, r.Header)
				copiedHeaders = true
			}
			out.Header.Del(h)
		}
	}

	if clientIP, _, err := net.SplitHostPort(r.RemoteAddr); err == nil {
		// If we aren't the first proxy retain prior X-Forwarded-For information as a comma+space separated list
		// and fold multiple headers into one.
		if prior, ok := out.Header["X-Forwarded-For"]; ok {
			clientIP = strings.Join(prior, ", ") + ", " + clientIP
		}
		out.Header.Set("X-Forwarded-For", clientIP)
	}

	return out
}

server.go

// A small test (echo) server.

package main

import (
	"io/ioutil"
	"log"
	"net/http"
	"time"
)

const (
	addr  = "localhost:8091"
	delay = 10 * time.Millisecond
)

func handle(w http.ResponseWriter, r *http.Request) {
	time.Sleep(delay)
	b, err := ioutil.ReadAll(r.Body)
	if err != nil {
		http.Error(w, "couldn't read: "+err.Error(), http.StatusBadGateway)
		return
	}
	w.Write(b)
}

func main() {
	server := &http.Server{
		Addr:    addr,
		Handler: http.HandlerFunc(handle),
	}
	log.Println("Now listening on", addr)
	log.Fatal(server.ListenAndServe())
}