net/http: `readLoopPeekFailLocked: <nil>` from client when server sends response immediately

[logrusorgru]

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

$ go version
go version go1.12.1 linux/amd64

Does this issue reproduce with the latest release?

Yep. 1.14.1

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

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/user/go"
GOPROXY=""
GORACE=""
GOROOT="/opt/go"
GOTMPDIR=""
GOTOOLDIR="/opt/go/pkg/tool/linux_amd64"
GCCGO="/usr/bin/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-build705707104=/tmp/go-build -gno-record-gcc-switches"

What did you do?

100% reproducible on Linux x64, and play.golang.org. The behavior is unpredictable and the code (see below) to reproduce should be executed few times to got the error and the log.

The error is:

Get http://127.0.0.1:9101/path: readLoopPeekFailLocked: <nil>

The log is:

transport.go:1829: Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 502 Bad Gateway\r\n\r\n"; err=<nil>

What happens?

HTTP server sends response without reading request and without a delay. This approach is good for proxy servers where a client determined by his IP (i.e. using white-list). Thus, we haven't to read request, if the user is not white-listed.

Reproducing

(try few times to got error)

play.golang.org

package main

import (
	"fmt"
	"log"
	"net"
	"net/http"
	"net/url"
	"sync"
	"time"
)

func mustParseURL(uri string) *url.URL {
	x, err := url.Parse(uri)
	if err != nil {
		panic(err)
	}
	return x
}

func main() {

	l, err := net.Listen("tcp", "127.0.0.1:9100")
	if err != nil {
		log.Fatal(err)
	}
	go func(l net.Listener) {
		for {
			c, err := l.Accept()
			if err != nil {
				log.Fatal(err)
			}
			go func(c net.Conn) {
				defer c.Close()
				fmt.Fprint(c, "HTTP/1.1 502 Bad Gateway\r\n\r\n")
			}(c)
		}
	}(l)
	time.Sleep(100 * time.Millisecond)

	var cl http.Client
	cl.Transport = &http.Transport{
		Proxy:           http.ProxyURL(mustParseURL("http://127.0.0.1:9100/")),
		MaxConnsPerHost: 100,
	}

	const N = 100

	var wg sync.WaitGroup
	wg.Add(N)
	for i := 0; i < N; i++ {
		go func() {
			defer wg.Done()
			resp, err := cl.Get("http://127.0.0.1:9101/path")
			if err != nil {
				log.Print("error:", err)
				return
			}
			if resp.StatusCode != 502 {
				log.Println("status:", resp.StatusCode)
			}
			resp.Body.Close()
		}()
	}

	wg.Wait()

}

Also, playing with the N constant I've got this error for N=10, N=100 and N=1000. For N=1000 this error occurs every time. For N=10 rarely. Seems, it depends on goroutines scheduling.

What did you expect to see?

Got this error every time or never.

What did you see instead?

It's unpredictable. That makes testing a bit harder.

Also

Probably related issues #15253, #15446

[bcmills]

CC @bradfitz

[lamg]

Go version

go version go1.13 linux/amd64

Behavior

Running the following code with go test -race fails most of the times, but not always. I've never seen it fail with go test.

package race

import (
	"bytes"
	"context"
	"net"
	h "net/http"
	ht "net/http/httptest"
	"testing"
	"time"
)

func TestDataRace(t *testing.T) {
	d := &dialer{content: "HTTP/1.1 502 Bad Gateway\r\n\r\n"}
	tr := &h.Transport{
		DialContext: d.dial,
	}
	req := ht.NewRequest(h.MethodGet, "http://example.com", nil)
	resp, e := tr.RoundTrip(req)
	if e != nil {
		t.Error(e)
	} else if resp.StatusCode != h.StatusBadGateway {
		t.Error("status:", resp.Status)
	}
}

type dialer struct {
	content string
}

func (d *dialer) dial(ctx context.Context, network,
	addr string) (n net.Conn, e error) {
	n = newMockConn(d.content)
	return
}

type mockConn struct {
	read  *bytes.Buffer
	write *bytes.Buffer
}

