Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
vadmeste opened this issue Jul 23, 2017 · 7 comments
Closed

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

vadmeste opened this issue Jul 23, 2017 · 7 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@vadmeste
Copy link

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
Copy link
Contributor

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 bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Jul 23, 2017
@bradfitz bradfitz added this to the Go1.10 milestone Jul 23, 2017
@bradfitz
Copy link
Contributor

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 added a commit to vadmeste/minio that referenced this issue Jul 24, 2017
vadmeste added a commit to vadmeste/minio that referenced this issue Jul 24, 2017
vadmeste added a commit to vadmeste/minio that referenced this issue Jul 24, 2017
vadmeste added a commit to vadmeste/minio that referenced this issue Jul 24, 2017
This is a workaround for this golang bug
golang/go#21133
vadmeste added a commit to vadmeste/minio that referenced this issue Jul 31, 2017
There is no way to have a transparent QuirkConn which provides a
workaround of this golang/go#21133, the easiest way is to expose
canSetReadDeadline() API to test if we are allowed to call
SetReadDealine API without triggering the golang issue.
vadmeste added a commit to vadmeste/minio that referenced this issue Aug 3, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
vadmeste added a commit to vadmeste/minio that referenced this issue Aug 3, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
vadmeste added a commit to vadmeste/minio that referenced this issue Aug 3, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
@vadmeste
Copy link
Author

vadmeste commented Aug 3, 2017

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

vadmeste added a commit to vadmeste/minio that referenced this issue Aug 4, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
vadmeste added a commit to vadmeste/minio that referenced this issue Aug 5, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
vadmeste added a commit to vadmeste/minio that referenced this issue Aug 6, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
harshavardhana pushed a commit to minio/minio that referenced this issue Aug 6, 2017
QuirkConn is added to replace net.Conn as a workaround to a golang bug:
golang/go#21133
@gopherbot
Copy link

Change https://golang.org/cl/62610 mentions this issue: net/http: avoid locking by using goroutine

@namusyaka
Copy link
Member

@tombergan Could you take a look at the CL?

@rsc
Copy link
Contributor

rsc commented Nov 22, 2017

Not convinced this is a bug in net/http. Hijack is not the only code being broken by this Conn implementation. Conn clients also expect that:

conn.SetReadDeadline(time.Now().Add(30*time.Second))
readHeader(conn)

will not read for more than 30 seconds. But this Conn implementation keeps bumping the deadline forward on every read, so as long as the header is coming in 1 byte every 4.9s, the readHeader could go on forever.

If a Conn.Read is going to change the timeout, presumably to keep Read from blocking for too long, it should still use the min of whatever timeout it wants to impose and any previously-set deadline.

I would be in favor of simply closing this bug.

Moving to Go 1.11 in any event but feel free to close, @tombergan or @bradfitz, if you agree with the rationale here.

@rsc rsc modified the milestones: Go1.10, Go1.11 Nov 22, 2017
@bradfitz
Copy link
Contributor

Agreed, will close. We've gone two releases so far with the Conn requirements spelled out in docs and net/http strictly depending on, and we've had minimum fallout, and most custom Conns have simply fixed their implementations given the new docs.

@golang golang locked and limited conversation to collaborators Nov 22, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

6 participants