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: problems or undocumented features dealing with handler timeout #6410

Closed
snarglebritchet opened this issue Sep 17, 2013 · 6 comments
Milestone

Comments

@snarglebritchet
Copy link

What steps will reproduce the problem?

First problem: a http handler which delays longer than server.WriteTimeout just silently
sends nothing, not even a HTTP error header. This behaviour might be deliberate (on the
basis of "use a timeout handler instead"), but it needs documenting.

Second problem: responseWriter.Write() returns nil for err (a write success) if
WriteTimeout has been exceeded. (Contrast: using a http.TimeoutHandler, it returns
"http: Handler timeout" correctly.)

Third problem: using a TimeoutHandler, with the actual handler having the behaviour or
Write, long delay, Write, and a timeout set to fire during the delay, the first write
sends the headers and the written value, then the timeout fires and appends the timeout
text and fails to set headers (because they were already sent). The result is a jumble
of output. This is not exactly an error, but it's a thing that needs communicating in
the docs: that the TimeoutHandler uses the same ResponseWriter, and if you have written
anything it will be unable to rescind it.


Which compiler are you using (5g, 6g, 8g, gccgo)?

8g


Which operating system are you using?

Ubuntu Linux 12.04 32 bit.


Which version are you using?  (run 'go version')

go version go1.1 linux/386
@rsc
Copy link
Contributor

rsc commented Oct 18, 2013

Comment 1:

Without concrete programs demonstrating 1, 2, and 3 I think it is unlikely anything is
going to happen.

Labels changed: added priority-later, go1.3maybe, removed priority-triage.

Status changed to Accepted.

@rsc
Copy link
Contributor

rsc commented Dec 4, 2013

Comment 2:

Labels changed: added release-none, removed go1.3maybe.

@rsc
Copy link
Contributor

rsc commented Dec 4, 2013

Comment 3:

Labels changed: added repo-main.

@rsc rsc added this to the Unplanned milestone Apr 10, 2015
@bradfitz bradfitz modified the milestones: Go1.9, Unplanned Feb 1, 2017
@bradfitz bradfitz self-assigned this Feb 1, 2017
@bradfitz
Copy link
Contributor

bradfitz commented Feb 1, 2017

I think most of this has since been fixed or documented, but assigning to myself to double-check.

@odeke-em
Copy link
Member

