From 66aaedf32c59d82f172daf80db5e2391bdef301a Mon Sep 17 00:00:00 2001 From: Will McCutchen <will@mccutch.org> Date: Wed, 28 Jun 2023 23:21:19 -0400 Subject: [PATCH] Update /drip endpoint: - Add Server-Timing trailers to record each component of the overall response time - Switch Content-Type from application/octet-stream to text/plain to make the endpoint a bit easier to work with in a browser - Eliminate unnecessary pause after writing final byte to response --- Makefile | 2 +- httpbin/handlers.go | 41 ++++++++++++---- httpbin/handlers_test.go | 79 ++++++++++++++++++++++++++++--- httpbin/helpers.go | 41 ++++++++++++++++ httpbin/static/index.html | 2 +- internal/testing/assert/assert.go | 24 ++++++++-- 6 files changed, 167 insertions(+), 22 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..b696589 100644 --- a/httpbin/handlers.go +++ b/httpbin/handlers.go @@ -584,6 +584,7 @@ func (h *HTTPBin) Delay(w http.ResponseWriter, r *http.Request) { // Drip returns data over a duration after an optional initial delay, then // (optionally) returns with the given status code. func (h *HTTPBin) Drip(w http.ResponseWriter, r *http.Request) { + start := time.Now() q := r.URL.Query() var ( @@ -639,21 +640,42 @@ func (h *HTTPBin) Drip(w http.ResponseWriter, r *http.Request) { pause = duration / time.Duration(numBytes-1) } - w.Header().Set("Content-Type", "application/octet-stream") - w.Header().Set("Content-Length", fmt.Sprintf("%d", numBytes)) + w.Header().Add("Trailer", "Server-Timing") + defer func() { + w.Header().Add("Server-Timing", encodeServerTimings([]serverTiming{ + {"total", time.Since(start), "total request duration"}, + {"delay", delay, "requested initial delay"}, + {"duration", duration, "requested duration"}, + {"pause", pause, "computed pause between writes"}, + })) + }() + + w.Header().Set("Content-Type", "text/plain") w.WriteHeader(code) flusher := w.(http.Flusher) flusher.Flush() - // wait for initial delay before writing response body - select { - case <-r.Context().Done(): + if delay > 0 { + select { + case <-time.After(delay): + // ok + case <-r.Context().Done(): + return + } + } + + // special case when we do not need to pause between each write + if pause == 0 { + b := bytes.Repeat([]byte{'*'}, int(numBytes)) + w.Write(b) 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{'*'} for i := int64(0); i < numBytes; i++ { w.Write(b) @@ -661,13 +683,14 @@ func (h *HTTPBin) Drip(w http.ResponseWriter, r *http.Request) { // 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..4453a65 100644 --- a/httpbin/handlers_test.go +++ b/httpbin/handlers_test.go @@ -1690,8 +1690,16 @@ func TestDrip(t *testing.T) { elapsed := time.Since(start) assert.StatusCode(t, resp, test.code) - assert.Header(t, resp, "Content-Type", "application/octet-stream") - assert.Header(t, resp, "Content-Length", strconv.Itoa(test.numbytes)) + assert.Header(t, resp, "Content-Type", "text/plain") + assert.Header(t, resp, "Content-Length", "") + assert.DeepEqual(t, resp.TransferEncoding, []string{"chunked"}, "incorrect Transfer-Encoding header") + + timings := decodeServerTimings(resp.Trailer.Get("Server-Timing")) + for _, k := range []string{"duration", "delay", "pause", "total"} { + if _, ok := timings[k]; !ok { + t.Fatalf("expected %q timing, got %v", k, timings) + } + } if len(body) != test.numbytes { t.Fatalf("expected %d bytes, got %d", test.numbytes, len(body)) @@ -1735,9 +1743,12 @@ func TestDrip(t *testing.T) { t.Parallel() var ( - duration = 100 * time.Millisecond - numBytes = 3 - wantDelay = duration / time.Duration(numBytes) + duration = 100 * time.Millisecond + numBytes = 3 + // compute initial delay using the same logic the endpoint will use + // to compute the pause between writes, to simplify the read loop + // below + wantDelay = duration / time.Duration(numBytes-1) endpoint = fmt.Sprintf("/drip?duration=%s&delay=%s&numbytes=%d", duration, wantDelay, numBytes) ) req := newTestRequest(t, "GET", endpoint) @@ -1750,6 +1761,7 @@ 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) + gotBody := make([]byte, 0, numBytes) for { start := time.Now() n, err := resp.Body.Read(buf) @@ -1762,9 +1774,62 @@ func TestDrip(t *testing.T) { 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) + + // allow for minor mismatch in local timers and server timers + assert.RoughDuration(t, gotDelay, wantDelay, 3*time.Millisecond) + + gotBody = append(gotBody, buf[:n]...) + } + + wantBody := bytes.Repeat([]byte{'*'}, numBytes) + assert.DeepEqual(t, gotBody, wantBody, "incorrect body") + }) + + t.Run("Server-Timings trailers", func(t *testing.T) { + t.Parallel() + + var ( + duration = 512 * time.Millisecond + delay = 250 * time.Millisecond + numBytes = 256 + params = url.Values{ + "duration": {duration.String()}, + "delay": {delay.String()}, + "numbytes": {strconv.Itoa(numBytes)}, } + ) + + req := newTestRequest(t, "GET", "/drip?"+params.Encode()) + resp := must.DoReq(t, client, req) + + // need to fully consume body for Server-Timing trailers to arrive + body := must.ReadAll(t, resp.Body) + assert.Equal(t, body, strings.Repeat("*", numBytes), "incorrect body") + + rawTimings := resp.Trailer.Get("Server-Timing") + t.Logf("Server-Timing: %s", rawTimings) + + timings := decodeServerTimings(rawTimings) + + // Ensure total server time makes sense based on duration and delay + total := timings["total"] + assert.DurationRange(t, total.dur, duration+delay, duration+delay+25*time.Millisecond) + + // Ensure computed pause time makes sense based on duration, delay, and + // numbytes (should be exact, but we're re-parsing a truncated float in + // the header value) + pause := timings["pause"] + assert.RoughDuration(t, pause.dur, duration/time.Duration(numBytes-1), 1*time.Millisecond) + + // remaining timings should exactly match request parameters, no need + // to adjust for per-run variations + wantTimings := map[string]serverTiming{ + "duration": {"duration", duration, "requested duration"}, + "delay": {"delay", delay, "requested initial delay"}, + } + for k, want := range wantTimings { + got := timings[k] + assert.DeepEqual(t, got, want, "incorrect timing for key %q", k) } }) diff --git a/httpbin/helpers.go b/httpbin/helpers.go index 9eca145..5b44171 100644 --- a/httpbin/helpers.go +++ b/httpbin/helpers.go @@ -415,3 +415,44 @@ func (b *base64Helper) Encode() ([]byte, error) { func (b *base64Helper) Decode() ([]byte, error) { return base64.URLEncoding.DecodeString(b.data) } + +type serverTiming struct { + name string + dur time.Duration + desc string +} + +func encodeServerTimings(timings []serverTiming) string { + var entries []string + for _, t := range timings { + ms := float64(t.dur) / float64(time.Millisecond) + entries = append(entries, fmt.Sprintf("%s;dur=%0.2f;desc=\"%s\"", t.name, ms, t.desc)) + } + return strings.Join(entries, ", ") +} + +func decodeServerTimings(headerVal string) map[string]serverTiming { + if headerVal == "" { + return nil + } + timings := map[string]serverTiming{} + for _, entry := range strings.Split(headerVal, ",") { + var t serverTiming + for _, kv := range strings.Split(entry, ";") { + kv = strings.TrimSpace(kv) + key, val, _ := strings.Cut(kv, "=") + switch key { + case "dur": + t.dur, _ = time.ParseDuration(val + "ms") + case "desc": + t.desc = strings.Trim(val, "\"") + default: + t.name = key + } + } + if t.name != "" { + timings[t.name] = t + } + } + return timings +} diff --git a/httpbin/static/index.html b/httpbin/static/index.html index 4d94d0b..71790b7 100644 --- a/httpbin/static/index.html +++ b/httpbin/static/index.html @@ -79,7 +79,7 @@ <li><a href="/deny"><code>/deny</code></a> Denied by robots.txt file.</li> <li><a href="/digest-auth/auth/user/passwd/MD5"><code>/digest-auth/:qop/:user/:passwd/:algorithm</code></a> Challenges HTTP Digest Auth.</li> <li><a href="/digest-auth/auth/user/passwd/MD5"><code>/digest-auth/:qop/:user/:passwd</code></a> Challenges HTTP Digest Auth.</li> -<li><a href="/drip?code=200&numbytes=5&duration=5"><code>/drip?numbytes=n&duration=s&delay=s&code=code</code></a> Drips data over a duration after an optional initial delay, then (optionally) returns with the given status code.</li> +<li><a href="/drip?code=200&numbytes=5&duration=5"><code>/drip?numbytes=n&duration=s&delay=s&code=code</code></a> Drips data over a duration after an optional initial delay, using <code>chunked</code> transfer-encoding, and (optionally) returns with the given status code.</li> <li><a href="/dump/request"><code>/dump/request</code></a> Returns the given request in its HTTP/1.x wire approximate representation.</li> <li><a href="/encoding/utf8"><code>/encoding/utf8</code></a> Returns page containing UTF-8 data.</li> <li><a href="/etag/etag"><code>/etag/:etag</code></a> Assumes the resource has the given etag and responds to If-None-Match header with a 200 or 304 and If-Match with a 200 or 412 as appropriate.</li> 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