From 34a21a3ef81df5aa42185fcae2e5a608404ac6a0 Mon Sep 17 00:00:00 2001 From: Will McCutchen Date: Tue, 17 Sep 2024 00:42:03 -0400 Subject: [PATCH] feat: add `Server-Timing` headers/trailers where relevant (#186) Here we add [Server-Timing headers/trailers](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing) to endpoints that let clients control response timing: - `/delay` (header) - `/drip` (header) - `/sse` (trailer) --- httpbin/handlers.go | 19 +++++++++ httpbin/handlers_test.go | 84 ++++++++++++++++++++++++++++++++++++++++ httpbin/helpers.go | 17 ++++++++ httpbin/helpers_test.go | 27 +++++++++++++ 4 files changed, 147 insertions(+) diff --git a/httpbin/handlers.go b/httpbin/handlers.go index 9da5fff..16503f6 100644 --- a/httpbin/handlers.go +++ b/httpbin/handlers.go @@ -607,6 +607,9 @@ func (h *HTTPBin) Delay(w http.ResponseWriter, r *http.Request) { return case <-time.After(delay): } + w.Header().Set("Server-Timing", encodeServerTimings([]serverTiming{ + {"initial_delay", delay, "initial delay"}, + })) h.RequestWithBody(w, r) } @@ -691,6 +694,12 @@ func (h *HTTPBin) Drip(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", textContentType) w.Header().Set("Content-Length", fmt.Sprintf("%d", numBytes)) + w.Header().Set("Server-Timing", encodeServerTimings([]serverTiming{ + {"total_duration", delay + duration, "total request duration"}, + {"initial_delay", delay, "initial delay"}, + {"write_duration", duration, "duration of writes after initial delay"}, + {"pause_per_write", pause, "computed pause between writes"}, + })) w.WriteHeader(code) // what we write with each increment of the ticker @@ -1110,6 +1119,7 @@ func (h *HTTPBin) Hostname(w http.ResponseWriter, _ *http.Request) { // SSE writes a stream of events over a duration after an optional // initial delay. func (h *HTTPBin) SSE(w http.ResponseWriter, r *http.Request) { + start := time.Now() q := r.URL.Query() var ( count = h.DefaultParams.SSECount @@ -1169,6 +1179,15 @@ func (h *HTTPBin) SSE(w http.ResponseWriter, r *http.Request) { } } + w.Header().Add("Trailer", "Server-Timing") + defer func() { + w.Header().Add("Server-Timing", encodeServerTimings([]serverTiming{ + {"total_duration", time.Since(start), "total request duration"}, + {"initial_delay", delay, "initial delay"}, + {"write_duration", duration, "duration of writes after initial delay"}, + {"pause_per_write", pause, "computed pause between writes"}, + })) + }() w.Header().Set("Content-Type", sseContentType) w.WriteHeader(http.StatusOK) diff --git a/httpbin/handlers_test.go b/httpbin/handlers_test.go index 3f37fe3..048c684 100644 --- a/httpbin/handlers_test.go +++ b/httpbin/handlers_test.go @@ -1929,6 +1929,11 @@ func TestDelay(t *testing.T) { if elapsed < test.expectedDelay { t.Fatalf("expected delay of %s, got %s", test.expectedDelay, elapsed) } + + timings := decodeServerTimings(resp.Header.Get("Server-Timing")) + assert.DeepEqual(t, timings, map[string]serverTiming{ + "initial_delay": {"initial_delay", test.expectedDelay, "initial delay"}, + }, "incorrect Server-Timing header value") }) } @@ -2224,6 +2229,38 @@ func TestDrip(t *testing.T) { assert.StatusCode(t, resp, http.StatusOK) assert.BodySize(t, resp, 0) }) + + t.Run("Server-Timings header", func(t *testing.T) { + t.Parallel() + + var ( + duration = 100 * time.Millisecond + delay = 50 * time.Millisecond + numBytes = 10 + ) + + url := fmt.Sprintf("/drip?duration=%s&delay=%s&numbytes=%d", duration, delay, numBytes) + req := newTestRequest(t, "GET", url) + resp := must.DoReq(t, client, req) + defer consumeAndCloseBody(resp) + + assert.StatusCode(t, resp, http.StatusOK) + + timings := decodeServerTimings(resp.Header.Get("Server-Timing")) + + // compute expected pause between writes to match server logic and + // handle lossy floating point truncation in the serialized header + // value + computedPause := duration / time.Duration(numBytes-1) + wantPause, _ := time.ParseDuration(fmt.Sprintf("%.2fms", computedPause.Seconds()*1e3)) + + assert.DeepEqual(t, timings, map[string]serverTiming{ + "total_duration": {"total_duration", delay + duration, "total request duration"}, + "initial_delay": {"initial_delay", delay, "initial delay"}, + "pause_per_write": {"pause_per_write", wantPause, "computed pause between writes"}, + "write_duration": {"write_duration", duration, "duration of writes after initial delay"}, + }, "incorrect Server-Timing header value") + }) } func TestRange(t *testing.T) { @@ -3299,6 +3336,53 @@ func TestSSE(t *testing.T) { assert.StatusCode(t, resp, http.StatusOK) assert.BodySize(t, resp, 0) }) + + t.Run("Server-Timings trailers", func(t *testing.T) { + t.Parallel() + + var ( + duration = 250 * time.Millisecond + delay = 100 * time.Millisecond + count = 10 + params = url.Values{ + "duration": {duration.String()}, + "delay": {delay.String()}, + "count": {strconv.Itoa(count)}, + } + ) + + req := newTestRequest(t, "GET", "/sse?"+params.Encode()) + resp := must.DoReq(t, client, req) + + // need to fully consume body for Server-Timing trailers to arrive + must.ReadAll(t, resp.Body) + + rawTimings := resp.Trailer.Get("Server-Timing") + t.Logf("raw Server-Timing header value: %q", rawTimings) + + timings := decodeServerTimings(rawTimings) + + // Ensure total server time makes sense based on duration and delay + total := timings["total_duration"] + 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_per_write"] + assert.RoughlyEqual(t, pause.dur, duration/time.Duration(count-1), 1*time.Millisecond) + + // remaining timings should exactly match request parameters, no need + // to adjust for per-run variations + wantTimings := map[string]serverTiming{ + "write_duration": {"write_duration", duration, "duration of writes after initial delay"}, + "initial_delay": {"initial_delay", delay, "initial delay"}, + } + for k, want := range wantTimings { + got := timings[k] + assert.DeepEqual(t, got, want, "incorrect timing for key %q", k) + } + }) } func TestWebSocketEcho(t *testing.T) { diff --git a/httpbin/helpers.go b/httpbin/helpers.go index f7ddaf7..6890e8f 100644 --- a/httpbin/helpers.go +++ b/httpbin/helpers.go @@ -563,3 +563,20 @@ func weightedRandomChoice[T any](choices []weightedChoice[T]) T { } panic("failed to select a weighted random choice") } + +// Server-Timing header/trailer helpers. See MDN docs for reference: +// https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Server-Timing +type serverTiming struct { + name string + dur time.Duration + desc string +} + +func encodeServerTimings(timings []serverTiming) string { + entries := make([]string, len(timings)) + for i, t := range timings { + ms := t.dur.Seconds() * 1e3 + entries[i] = fmt.Sprintf("%s;dur=%0.2f;desc=\"%s\"", t.name, ms, t.desc) + } + return strings.Join(entries, ", ") +} diff --git a/httpbin/helpers_test.go b/httpbin/helpers_test.go index 2950f2d..e8569c7 100644 --- a/httpbin/helpers_test.go +++ b/httpbin/helpers_test.go @@ -11,6 +11,7 @@ import ( "net/url" "regexp" "strconv" + "strings" "testing" "time" @@ -545,3 +546,29 @@ func normalizeChoices[T any](choices []weightedChoice[T]) []weightedChoice[T] { } return normalized } + +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 +}