In regards to:

  1. We've got TestServerTimeouts
    func TestServerTimeouts(t *testing.T) {
    setParallel(t)
    defer afterTest(t)
    // Try three times, with increasing timeouts.
    tries := []time.Duration{250 * time.Millisecond, 500 * time.Millisecond, 1 * time.Second}
    for i, timeout := range tries {
    err := testServerTimeouts(timeout)
    if err == nil {
    return
    }
    t.Logf("failed at %v: %v", timeout, err)
    if i != len(tries)-1 {
    t.Logf("retrying at %v ...", tries[i+1])
    }
    }
    t.Fatal("all attempts failed")
    }
    func testServerTimeouts(timeout time.Duration) error {
    reqNum := 0
    ts := httptest.NewUnstartedServer(HandlerFunc(func(res ResponseWriter, req *Request) {
    reqNum++
    fmt.Fprintf(res, "req=%d", reqNum)
    }))
    ts.Config.ReadTimeout = timeout
    ts.Config.WriteTimeout = timeout
    ts.Start()
    defer ts.Close()
    // Hit the HTTP server successfully.
    c := ts.Client()
    r, err := c.Get(ts.URL)
    if err != nil {
    return fmt.Errorf("http Get #1: %v", err)
    }
    got, err := ioutil.ReadAll(r.Body)
    expected := "req=1"
    if string(got) != expected || err != nil {
    return fmt.Errorf("Unexpected response for request #1; got %q ,%v; expected %q, nil",
    string(got), err, expected)
    }
    // Slow client that should timeout.
    t1 := time.Now()
    conn, err := net.Dial("tcp", ts.Listener.Addr().String())
    if err != nil {
    return fmt.Errorf("Dial: %v", err)
    }
    buf := make([]byte, 1)
    n, err := conn.Read(buf)
    conn.Close()
    latency := time.Since(t1)
    if n != 0 || err != io.EOF {
    return fmt.Errorf("Read = %v, %v, wanted %v, %v", n, err, 0, io.EOF)
    }
    minLatency := timeout / 5 * 4
    if latency < minLatency {
    return fmt.Errorf("got EOF after %s, want >= %s", latency, minLatency)
    }
    // Hit the HTTP server successfully again, verifying that the
    // previous slow connection didn't run our handler. (that we
    // get "req=2", not "req=3")
    r, err = c.Get(ts.URL)
    if err != nil {
    return fmt.Errorf("http Get #2: %v", err)
    }
    got, err = ioutil.ReadAll(r.Body)
    r.Body.Close()
    expected = "req=2"
    if string(got) != expected || err != nil {
    return fmt.Errorf("Get #2 got %q, %v, want %q, nil", string(got), err, expected)
    }
    if !testing.Short() {
    conn, err := net.Dial("tcp", ts.Listener.Addr().String())
    if err != nil {
    return fmt.Errorf("long Dial: %v", err)
    }
    defer conn.Close()
    go io.Copy(ioutil.Discard, conn)
    for i := 0; i < 5; i++ {
    _, err := conn.Write([]byte("GET / HTTP/1.1\r\nHost: foo\r\n\r\n"))
    if err != nil {
    return fmt.Errorf("on write %d: %v", i, err)
    }
    time.Sleep(timeout / 2)
    }
    }
    return nil
    }
  2. We've got TestOnlyWriteTimeout
    func TestOnlyWriteTimeout(t *testing.T) {
    setParallel(t)
    defer afterTest(t)
    var (
    mu sync.RWMutex
    conn net.Conn
    )
    var afterTimeoutErrc = make(chan error, 1)
    ts := httptest.NewUnstartedServer(HandlerFunc(func(w ResponseWriter, req *Request) {
    buf := make([]byte, 512<<10)
    _, err := w.Write(buf)
    if err != nil {
    t.Errorf("handler Write error: %v", err)
    return
    }
    mu.RLock()
    defer mu.RUnlock()
    if conn == nil {
    t.Error("no established connection found")
    return
    }
    conn.SetWriteDeadline(time.Now().Add(-30 * time.Second))
    _, err = w.Write(buf)
    afterTimeoutErrc <- err
    }))
    ts.Listener = trackLastConnListener{ts.Listener, &mu, &conn}
    ts.Start()
    defer ts.Close()
    c := ts.Client()
    errc := make(chan error)
    go func() {
    res, err := c.Get(ts.URL)
    if err != nil {
    errc <- err
    return
    }
    _, err = io.Copy(ioutil.Discard, res.Body)
    res.Body.Close()
    errc <- err
    }()
    select {
    case err := <-errc:
    if err == nil {
    t.Errorf("expected an error from Get request")
    }
    case <-time.After(5 * time.Second):
    t.Fatal("timeout waiting for Get error")
    }
    if err := <-afterTimeoutErrc; err == nil {
    t.Error("expected write error after timeout")
    }
    }
  3. am not sure fully yet, I'll defer to Mr. HTTP @bradfitz

@bradfitz
Copy link
Contributor

Thanks @odeke-em for investigating and finding the tests.

And #3 has been documented much more in the four years since this bug was filed. It now says:

        // Changing the header map after a call to WriteHeader (or
        // Write) has no effect unless the modified headers are
        // trailers.

So I think we're good here. These many-bug-reports-in-one bugs tend to slip through the cracks since they can't be closed piecemeal. In the future, feel free to spam us with a dozen small bugs, cross-referenced as needed.

@golang golang locked and limited conversation to collaborators Jun 14, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants