net/http: Read deadline and hijack conflict ? (regression in 1.8)

[vadmeste]

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

go version go1.8.3 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/vadmeste/work/gospace"
GORACE=""
GOROOT="/home/vadmeste/work/go"
GOTOOLDIR="/home/vadmeste/work/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build477756641=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

1. I ran the following http server: https://play.golang.org/p/AzKdcy-k05 in my local machine
2. curl http://localhost:1234 in a separate terminal

What did you expect to see?

curl http://localhost:1234 returns text immediately

What did you see instead?

curl http://localhost:1234 returns text after 5 secondes

More explanation:

The code represents a simple http server, with a customized net.Conn which set deadline on Read().
The http server has a handler which hijacks the connection and returns some text. However, running curl http://localhost:1234 doesn't return only after 5 seconds (which is the read timeout value).

** The code works with go 1.7.6 but doesn't with go 1.8.3 **

It looks like this commit causes the problem: faf882d

[bradfitz]

Go 1.9rc1 is due out imminently, which means the time to report issues with Go 1.8 was about 7-9 months ago. I suggest you try out Go 1.9 and report any bugs you find before it's too late for Go 1.9.

Go 1.8 documented:

https://golang.org/doc/go1.8#net_http

The Context returned by Request.Context is canceled if the underlying net.Conn closes. For instance, if the user closes their browser in the middle of a slow request, the Handler can now detect that the user is gone. This complements the existing CloseNotifier support. This functionality requires that the underlying net.Conn implements recently clarified interface documentation.

And https://golang.org/doc/go1.8#net

The Conn documentation has been updated to clarify expectations of an interface implementation. Updates in the net/http packages depend on implementations obeying the documentation.

Updating: implementations of the Conn interface should verify they implement the documented semantics. The golang.org/x/net/nettest package will exercise a Conn and validate it behaves properly.

But your net.Conn implementation looks fine, so I think this is actually a bug in net/http, but it's too late to fix for Go 1.9, so I'l target this at Go 1.10.

Using the modified program https://play.golang.org/p/eRBx-bv4Rr with more logging against Go 1.7 vs Go 1.8:

bradfitz@gdev:~$ GOROOT=$HOME/go1.7 go run hijack.go
2017/07/23 16:39:47 Fetching...
2017/07/23 16:39:47 Conn.Read(4096) ...
2017/07/23 16:39:47 Conn.Read = 96, <nil>
2017/07/23 16:39:47 in Handler.
2017/07/23 16:39:47 Got: &{200 Connected 200 HTTP/1.0 1 0 map[] 0xc4200f4100 -1 [] true false map[] 0xc4200d40f0 <nil>}, <nil>
HTTP/1.0 200 Connected
Connection: close

And Go 1.8:

bradfitz@gdev:~$ GOROOT=$HOME/go1.8 go run hijack.go
2017/07/23 16:39:51 Fetching...
2017/07/23 16:39:51 SetReadDeadline(off)
2017/07/23 16:39:51 Conn.Read(4096) ...
2017/07/23 16:39:51 Conn.Read = 96, <nil>
2017/07/23 16:39:51 SetReadDeadline(off)
2017/07/23 16:39:51 in Handler.
2017/07/23 16:39:51 SetReadDeadline(-352054h39m51.732834171s)
2017/07/23 16:39:51 Conn.Read(1) ...
2017/07/23 16:39:56 Conn.Read = 0, read tcp 127.0.0.1:42428->127.0.0.1:37735: i/o timeout
2017/07/23 16:39:56 SetReadDeadline(off)
2017/07/23 16:39:56 Got: &{200 Connected 200 HTTP/1.0 1 0 map[] 0xc4200184c0 -1 [] true false map[] 0xc42000a800 <nil>}, <nil>
HTTP/1.0 200 Connected
Connection: close

random data

What happens in Go 1.8 is that the Hijack call calls SetReadDeadline(aLongTimeAgo) to interrupt any currently-blocked net.Conn.Read call or any soon-to-be-called net.Conn.Read 1 byte read.

But this net.Conn implementation in its Read method unconditionally calls SetReadDeadline itself, extending it from aLongTimeAgo (1 second after Unix time began) to 5 seconds from current time.

As a workaround, you could make your net.Conn type implement SetReadDeadline itself and track whether it's in aLongTimeAgo mode (I'd just check for any deadline before current time) and if so, don't do your own extensions.

I'll have to think about how to fix this in Go. Too bad we don't have context support in io.Reader. The the Hijack could've just canceled the context of the background 1 byte read, not affecting other deadlines.

/cc @tombergan

[bradfitz]

Btw, the workaround would look like:

// timeoutableConn
type timeoutableConn struct {
	net.Conn
	hadReadDeadlineInPast int32 // atomic
}

func (c *timeoutableConn) Read(b []byte) (n int, err error) {
	if atomic.LoadInt32(&c.hadReadDeadlineInPast) != 1 {
		c.Conn.SetReadDeadline(time.Now().Add(5 * time.Second))
	}
	return c.Conn.Read(b)
}

func (c *timeoutableConn) SetReadDeadline(t time.Time) error {
	inPast := int32(0)
	if t.Before(time.Now()) {
		inPast = 1
	}
	atomic.StoreInt32(&c.hadReadDeadlineInPast, inPast)
	return c.Conn.SetReadDeadline(t)
}

I've verified that successfully works around this.

[vadmeste]

@bradfitz, thanks. It also works for me. I appreciate you suggesting the workaround.