func newMockConn(content string) (m *mockConn) {
	m = &mockConn{
		read:  bytes.NewBufferString(content),
		write: new(bytes.Buffer),
	}
	return
}

func (m *mockConn) Read(p []byte) (n int, e error) {
	n, e = m.read.Read(p)
	return
}

func (m *mockConn) Write(p []byte) (n int, e error) {
	n, e = m.write.Write(p)
	return
}

func (m *mockConn) Close() (e error) { return }

func (m *mockConn) LocalAddr() (a net.Addr) { return }

func (m *mockConn) RemoteAddr() (a net.Addr) { return }

func (m *mockConn) SetDeadline(t time.Time) (e error) { return }

func (m *mockConn) SetReadDeadline(t time.Time) (e error) {
	return
}

func (m *mockConn) SetWriteDeadline(t time.Time) (e error) {
	return
}

Output when failing

2019/10/11 17:19:50 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 502 Bad Gateway\r\n\r\n"; err=<nil>
--- FAIL: TestDataRace (0.00s)
    race_test.go:21: readLoopPeekFailLocked: <nil>
FAIL
exit status 1

[lamg]

Defining in the previous code mockConn, newMockConn, mockConn.Read and mockConn.Write the following way, the error never appeared so far, with go test or go test -race:

type mockConn struct {
	read    *bytes.Buffer
	write   *bytes.Buffer
	writeOk chan bool
}

func newMockConn(content string) (m *mockConn) {
	m = &mockConn{
		read:    bytes.NewBufferString(content),
		write:   new(bytes.Buffer),
		writeOk: make(chan bool, 0),
	}
	return
}

func (m *mockConn) Read(p []byte) (n int, e error) {
	<-m.writeOk
	n, e = m.read.Read(p)
	return
}

func (m *mockConn) Write(p []byte) (n int, e error) {
	n, e = m.write.Write(p)
	m.writeOk <- true
	return
}

[cuonglm]

Maybe related #34066

[sebglon]

I have exactly the same with golang 1.13 and a fake http server like that:
echo -e "HTTP/1.1 200 OK\n\n{}" | nc -l -p ${SERVER_PORT}

[cyx]

@logrusorgru seeing this happen as well. Can you reproduce it on go 1.11 as well or just 1.12++ ?

[bcmills]

@cyx, note that per the release policy, neither Go 1.11 nor 1.12 is supported at this point.

