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: ResponseWriter.Write does not error after WriteTimeout nor is ErrorLog used #21389

Open
djui opened this issue Aug 10, 2017 · 14 comments · May be fixed by #52920
Open

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

djui opened this issue Aug 10, 2017 · 14 comments · May be fixed by #52920
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@djui
Copy link

djui commented Aug 10, 2017

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

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.

@tombergan tombergan added this to the Go1.10 milestone Aug 15, 2017
@djui djui changed the title http.Server.ResponseWriter.Write attempts do not error after http.Server.WriteTimeout nor is http.Server.ErrorLog used http.Server.ResponseWriter.Write does not error after http.Server.WriteTimeout nor is http.Server.ErrorLog used Aug 16, 2017
@djui djui changed the title http.Server.ResponseWriter.Write does not error after http.Server.WriteTimeout nor is http.Server.ErrorLog used ResponseWriter.Write does not error after WriteTimeout nor is ErrorLog used Aug 16, 2017
@djui
Copy link
Author

djui commented Aug 16, 2017

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

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

djui commented Aug 17, 2017

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.

@dsnet dsnet changed the title ResponseWriter.Write does not error after WriteTimeout nor is ErrorLog used net/http: ResponseWriter.Write does not error after WriteTimeout nor is ErrorLog used Aug 22, 2017
@tombergan
Copy link
Contributor

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

bradfitz commented Dec 4, 2017

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.

@bradfitz bradfitz added the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Dec 4, 2017
@bradfitz bradfitz modified the milestones: Go1.10, Go1.11 Dec 4, 2017
@bradfitz bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Jul 2, 2018
@bradfitz bradfitz modified the milestones: Go1.11, Go1.12 Jul 2, 2018
@gopherbot gopherbot removed the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Jul 2, 2018
@agnivade
Copy link
Contributor

@tombergan - Did you get a chance to look at this ?

@neild
Copy link
Contributor

neild commented Jul 20, 2021

(Comment started on #47229, moved here because I realized that was a duplicate of this one.)

The Write method does not return an error in this case because the write is to a *bufio.Writer, and errors writing to the underlying connection will not be detected until the buffer fills. It would be nice if we could immediately report errors in this case.

Server behavior when WriteTimeout is exceeded varies with HTTP/1 and HTTP/2.

For HTTP/1, WriteTimeout sets the write deadline on the connection at the start of handling a request. There isn't any particular handling of the case where the deadline is exceeded (so far as I can tell), so if the deadline passes the server will not respond. This does not seem useful.

For HTTP/2, WriteTimeout sets a timer which causes the response stream to be closed with a status of INTERNAL_ERROR when the deadline passes.

Responding to the client immediately upon passing the write timeout (even if only by closing the connection or stream) seems reasonable. The fact that we do this for HTTP/2 seems to indicate that doing the same for HTTP/1 is acceptable.

@mitar
Copy link
Contributor

mitar commented Oct 21, 2021

So while we wait for "perfect" solution, could we in meantime do the point 2) above: logging using http.Server.ErrorLog? We just recently had a long debugging session when our requests for one reason started taking longer to handle and then nothing was being returned to the clients. We thought first it is CloudFlare protection, then reverse proxy, Go code was saying that handler successfully completed. Only later we remembered to check timeouts. So us storing all server error logs didn't help us catch this.

So I would request that timeout is simply logged to the error log for now. How to surface that to the caller seems to be a much more complicated issue (and frankly, I have seen too much code doing _, _ := w.Write(...) to believe anyone is checking return errors there anyway).

@mvrhov
Copy link

mvrhov commented Mar 14, 2022

I have also lost several days while trying to debug this on code I have not wrote and had no idea, that the http server had a WriteTimout set. The main problem was that it also looked, like everything is ok from the logs.

johanneswuerbach added a commit to johanneswuerbach/go that referenced this issue May 16, 2022
Calling Write on a response now returns an error if the call happened
after the configured server WriteTimeout.

Fixes golang#21389
johanneswuerbach added a commit to johanneswuerbach/go that referenced this issue May 16, 2022
response.Write now returns an error if the called happened after
the configured server WriteTimeout.

Fixes golang#21389
@gopherbot
Copy link

Change https://go.dev/cl/406554 mentions this issue: net/http: return an error if Write is called after WriteTimeout

@mpl
Copy link
Contributor

mpl commented Jul 22, 2022

(Comment started on #47229, moved here because I realized that was a duplicate of this one.)

The Write method does not return an error in this case because the write is to a *bufio.Writer, and errors writing to the underlying connection will not be detected until the buffer fills. It would be nice if we could immediately report errors in this case.

Server behavior when WriteTimeout is exceeded varies with HTTP/1 and HTTP/2.

For HTTP/1, WriteTimeout sets the write deadline on the connection at the start of handling a request. There isn't any particular handling of the case where the deadline is exceeded (so far as I can tell), so if the deadline passes the server will not respond. This does not seem useful.

For HTTP/2, WriteTimeout sets a timer which causes the response stream to be closed with a status of INTERNAL_ERROR when the deadline passes.

Responding to the client immediately upon passing the write timeout (even if only by closing the connection or stream) seems reasonable. The fact that we do this for HTTP/2 seems to indicate that doing the same for HTTP/1 is acceptable.

Hello @neild ,

I was about to open an issue about the fact that a reverse-proxy with a WriteTimeout behave differently on HTTP/1 and on HTTP/2 (because the RoundTrip is eventually cancelled only in the case of HTTP/2, for the reasons you state above). This is why we have traefik/traefik#9191
It can be demonstrated trivially with something like:

package main

import (
	"log"
	"net/http"
	"net/http/httputil"
	"net/url"
	"time"
)

func main() {
	// docker run -p 6060:80 traefik/whoami
	dest, err := url.Parse("http://localhost:6060")
	if err != nil {
		log.Fatal(err)
	}
	next := httputil.NewSingleHostReverseProxy(dest)
	next.ErrorHandler = func(w http.ResponseWriter, request *http.Request, err error) {
		println("ROUNDTRIP ERROR")
		w.WriteHeader(http.StatusInternalServerError)
		w.Write([]byte("500"))
	}
	s := &http.Server{
		Addr:         ":80",
		Handler:      next,
		WriteTimeout: 3 * time.Second,
	}
	log.Fatal(s.ListenAndServeTLS("cert.pem", "key.pem"))
}

Can I consider that this here issue #21389 is indeed the same problem and just track it, or should I open a new issue?

@neild
Copy link
Contributor

neild commented Jul 22, 2022

@mpl Yeah, that sounds like the same problem to me. No need for a new issue.

johanneswuerbach added a commit to johanneswuerbach/go that referenced this issue Sep 5, 2022
response.Write now returns an error if the called happened after
the configured server WriteTimeout.

Fixes golang#21389
johanneswuerbach added a commit to johanneswuerbach/go that referenced this issue Sep 16, 2022
response.Write now returns an error if the called happened after
the configured server WriteTimeout.

Fixes golang#21389
@mitar
Copy link
Contributor

mitar commented Oct 22, 2023

Maybe w.Success() error method should be added, which you can call inside your http handler to:

  • Block until all writes have flushed.
  • If writing failed, or timeout happened, it returns an error.

So it would allow one to opt-in in checking that writes succeeded.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

Successfully merging a pull request may close this issue.