net/http: WriteTimeout not reset in http2

[pnelson]

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

$ go version
go version go1.8beta2 linux/amd64

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

Ubuntu 16.04 amd64

$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/pnelson"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build506631447=/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?

I wrote a simple HTTP/2 server with a WriteTimeout set to reproduce.

https://github.com/pnelson/go-timeouts-test

Using a load testing tool for 5 seconds yields latencies to the point of client timeout. Also reproducible in browser by refreshing the page a few times.

What did you expect to see?

Request latency to be well under 2s.

What did you see instead?

Request latency greater than 30s (client timeout) after a few requests from the same client, presumably due to connection reuse and timeout not being reset.

This sounds a bit similar to an older issue with ReadTimeout, #16450.

[vcabbage]

@pnelson and I chatted about this issue on Slack. As far as I can tell, HTTP1 write deadlines are reset here, but since HTTP2 takes a different path the deadline is never reset.

The patch below resolved the issue for me. (It may well not be the correct fix, but I think it narrows down the issue.)

index 2e0b3c905a..c9aa12948f 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -4323,6 +4323,9 @@ func (sc *http2serverConn) processHeaders(f *http2MetaHeadersFrame) error {
        if sc.hs.ReadTimeout != 0 {
                sc.conn.SetReadDeadline(time.Time{})
        }
+       if sc.hs.WriteTimeout != 0 {
+               sc.conn.SetWriteDeadline(time.Now().Add(sc.hs.WriteTimeout))
+       }

        go sc.runHandler(rw, req, handler)
        return nil

[vcabbage]

@pnelson and I chatted about this issue on Slack. As far as I can tell, HTTP1 write deadlines are reset here, but since HTTP2 takes a different path the deadline is never reset.

The patch below resolved the issue for me. (It may well not be the correct fix, but I think it narrows down the issue.)

index 2e0b3c905a..c9aa12948f 100644
--- a/src/net/http/h2_bundle.go
+++ b/src/net/http/h2_bundle.go
@@ -4323,6 +4323,9 @@ func (sc *http2serverConn) processHeaders(f *http2MetaHeadersFrame) error {
        if sc.hs.ReadTimeout != 0 {
                sc.conn.SetReadDeadline(time.Time{})
        }
+       if sc.hs.WriteTimeout != 0 {
+               sc.conn.SetWriteDeadline(time.Now().Add(sc.hs.WriteTimeout))
+       }

        go sc.runHandler(rw, req, handler)
        return nil

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[gopherbot]

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

[rsc]

@bradfitz, should this be closed?

[rsc]

@bradfitz, should this be closed?

[bradfitz]

No, it should be fixed properly later. There's a pending CL for 1.9 to respect the field. Currently the submitted workaround just makes the field ignored for 1.8.

[bradfitz]

No, it should be fixed properly later. There's a pending CL for 1.9 to respect the field. Currently the submitted workaround just makes the field ignored for 1.8.

[gopherbot]

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

[gopherbot]

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