net/http: ResponseWriter.Write does not error after WriteTimeout nor is ErrorLog used

[djui]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.8.3 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/uwe/dev/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.8.3/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.8.3/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/p2/0p6x8w350vqgpvfby6wnxnhc0000gn/T/go-build935868292=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
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?

https://play.golang.org/p/pwjZmMKleR

Create a HTTP server with a WriteTimeout = 1 * time.Second and a HTTPHandler with an artificial time.Sleep(2 * time.Second) and then writing out some bytes. Then start the server and run a request against this handler.

What did you expect to see?

Writing a response after hitting WriteTimeout should at least do one out of the two options:

1. Return an error for n, err := w.Write()
2. Log a message to http.Server.ErrorLog

(1) would indicate that no more bytes can be written, e.g. because the connection was closed.

(2) would be similar to w.conn.server.logf("http: multiple response.WriteHeader calls"), e.g. w.conn.server.logf("http: write attempt after write timeout").

What did you see instead?

Neither (1) nor (2) happened.

This was confusing as I saw in my http logging middleware that response bytes have been written, but I did not understand to where/which connection; which was hard to debug.

While trying to understand how WriteTimeout works it seems that the http server's ResponseWriter is not aware of the consequences. But I would like to discuss if there are options to improve the situation/inform the user.

An example of the observed consequences with WriteTimeout set to 3 * time.Second on e.g. Heroku:

Aug 07 12:16:48 {"level":"info","ts":1502108208.0430696,"caller":"middleware/logger.go:91","msg":"Outgoing response","request_id":"a8fe82a0-c212-4527-9cae-06e38cf46d49","status":200,"latency":9.043189693,"bytes_out":97} 
Aug 07 12:16:48 heroku/router:  at=error code=H13 desc="Connection closed without response" method=GET path="/foo" host=bar request_id=a8fe82a0-c212-4527-9cae-06e38cf46d49 fwd="54.216.3.69" dyno=web.1 connect=0ms service=9044ms status=503 bytes=0 protocol=https

[tombergan]

I believe this happens because of buffering inside net/http.Server. Replace "hello" with bytes.Repeat([]byte("x"), 3965) and the server sees a write error. Use 3964 instead and the server does not see a write error. The ResponseWriter uses a 4096 byte buffer. I'd bet that 4096 - 3964 = 132 is the number of bytes in the HTTP status line plus response headers, but I have not verified.

Would you consider this a dup of #18997, or perhaps blocked on #18997? We cannot easily make Write fail without removing the buffer. I also think this would be too spammy for w.conn.server.logf. However, this looks like something we could expose easily with httptrace.

[djui]

It seems your assumption about buffering is right. Also the 132 bytes map exactly to the chunked encoded header length. I can also see the error write tcp 127.0.0.1:2->127.0.0.1:3: i/o timeout then. I think this relates to #8534 as, if I use server.ConnState I can see the connection going to StateClosed. What I do not understand yet, is how this change won't report the error given the comment: 5. checkConnErrorWriter{c}, which notes any non-nil error on Write and populates c.werr with it if so. Is it that c.werr then itself is swallowed or can't be accessed?

I think being able to inspect this scenario via a server httptrace #18997 could help debugging this, but eventually having buffered Write() returning the actual error would be better.

[tombergan]

Write cannot return the actual error without getting rid of the internal buffering, because the error is not learned until we try to flush the buffer.

[djui]

I understand. Can’t I force to flush? Me as the handler implementor know when I am done writing my response, this handler could then call flush on the underlying buffer or TCPConn. However I believe I can’t get a handle on neither. And even if I could flush, shouldn’t flush then force a write out and that should cause an error which in turn should then be reported somewhere?
I still do not understand where in the standard library the error occurs, after the buffer is flushed and everything buffered should have been written, and why it’s neither handled nor reported.

[tombergan]

And even if I could flush, shouldn’t flush then force a write out and that should cause an error which in turn should then be reported somewhere?

You can flush: the default http.ResponseWriter implements http.Flusher:
https://golang.org/pkg/net/http/#Flusher

You would call Flush() after Write(), and the error would happen during your call to Flush(). However, Flush() does not return an error, so you cannot tell if the flush succeeded. This makes me sad and was likely an oversight when Flush() was added.

why it’s neither handled nor reported.

The flush error is not reported because it happens asynchronously to any user calls so there's no place to report it (at least not until there is a server httptrace). What did you mean by "handled"? net/http does detect the error and stops using the connection, so in that sense the error is "handled".

I think the best solution I can offer right now is #18997. I would like to add an error to Flush(), but we cannot do that without breaking backwards compatibility. Happy to hear other ideas though if someone has them.

[bradfitz]

We could start a timer at the beginning of the request to fire at WriteTimeout and cause the ResponseWriter to return Write errors, regardless of buffering status. That work, @tombergan?

Too late for Go 1.10, though. Just found this while cleaning up bugs. It had arrived while I was out on leave.