net/http: problems or undocumented features dealing with handler timeout

[snarglebritchet]

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]

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]

Comment 2:

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

[rsc]

Comment 3:

Labels changed: added repo-main.

[bradfitz]

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

[odeke-em]

In regards to:

1. We've got TestServerTimeouts

   go/src/net/http/serve_test.go

   Lines 505 to 595 in 07a22bb

   	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

   go/src/net/http/serve_test.go

   Lines 771 to 824 in 07a22bb

   	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]

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.