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)

Author: mccutchen

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)
 

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) {

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, ", ")
+}

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
+}