net/http: WriteTimeout times out writes before they're written

[WGH-]

(related to #21389)

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

I checked go version go1.10 linux/amd64 and go version go1.9.4 linux/amd64, which behave the same.

Does this issue reproduce with the latest release?

Yeah.

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/ubuntu/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/ubuntu/go"
GORACE=""
GOROOT="/usr/lib/go-1.10"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go-1.10/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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-build665138149=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I set WriteTimeout to some value, which was smaller than the time handler took to handle the request.

https://gist.github.com/WGH-/90bbfe656e63f6fa457db84f91384c41

curl '18.196.145.219:8080/foo?t=1.5s' -v

What did you expect to see?

Well, the documentation clearly states "It is reset whenever a new request's header is read.", after all. So strictly speaking, everything is working as intended.

However, I expected that WriteTimeout would only timeout write calls that're taking too long, or at least that it would start ticking at the first write. It would make much more sense this way.

What did you see instead?

As soon as server tries to write anything, even it hasn't written anything before, assuming timeout is passed, it will close the connection.

curl: (52) Empty reply from server

[WGH-]

This confusing behaviour is the underlying cause of some bug in Mattermost:
https://mattermost.atlassian.net/browse/MM-9692 mattermost/mattermost#8348

[andybons]

Since this is working as intended and documented as such, and changing the behavior will likely break code (which we can’t do due to the Go 1 compatibility promise), this looks like something to consider for Go2.

I’ll let @bradfitz weigh in on it.

[WGH-]

As of Go 1, perhaps, WriteTimeout needs a clearer description. Maybe it's just me, but not only I had to read it several times, but I also had to check the source code to ensure that I understood it correctly.

For reference, right now it's like this:

    // WriteTimeout is the maximum duration before timing out
    // writes of the response. It is reset whenever a new
    // request's header is read. Like ReadTimeout, it does not
    // let Handlers make decisions on a per-request basis.
    WriteTimeout time.Duration

[ianlancetaylor]

I think this code is working as documented, though no doubt the documentation could be improved. If you set a short timeout, that timeout applies. I can't tell precisely what different behavior you are after; perhaps using a context.Context would help here.

[ianlancetaylor]

CC @bradfitz

[WGH-]

I can't tell precisely what different behavior you are after

Judging from WriteTimeout name alone, one would expect that timeout applies either to each Write separately or to writing response as a whole. However, WriteTimeout in fact imposes combined limit on reading request body, processing it (e.g. executing DB queries), and writing the response.

Moreover, even if WriteTimeout is hit during "request processing", it won't be detected until after request is completely processed (e.g. all DB queries are executed), and attempt to write the response is made. Like context.Context, WriteTimeout effectively "aborts" long requests, howeverer, unlike context.Context, it does so in rather ineffective way, i.e. it only prevents response from being written.

So, in my opinion, there're three related, but separate issues:

• Current behaviour is questionable due to issues with requests taking too long (described above).
• Variable name is somewhat misleading.
• Documentation is somewhat vague.

As of documentation, Mattermost configuration page has this clear and accurate description what WriteTimeout actually does: "this is the maximum time allowed from the end of reading the request headers until the response is written." I like its wording.

[bradfitz]

We can update docs if you have a suggestion for what would clarify it, but like others said, we can't change behavior here.

The real feature request bug that people are interested in is #16100, to manipulating timeouts within a Handler.