net/http Server WriteTimeout doesn't work as expected

[Thorsten von Eicken]

I'm having trouble using net/http's WriteTimeout in Go1.3 on ubuntu 12.04 and 14.04. The short is that if I set a WriteTimeout to N seconds and I run a handler that takes more than N seconds then the response is never written to the socket and the socket hangs. I see issue https://code.google.com/p/go/issues/detail?id=6410 and I can add the samples below to it, if what I'm observing is the same problem and a valid problem...

Here's my expectation of what ReadTimeout and WriteTimeout should do. If I'm misguided, obviously the examples below may not apply...

• ReadTimeout: when net/http.Server is actively reading the next request from the socket it times out if the read doesn't complete within the timeout
  
• WriteTimeout: when net/http.ResponseWriter is trying to write something to the socket and the write doesn't complete or doesn't manage to write at least one byte within the WriteTimeout
• If there is no read or no write pending then the respective timeouts should not apply

This is the test program I used to narrow down the problem. Basically it sets ReadTimeout and WriteTimeout per the command line flags, and starts an http server that has a single handler that responds with "Hello World" after 10 seconds.

package main

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

var r *int = flag.Int("r", 0, "read timeout")
var w *int = flag.Int("w", 0, "write timeout")

func main() {
        flag.Parse()
        http.HandleFunc("/", slashHandler)
        server := http.Server{
                Addr:         ":8123",
                ReadTimeout:  time.Duration(*r) * time.Second,
                WriteTimeout: time.Duration(*w) * time.Second,
        }
        fmt.Printf("Read timeout: %ds, write timeout: %ds\n", *r, *w)
        server.ListenAndServe()
}

func slashHandler(w http.ResponseWriter, r *http.Request) {
        time.Sleep(10 * time.Second)
        w.Write([]byte("Hello world!\n"))
}

Test case #1 no timeouts:

$ go run timeouttest.go & sleep 1; time curl -v http://localhost:8123/; kill %+
[1] 30352
Read timeout: 0s, write timeout: 0s
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8123 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost:8123
> Accept: */*
>
< HTTP/1.1 200 OK
< Date: Thu, 14 Aug 2014 20:00:44 GMT
< Content-Length: 13
< Content-Type: text/plain; charset=utf-8
<
Hello world!
* Connection #0 to host localhost left intact

real    0m10.014s
user    0m0.006s
sys     0m0.004s

Works as expected: curl gets the response after 10 seconds.

Test case #2 read and write timeouts:

$ go run timeouttest.go -r 2 -w 2 & sleep 1; time curl -v http://localhost:8123/; kill %+
Read timeout: 2s, write timeout: 2s
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8123 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost:8123
> Accept: */*
>
* Empty reply from server
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server

real    0m12.013s
user    0m0.006s
sys     0m0.004s

