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: ReadTimeout is not honored when ReadHeaderTimeout > ReadTimeout #35626

Open
james-johnston-thumbtack opened this issue Nov 15, 2019 · 4 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@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.
	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
	}
@bradfitz bradfitz changed the title ReadTimeout is not honored when ReadHeaderTimeout > ReadTimeout net/http: ReadTimeout is not honored when ReadHeaderTimeout > ReadTimeout Nov 16, 2019
@fraenkel
Copy link
Contributor

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.

@golang golang deleted a comment Nov 17, 2019
@james-johnston-thumbtack
Copy link
Author

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

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 andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 18, 2019
@andybons andybons added this to the Unplanned milestone Nov 18, 2019
@andybons
Copy link
Member

@bradfitz @mikioh

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

3 participants