net/http: ReadTimeout is not honored when ReadHeaderTimeout > ReadTimeout

[james-johnston-thumbtack]

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

$ go version
go version go1.13.4 linux/amd64

Does this issue reproduce with the latest release?

It should.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
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-build860032074=/tmp/go-build -gno-record-gcc-switches"

What did you do?

The following simple program runs a Hello World HTTP server with 5 second ReadTimeout and 10 second ReadHeaderTimeout.

package main

import (
	"fmt"
	"net/http"
	"time"
)

func main() {
	http.HandleFunc("/", HelloServer)
	server := &http.Server{
		Addr:              ":1234",
		ReadHeaderTimeout: 10 * time.Second,
		ReadTimeout:       5 * time.Second,
	}
	server.ListenAndServe()
}

func HelloServer(w http.ResponseWriter, r *http.Request) {
	fmt.Fprintf(w, "Hello, %s!", r.URL.Path[1:])
}

Start the server. Now, test the timeouts by connecting as a client as follows, where nc is the netcat program. The client initiates a connection but never sends any bytes containing request headers.

jamesjohnston-mac:website jamesjohnston$ time nc localhost 1234

real	0m10.019s
user	0m0.005s
sys	0m0.010s

What did you expect to see?

The connection should time out after 5 seconds. The documentation for ReadTimeout states the following:

	// ReadTimeout is the maximum duration for reading the entire
	// request, including the body.

Since headers are part of the request, we'd also expect this timeout to apply to headers as well.

What did you see instead?

The connection timed out after 10 seconds, not 5 seconds.

NOTE: If we instead did an HTTP POST with a request body included, and then sent the full request (headers+body) in the time between 5 and 10 seconds (with a flush on network connection after sending all headers and before the body), then we would find that the headers would be successfully received by server but then the body would instantly time out when trying to read it. I struggle to see how this would be of any use in the real world, especially seeing as how ServeHTTP cannot adjust read timeouts/deadlines - i.e. lengthen them to something that isn't timing out immediately. (see #16100 )

Suggested action items

I do not know what the actual intended behavior the maintainers of the http package wish to have. It seems to me there are two options to resolve this contradiction:

• Update documentation to reflect actual behavior. For example, update comment on ReadTimeout to look something like:

	// ReadTimeout is the maximum duration for reading the entire
	// request, including the body.  As an exception, if
	// ReadHeaderTimeout > ReadTimeout, then ReadHeaderTimeout will
	// apply for reading the header portion of the request, but then the
	// request body will immediately time out when attempting to read it if
	// the ReadTimeout deadline has already elapsed.

• Update code to match current documented behavior. For example, update

  go/src/net/http/server.go

  Line 946 in 440f7d6

  t0 := time.Now()

  to look something like:

	t0 := time.Now()
	if d := c.server.readHeaderTimeout(); d != 0 {
		hdrDeadline = t0.Add(d)
	}
	if d := c.server.ReadTimeout; d != 0 {
		wholeReqDeadline = t0.Add(d)
	}
	// New: Enforce hdrDeadline <= wholeReqDeadline
	// (Not shown: logic to deal with infinite ReadHeaderTimeout and/or ReadTimeout
	if wholeReqDeadline.Before(hdrDeadline) {
		hdrDeadline = wholeReqDeadline
	}

[fraenkel]

Changing this behavior could break applications.
The current behavior is the requestTimeout = readHeaderTimeout + readTimeout.
It would be safer to just adjust the documentation to match the behavior.

[james-johnston-thumbtack]

The current behavior is the requestTimeout = readHeaderTimeout + readTimeout

@fraenkel I think that isn't true either... I actually assumed as you that this was the case, and tried to use a ReadHeaderTimeout > ReadTimeout in my application. But it turns out it's actually not, and having such a relationship shows an interesting behavior. Observe the following if we alter the example to read:

func HelloServer(w http.ResponseWriter, r *http.Request) {
	fmt.Fprintf(w, "serving endpoint %v\n", r.URL.Path[1:])
	body, err := ioutil.ReadAll(r.Body)
	if err != nil {
		fmt.Fprintf(w, "while reading body: %v", err)
	} else {
		fmt.Fprintf(w, "Hello, %s!", string(body))
	}
}

Then create the following shell script with a client payload:

#!/bin/bash

sleep 7
echo POST /myroute HTTP/1.1
echo Host: localhost
echo Content-Length: 5
echo
sleep 0.1 # Required in order to defeat buffering and flush headers in a separate packet
echo James

And run it:

$ time ./testreq.sh | nc localhost 1234
HTTP/1.1 200 OK
Date: Sun, 17 Nov 2019 18:51:36 GMT
Content-Length: 90
Content-Type: text/plain; charset=utf-8
Connection: close

serving endpoint myroute
while reading body: read tcp [::1]:1234->[::1]:63741: i/o timeout
real	0m7.130s
user	0m0.009s
sys	0m0.015s

The server happily waits up to ReadHeaderTimeout for headers, but after getting them, if ReadTimeout is elapsed, it instantly times out the request when trying to read the body. (Note therefore that it doesn't affect GET requests where there's no body.) It seems like kind of a useless behavior in real life, and therefore an error for anyone to ever be setting ReadHeaderTimeout > ReadTimeout.

I accidentally set ReadHeaderTimeout > ReadTimeout in my application because ReadHeaderTimeout documentation says:

	// ReadHeaderTimeout is the amount of time allowed to read
	// request headers. The connection's read deadline is reset
	// after reading the headers and the Handler can decide what
	// is considered too slow for the body.

The question is: the read deadline is reset to what? I assumed it would be reset to a new deadline based off of whenever the headers had stopped reading. i.e. that something sensible would happen when ReadHeaderTimeout > ReadTimeout. For example, reset deadline to timeHeadersWereReceived + ReadTimeout. But it turns out that it is reset to timeConnectionWasOpened + ReadTimeout and if more than ReadTimeout has already elapsed, then the connection will instantly time out at the moment we transition from headers to body.

I think that documentation could also use clarification to indicate what value the read deadline is reset to, and then explicitly call out this interesting behavior as a warning.

[fraenkel]

Sorry I should have been more clear. I dont think the current behavior is valuable given what I would have expected the proper behavior to be.

If there is no ReadHeaderTimeout, the request timeout is exactly the read timeout. If there is a ReadHeaderTimeout set, the headers must be read within that timeout window, but the request timeout is the remaining amount given the sum of ReadHeaderTimeout + ReadTimeout.
Personally I would have preferred the ReadHeaderTimeout when set to only govern the header part and allow the ReadTimeout to be the rest. But now the remainder is carried over.

What you see above seems correct to me. The header timeout expired and so does the request. For a GET request, having this split timeout doesn't make much sense given there is usually no body. It would have been useful if the timeouts were disconnected so one could guarantee headers are read within time X and bodies within time Y.

I guess if one looks at the current ReadHeaderTimeout usage, we could determine if changing the behavior affects people and whether it would be for the better.

[andybons]

@bradfitz @mikioh