From a670942286b684cf72aed3d2e84162ec6eb20ab8 Mon Sep 17 00:00:00 2001 From: Will McCutchen <will@mccutch.org> Date: Thu, 29 Jun 2023 18:45:22 -0400 Subject: [PATCH] Improve /drip semantics (#132) This started with me wading into the `/drip` endpoint to add `Server-Timing` trailers as suggested in https://github.com/mccutchen/go-httpbin/issues/72. In making those changes, I discovered that the standard golang net/http server we're building on only supports sending trailers when the response is written using `Content-Encoding: chunked`. Initially, I thought it would be reasonable for this endpoint, which is designed to stream writes to the client, to switch over to a chunked response, but upon further consideration I don't think that's a good idea. So I'll defer adding trailers to some later work. But, in thinking this through (and fighting with the unit tests already in place for drip), I realized that the `/drip` endpoint had room for improvement, if we think about it as an endpoint _designed to let clients test their behavior when an HTTP server is responding very slowly_. So, we ended up with these changes: Initial delay semantics: - Originally, `/drip` would immediately write the desired status code and then wait for the initial delay (if any). - Here we update that so that it waits for the initial delay before writing anything to the response, to better simulate a server that is just very slow to respond at all. Incremental write timings: - Switch over to a ticker to more accurately pace the incremental writes across the requested duration - Stop sleeping after the final byte is written (should not affect clients, but avoids wasting server resources) Worth noting that I now believe it's important that this endpoint **not** switch over to chunked content encoding, because it is useful to maintain and endpoint that simulates a server very slowly writing a "normal" HTTP response. --- Makefile | 2 +- httpbin/handlers.go | 34 +++++++++---- httpbin/handlers_test.go | 79 ++++++++++++++++++------------- internal/testing/assert/assert.go | 24 ++++++++-- 4 files changed, 91 insertions(+), 48 deletions(-) diff --git a/Makefile b/Makefile index 9a10cbe..bbcd4ae 100644 --- a/Makefile +++ b/Makefile @@ -70,7 +70,7 @@ lint: # run locally # ============================================================================= run: build - $(DIST_PATH)/go-httpbin + $(DIST_PATH)/go-httpbin -host 127.0.0.1 -port 8080 .PHONY: run watch: diff --git a/httpbin/handlers.go b/httpbin/handlers.go index 9dc7888..097473c 100644 --- a/httpbin/handlers.go +++ b/httpbin/handlers.go @@ -639,35 +639,49 @@ func (h *HTTPBin) Drip(w http.ResponseWriter, r *http.Request) { pause = duration / time.Duration(numBytes-1) } + // Initial delay before we send any response data + if delay > 0 { + select { + case <-time.After(delay): + // ok + case <-r.Context().Done(): + w.WriteHeader(499) // "Client Closed Request" https://httpstatuses.com/499 + return + } + } + w.Header().Set("Content-Type", "application/octet-stream") w.Header().Set("Content-Length", fmt.Sprintf("%d", numBytes)) w.WriteHeader(code) - flusher := w.(http.Flusher) - flusher.Flush() - - // wait for initial delay before writing response body - select { - case <-r.Context().Done(): + // special case when we do not need to pause between each write + if pause == 0 { + for i := int64(0); i < numBytes; i++ { + w.Write([]byte{'*'}) + } return - case <-time.After(delay): } - // write response body byte-by-byte, pausing between each write + // otherwise, write response body byte-by-byte + ticker := time.NewTicker(pause) + defer ticker.Stop() + b := []byte{'*'} + flusher := w.(http.Flusher) for i := int64(0); i < numBytes; i++ { w.Write(b) flusher.Flush() // don't pause after last byte if i == numBytes-1 { - break + return } select { + case <-ticker.C: + // ok case <-r.Context().Done(): return - case <-time.After(pause): } } } diff --git a/httpbin/handlers_test.go b/httpbin/handlers_test.go index ebdce3e..ce59b6f 100644 --- a/httpbin/handlers_test.go +++ b/httpbin/handlers_test.go @@ -1693,6 +1693,13 @@ func TestDrip(t *testing.T) { assert.Header(t, resp, "Content-Type", "application/octet-stream") assert.Header(t, resp, "Content-Length", strconv.Itoa(test.numbytes)) + // Note: while the /drip endpoint seems like an ideal use case for + // using chunked transfer encoding to stream data to the client, it + // is actually intended to simulate a slow connection between + // server and client, so it is important to ensure that it writes a + // "regular," un-chunked response. + assert.DeepEqual(t, resp.TransferEncoding, nil, "unexpected Transfer-Encoding header") + if len(body) != test.numbytes { t.Fatalf("expected %d bytes, got %d", test.numbytes, len(body)) } @@ -1735,10 +1742,12 @@ func TestDrip(t *testing.T) { t.Parallel() var ( - duration = 100 * time.Millisecond - numBytes = 3 - wantDelay = duration / time.Duration(numBytes) - endpoint = fmt.Sprintf("/drip?duration=%s&delay=%s&numbytes=%d", duration, wantDelay, numBytes) + duration = 100 * time.Millisecond + numBytes = 3 + endpoint = fmt.Sprintf("/drip?duration=%s&numbytes=%d", duration, numBytes) + + // Match server logic for calculating the delay between writes + wantPauseBetweenWrites = duration / time.Duration(numBytes-1) ) req := newTestRequest(t, "GET", endpoint) resp := must.DoReq(t, client, req) @@ -1750,49 +1759,50 @@ func TestDrip(t *testing.T) { // wait between writes so that even the first iteration of this loop // expects to wait the same amount of time for a read. buf := make([]byte, 1024) - for { + gotBody := make([]byte, 0, numBytes) + for i := 0; ; i++ { start := time.Now() n, err := resp.Body.Read(buf) - gotDelay := time.Since(start) + gotPause := time.Since(start) + + // We expect to read exactly one byte on each iteration. On the + // last iteration, we expct to hit EOF after reading the final + // byte, because the server does not pause after the last write. + assert.Equal(t, n, 1, "incorrect number of bytes read") + assert.DeepEqual(t, buf[:n], []byte{'*'}, "unexpected bytes read") + gotBody = append(gotBody, buf[:n]...) if err == io.EOF { break } assert.NilError(t, err) - assert.Equal(t, n, 1, "incorrect number of bytes read") - assert.DeepEqual(t, buf[:n], []byte{'*'}, "unexpected bytes read") - if gotDelay < wantDelay { - t.Fatalf("to wait at least %s between reads, waited %s", wantDelay, gotDelay) + + // only ensure that we pause for the expected time between writes + // (allowing for minor mismatch in local timers and server timers) + // after the first byte. + if i > 0 { + assert.RoughDuration(t, gotPause, wantPauseBetweenWrites, 3*time.Millisecond) } } + + wantBody := bytes.Repeat([]byte{'*'}, numBytes) + assert.DeepEqual(t, gotBody, wantBody, "incorrect body") }) t.Run("handle cancelation during initial delay", func(t *testing.T) { t.Parallel() // For this test, we expect the client to time out and cancel the - // request after 10ms. The handler should immediately write a 200 OK - // status before the client timeout, preventing a client error, but it - // will wait 500ms to write anything to the response body. - // - // So, we're testing that a) the client got an immediate 200 OK but - // that b) the response body was empty. + // request after 10ms. The handler should still be in its intitial + // delay period, so this will result in a request error since no status + // code will be written before the cancelation. ctx, cancel := context.WithTimeout(context.Background(), 25*time.Millisecond) defer cancel() - req := newTestRequest(t, "GET", "/drip?duration=500ms&delay=500ms") - req = req.WithContext(ctx) - - resp := must.DoReq(t, client, req) - assert.StatusCode(t, resp, http.StatusOK) - - body, err := io.ReadAll(resp.Body) - if !os.IsTimeout(err) { - t.Fatalf("expected client timeout while reading body, bot %s", err) - } - if len(body) > 0 { - t.Fatalf("expected client timeout before body was written, got body %q", string(body)) + req := newTestRequest(t, "GET", "/drip?duration=500ms&delay=500ms").WithContext(ctx) + if _, err := client.Do(req); !os.IsTimeout(err) { + t.Fatalf("expected timeout error, got %s", err) } }) @@ -1802,19 +1812,22 @@ func TestDrip(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), 250*time.Millisecond) defer cancel() - req := newTestRequest(t, "GET", "/drip?duration=900ms&delay=100ms") - req = req.WithContext(ctx) - + req := newTestRequest(t, "GET", "/drip?duration=900ms&delay=100ms").WithContext(ctx) resp := must.DoReq(t, client, req) + + // In this test, the server should have started an OK response before + // our client timeout cancels the request, so we should get an OK here. assert.StatusCode(t, resp, http.StatusOK) - // in this case, the timeout happens while trying to read the body + // But, we should time out while trying to read the whole response + // body. body, err := io.ReadAll(resp.Body) if !os.IsTimeout(err) { t.Fatalf("expected timeout reading body, got %s", err) } - // but we should have received a partial response + // And even though the request timed out, we should get a partial + // response. assert.DeepEqual(t, body, []byte("**"), "incorrect partial body") }) diff --git a/internal/testing/assert/assert.go b/internal/testing/assert/assert.go index 112be3a..96efe65 100644 --- a/internal/testing/assert/assert.go +++ b/internal/testing/assert/assert.go @@ -6,14 +6,15 @@ import ( "reflect" "strings" "testing" + "time" "github.com/mccutchen/go-httpbin/v2/internal/testing/must" ) // Equal asserts that two values are equal. -func Equal[T comparable](t *testing.T, want, got T, msg string, arg ...any) { +func Equal[T comparable](t *testing.T, got, want T, msg string, arg ...any) { t.Helper() - if want != got { + if got != want { if msg == "" { msg = "expected values to match" } @@ -23,9 +24,9 @@ func Equal[T comparable](t *testing.T, want, got T, msg string, arg ...any) { } // DeepEqual asserts that two values are deeply equal. -func DeepEqual[T any](t *testing.T, want, got T, msg string, arg ...any) { +func DeepEqual[T any](t *testing.T, got, want T, msg string, arg ...any) { t.Helper() - if !reflect.DeepEqual(want, got) { + if !reflect.DeepEqual(got, want) { if msg == "" { msg = "expected values to match" } @@ -89,3 +90,18 @@ func BodyEquals(t *testing.T, resp *http.Response, want string) { got := must.ReadAll(t, resp.Body) Equal(t, got, want, "incorrect response body") } + +// DurationRange asserts that a duration is within a specific range. +func DurationRange(t *testing.T, got, min, max time.Duration) { + t.Helper() + if got < min || got > max { + t.Fatalf("expected duration between %s and %s, got %s", min, max, got) + } +} + +// RoughDuration asserts that a duration is within a certain tolerance of a +// given value. +func RoughDuration(t *testing.T, got, want time.Duration, tolerance time.Duration) { + t.Helper() + DurationRange(t, got, want-tolerance, want+tolerance) +} -- GitLab