My interpretation of the 12s delay is that Go thinks it responded after 10 seconds (but didn't) and then times out the next request after 2 additional seconds. Bug: Empty reply from server.

Test case #3 write timeout:

$ go run timeouttest.go -w 2 & sleep 1; time curl -v http://localhost:8123/; kill %+
[3] 30416
Read timeout: 0s, write timeout: 2s
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8123 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost:8123
> Accept: */*
>
^C
real    0m38.046s
user    0m0.006s
sys     0m0.004s

Bug: the response after 10 seconds is never written to the socket, I had to kill curl (see timestamp).

Test case #4: read timeout:

$ go run timeouttest.go -r 2 & sleep 1; time curl -v http://localhost:8123/; kill %+
[4] 30482
Read timeout: 2s, write timeout: 0s
* Hostname was NOT found in DNS cache

*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8123 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost:8123
> Accept: */*
>
^C
real    0m40.855s
user    0m0.006s
sys     0m0.004s

Similar effect to #3; I had expected to see the read timeout hit after 12 seconds like #2.

[James Bardin]

On Thursday, August 14, 2014 4:24:45 PM UTC-4, Thorsten von Eicken wrote:

I'm having trouble using net/http's WriteTimeout in Go1.3 on ubuntu 12.04 and 14.04. The short is that if I set a WriteTimeout to N seconds and I run a handler that takes more than N seconds then the response is never written to the socket and the socket hangs. I see issue https://code.google.com/p/go/issues/detail?id=6410 and I can add the samples below to it, if what I'm observing is the same problem and a valid problem...

Here's my expectation of what ReadTimeout and WriteTimeout should do. If I'm misguided, obviously the examples below may not apply...

• ReadTimeout: when net/http.Server is actively reading the next request from the socket it times out if the read doesn't complete within the timeout
  
• WriteTimeout: when net/http.ResponseWriter is trying to write something to the socket and the write doesn't complete or doesn't manage to write at least one byte within the WriteTimeout
• If there is no read or no write pending then the respective timeouts should not apply

I think this last statement is where you're going wrong. These are "Timeout if it's convenient" settings, these are hard deadlines set on the underlying network connection, which has no knowledge of your HTTP session. Once the deadline is reached, all further reads or writes fail. These are doing exactly what they're supposed to be doing.

In order to get the behavior you want, you need to do your timeout in the handler itself, which is what http.TimeoutHandler is for. That bug report is confusing multiple issues between TimeoutHandler the underlying network timeouts, and how the headers are written. I'm not sure if there's any actual bug other than possibly improving the documentation.

[James Bardin]

On Thursday, August 14, 2014 5:15:36 PM UTC-4, James Bardin wrote:

I think this last statement is where you're going wrong. These are "Timeout if it's convenient" settings, 

Sorry, of course that should have read 'These are not "Timeout if it's convenient" settings,` 

[Thorsten von Eicken]

In order to get the behavior you want, you need to do your timeout in the handler itself, which is what http.TimeoutHandler is for. 

I'm not looking for a timeout for my handler. What I'm looking for is a timeout for connections that don't make progress outside of my handler. E.g.:

• The connection is idle forever, I'd like it to be reaped at some point so these don't build up
• The client sent a partial request and then stalls forever
• The client is not consuming the response

In my book these are all cases that can end up in a build-up of used file descriptors due to malicious as well as error cases. I was expecting ReadTimeout and WriteTimeout to handle these. They evidently don't do that cleanly, is there any other way to handle these cleanly?

[Thorsten von Eicken]

I think this last statement is where you're going wrong. These are "Timeout if it's convenient" settings, these are hard deadlines set on the underlying network connection, which has no knowledge of your HTTP session. Once the deadline is reached, all further reads or writes fail. These are doing exactly what they're supposed to be doing.

Can you explain what ReadTimeout and WriteTimeout actually do? Tracing the source code is not exactly trivial.  It seems that ReadTimeout means "close the file descriptor if no read has succeeded in N seconds"? And WriteTimeout means "freeze the file descriptor (but don't close it?) if no write has succeeded in N seconds"? Mhh, that doesn't exactly jibe with the results I got either... puzzled...

[James Bardin]

On Thu, Aug 14, 2014 at 9:54 PM, Thorsten von Eicken <t...@rightscale.com> wrote:

Can you explain what ReadTimeout and WriteTimeout actually do

They are directly applied to the network connection using SetReadDeadline and SetWriteDeadline on the underlying connection: http://golang.org/pkg/net/#Conn

[James Bardin]

On Thu, Aug 14, 2014 at 9:40 PM, Thorsten von Eicken <t...@rightscale.com> wrote:

I'm not looking for a timeout for my handler. What I'm looking for is a timeout for connections that don't make progress outside of my handler. E.g.:

• The connection is idle forever, I'd like it to be reaped at some point so these don't build up

• The client sent a partial request and then stalls forever
• The client is not consuming the response

These are coarsely handled by setting a timeout that is longer than the maximum acceptable connection time. This of course gets harder when connection can be very long or vary greatly.

There are definitely complex cases that the stdlib doesn't cover, and are left up to the user. Managing every combination of timeout is one example, as are things like limiting the number of connections per client. 

There's a lot you can do by creating a custom net.Listener which in turn creates managed network connections. You also have the very useful Server.ConnState callback, which lets manage the underlying connection based on the state of the http session.

It's very common for systems that are concerned about fine control over these things to use purpose built software like a loadbalancer that can help manage resources. But you can of course write this load balancing functionality yourself in go. 

[Thorsten von Eicken]

I guess the only thing I can really conclude is that it's best not to use these timeouts with http 'cause they cause more harm than good. The test cases show that they're as likely to leave connections in some unusable state as anything else. I can't argue against your "works as designed" but in my book it's rather disappointing.

[Thorsten von Eicken]

To try to be constructive, it seems to me that the problem is in the ResponseWriter code, for example, http://golang.org/src/pkg/net/http/server.go?#L967 and the following WriteHeader function. These either sweep errors returned by write under the rug or pass them back to the calling HttpHandler who can't do anything about them. Instead, when a fatal error (such as a timeout) occurs on a connection the connection should be closed. This wouldn't fix the real problem with misleading users to think the timeouts are useful but at least would fix the current state where connections stay open but are unusable.

[James Bardin]

On Thu, Aug 14, 2014 at 10:54 PM, Thorsten von Eicken <t...@rightscale.com> wrote:

To try to be constructive, it seems to me that the problem is in the ResponseWriter code, for example, http://golang.org/src/pkg/net/http/server.go?#L967 and the following WriteHeader function. These either sweep errors returned by write under the rug or pass them back to the calling HttpHandler who can't do anything about them. Instead, when a fatal error (such as a timeout) occurs on a connection the connection should be closed. 

I was about to reply with the same thing. The timeout error specifically is never seen by the handler, so logging it isn't even an option right now. It just succeeds and leave the connection open.

That's definitely something that needs an issue filed.

[James Bardin]

Started an issue specifically for the open connection after WriteTimeout:

https://code.google.com/p/go/issues/detail?id=8534

[sandysk...@gmail.com]

I met the same problem， It seems that it's something with the http keep-alive options. Curl uses this options as default when doing a http request. If you use 'time curl -H "Connection: Close" http://127.0.01:8123"' ,it might terminate after excactly 10s , but still gets no response result.

在 2014年8月15日星期五UTC+8上午4时24分45秒，Thorsten von Eicken写道：

...

[sandysk...@gmail.com]

Do u solve the problem yet ?

在 2014年8月15日星期五UTC+8上午4时24分45秒，Thorsten von Eicken写道：

I'm having trouble using net/http's WriteTimeout in Go1.3 on ubuntu 12.04 and 14.04. The short is that if I set a WriteTimeout to N seconds and I run a handler that takes more than N seconds then the response is never written to the socket and the socket hangs. I see issue https://code.google.com/p/go/issues/detail?id=6410 and I can add the samples below to it, if what I'm observing is the same problem and a valid problem...

...

[James Bardin]

On Sunday, November 16, 2014, sandysk...@gmail.com <sandysk...@gmail.com> wrote:

Do u solve the problem yet ?

What problem are you referring to?

Issue 8534 has been closed. 

[sandysk...@gmail.com]

I think  go 1.4 have solved those bugs.

在 2014年11月17日星期一 UTC+8上午11:13:29，James Bardin写道：