(@sebglon's report of a repro using Go 1.13 is helpful, though.)

[logrusorgru]

@cyx, I just have checked out go version go1.11.13 linux/amd64. I can say that this is reproducible in the entire go version go1.11.13 linux/amd64 - go version go1.14.1 linux/amd64 range.

I don't think this issue is a real problem, but anyone is working with HTTP "manually" may run into it.

I just use (let's say it's app.go)

var isTesting bool

// [...]

// handler function
    if isTesting {
       time.Sleep(100*time.Microsecond)
    }

(let's say it's app_test.go)

var _ = func() struct{} {
    isTesting = true
    return struct{}{}
}()

To get my tests 100% stable.

Because of the 100µs, I think it's about goroutines scheduling.

[cyx]

Thanks! That makes sense. I'm seeing this in production with the clients primarily being node http clients -- although the interesting thing is that I only see it on higher throughput environments

[jsha]

I can report that we're seeing this issue in production at Let's Encrypt, using https://github.com/letsencrypt/boulder/. Specifically, there are some "hasty" HTTP servers out there that will send an HTTP response as soon as the TCP connection completes. When we make multiple concurrent requests to such a server, we get Unsolicited response in our stdout logs.

The reason we'd like to see this fixed: In general we try to route all log output through our logging system, and this is the one place in net/http that regularly prints to stdout. I have a minimized repro case below that is a bit shorter than ones posted to this thread. Reproduces 100% on Go 1.14.2 (latest as of 2020-04-23).

package main

import (
	"log"
	"net"
	"net/http"
	"sync"
	"time"
)

const port = ":8081"

var wg sync.WaitGroup

func main() {
	go hastyHTTPServer()
	time.Sleep(100 * time.Millisecond)
	for i := 0; i < 2; i++ {
		wg.Add(1)
		go fetchLoop()
	}
	wg.Wait()
}

func fetchLoop() {
	for i := 0; i < 1e3; i++ {
		resp, err := http.Get("http://localhost" + port)
		if err != nil {
			log.Println(err)
			continue
		}
		resp.Body.Close()
	}
	wg.Done()
}

// hastyHTTPServer runs an HTTP server that sends a response and closes the
// connection as soon as a client makes a TCP connection, rather than waiting
// for the client to actually make an HTTP request.
// A real-world example of this type of server can be seen at 8849777.com
func hastyHTTPServer() {
	ln, err := net.Listen("tcp", port)
	if err != nil {
		log.Fatal(err)
	}
	for {
		conn, err := ln.Accept()
		if err != nil {
			log.Fatal(err)
		}
		go func() {
			conn.Write([]byte("HTTP/1.0 200 OK\r\n\r\nQuick response!"))
			conn.Close()
		}()
	}
}

The output is like below (the number of errors varies from run to run, but there's almost always at least one error):

$ go run hastyserver.go 
2020/04/23 16:26:37 Unsolicited response received on idle HTTP channel starting with "HTTP/1.0 200 OK\r\n\r\nQuick response!"; err=<nil>
2020/04/23 16:26:37 Get "http://localhost:8081": readLoopPeekFailLocked: <nil>
2020/04/23 16:26:37 Unsolicited response received on idle HTTP channel starting with "HTTP/1.0 200 OK\r\n\r\nQuick response!"; err=<nil>
2020/04/23 16:26:37 Get "http://localhost:8081": readLoopPeekFailLocked: <nil>
2020/04/23 16:26:37 Unsolicited response received on idle HTTP channel starting with "HTTP/1.0 200 OK\r\n\r\nQuick response!"; err=<nil>
2020/04/23 16:26:37 Get "http://localhost:8081": readLoopPeekFailLocked: <nil>

Expected behavior:

No errors output.

Additional detail:

This test case also reproduces when I set http.DisableKeepAlives, and when I set Connection:Close on the response from the hasty server. Also, each connection yields at most 1 HTTP response, so this is not really an issue about an unsolicited response on an idle channel as the message suggests, but seems like a race between roundTrip incrementing numExpectedResponses and readLoop checking whether numExpectedResponses is 0. I don't know this code very well but I wonder if it makes sense to treat every connection as starting with numExpectedResponses at 1?

I've tried to figure out whether hasty responses are allowed or disallowed by RFC 7230. The closest language I can find is:

HTTP only presumes a reliable
transport with in-order delivery of requests and the corresponding
in-order delivery of responses. The mapping of HTTP request and
response structures onto the data units of an underlying transport
protocol is outside the scope of this specification.

Which seems to implicitly allow them. At any rate it's not clear that it would be possible to consistently reject hasty responses, since there's an unavoidable network race between writing a request and reading a response. Given that, I think it probably makes sense to make the current behavior (accepting hasty responses) more consistent.

[jsha]

I can confirm that this patch, which starts persistConns with numExpectedResponses = 1, causes the repro code above to run without errors.

0001-Start-persistConns-with-numExpectedResponses-1.patch.txt

[qingyunha]

move <-pc.reqch to the front of Peek may solve this problem

--- net/http/transport.go.bk    2020-04-24 10:06:11.253338231 +0800
+++ net/http/transport.go       2020-04-24 10:07:03.676671394 +0800
@@ -1893,6 +1893,7 @@
 
        alive := true
        for alive {
+               rc := <-pc.reqch
                pc.readLimit = pc.maxHeaderResponseSize()
                _, err := pc.br.Peek(1)
 
@@ -1904,7 +1905,6 @@
                }
                pc.mu.Unlock()
 
-               rc := <-pc.reqch
                trace := httptrace.ContextClientTrace(rc.req.Context())
 
                var resp *Response