net/http: closeNotify does not work well when read timeout is set

[xiang90]

There is a read timeout configuration for http server:

ReadTimeout    time.Duration // maximum duration before timing out read of the request

I expect it is the timeout for finishing reading the request only.

When read timeout is set, the connection will be considered as closed after the timeout even if the connection is still open and working. The following code set up a http server with read timeout and a handler simply blocks forever until closeNotify fires.

I expect to see the hander blocks "forever", but it unblocks after the read timeout.

The closeNotifiy depends on the read of the underlying connection. Shall we cancel the read timeout after finishing reading the request?

package main

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

func main() {
    srv := &http.Server{
        Addr:        "localhost:8080",
        Handler:     myhandler{},
        ReadTimeout: time.Second,
    }
    go func() {
        // wait server to start
        time.Sleep(time.Second)
        resp, err := http.Get("http://" + srv.Addr)
        if err != nil {
            log.Println(err)
            return
        }
        resp.Body.Close()
    }()
    log.Fatal(srv.ListenAndServe())
}

type myhandler struct{}

func (h myhandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
    if cn, ok := w.(http.CloseNotifier); ok {
        <-cn.CloseNotify()
        log.Panicf("unexpected closed client")
    }
}

[rsc]

Too late for Go 1.5.

[bwplotka]

Any update on that? We have Go 1.7 and this is still not fixed. We just lost one day investigating the bug which was caused by the ReadTimeout behaving totally different than stated in documentation:

ReadTimeout  time.Duration // maximum duration before timing out read of the request

The above is not true while using CloseNotify channel. As stated in @xiang90 description, for CloseNotify this is an absolute max duration before timing out of the whole connection.

Surprisingly, the WriteTimeout works as expected and it is using the same overwriting the Deadline mechanism.

Any plans for this bug?

[bradfitz]

A lot of work happened in this space in Go 1.8. Notably,
c7e0dda and faf882d.

I lost this bug because it fell into the "Unplanned" milestone, which we no longer use. I'll retarget this for Go 1.9.

But it might also be fixed by the Go 1.8 changes. Can you investigate using Go 1.8beta2?

See https://groups.google.com/forum/#!topic/golang-nuts/5YvvkQjJJW0 for details.

$ go get golang.org/x/build/version/go1.8beta2

[bwplotka]

Thanks, will try in the next days.

[gopherbot]

CL https://golang.org/cl/34515 mentions this issue.

[bwplotka]

@bradfitz: I can confirm that I can reproduce this issue on go version go1.8beta2 linux/amd64 and on the current master.

I dived even deeper into the code and used this occasion to start my contribution to Go ! (:

Sorry that I did not discuss the change before doing the CL, but maybe it will be easier to iterate over the initial attempt: https://go-review.googlesource.com/#/c/34515/

The main problem is that even the updated description is not entirely true:

// ReadTimeout is the maximum duration for reading the entire
// request, including the body.

// Because ReadTimeout does not let Handlers make per-request
// decisions on each request body's acceptable deadline or
// upload rate, most users will prefer to use
// ReadHeaderTimeout. It is valid to use them both.

Reading the whole body does not reset the ReadTimeout Deadline. ReadTimeout Deadline is being reset (or replaced by IdleTimeout) in the very end of the conn serve method for every request. As a result timeout can exceed while being in handler. In my opinion we should update the description that this Timeout also includes time spend in the Handler (which I did in the CL with the test case for that). My only worry is that now ReadTimeout is not really for... Read but rather RequestTimeout. (:

Any ideas or feedback? Naturally, I am new to the Go contribution and net/http internal code, so I could make a mistake in my thinking in these area.

[bradfitz]

I think this was fixed between Go 1.8beta2 and Go 1.8rc1 in https://go-review.googlesource.com/34813 while fixing #18447.

@Bplotka, @xiang90, could either of you two confirm?

[bwplotka]

Yes, it seems that the issue is fixed in Go 1.8rc1

[odeke-em]

@bradfitz, @Bplotka confirmed it.
Running the test program:

• With Go1.7
  net/http: closeNotify does not work well when read timeout is set #9524 (comment) I get back a response ASAP and a panic in the server, which is the bug report.

• With >= Go1.8 ie tip b53f0f8
  It hangs forever, so fixed.

[xiang90]

The original issue is fixed on tip.

[xiang90]

Shall I close this issue? @bradfitz