Public: anyone can read this; the crew can change it.
A test pins Server-Timing: a phase name never carries text from the request, and the header stays one valid line #6919
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/6910-a-test-pins-server-timing-a-phase-name-n → main 1 commit fork
2 files
changed +78
−3
src/core/route_timing.ts +17 −3
| @@ -248,7 +248,13 @@ const snap = (counts?: Counts): [number, number] | undefined => { | ||
| 248 | 248 | export function timePhase<T>(request: Request, name: string, work: () => T, counts?: Counts): T { |
| 249 | 249 | const before = snap(counts); |
| 250 | 250 | const started = performance.now(); |
| 251 | const value = work(); | |
| 251 | let value: T; | |
| 252 | try { | |
| 253 | value = work(); | |
| 254 | } catch (err) { | |
| 255 | noteSince(request, name, started, before, counts); | |
| 256 | throw err; | |
| 257 | } | |
| 252 | 258 | noteSince(request, name, started, before, counts); |
| 253 | 259 | return value; |
| 254 | 260 | } |
| @@ -256,7 +262,13 @@ export function timePhase<T>(request: Request, name: string, work: () => T, coun | ||
| 256 | 262 | export async function timePhaseAsync<T>(request: Request, name: string, work: () => Promise<T>, counts?: Counts): Promise<T> { |
| 257 | 263 | const before = snap(counts); |
| 258 | 264 | const started = performance.now(); |
| 259 | const value = await work(); | |
| 265 | let value: T; | |
| 266 | try { | |
| 267 | value = await work(); | |
| 268 | } catch (err) { | |
| 269 | noteSince(request, name, started, before, counts); | |
| 270 | throw err; | |
| 271 | } | |
| 260 | 272 | noteSince(request, name, started, before, counts); |
| 261 | 273 | return value; |
| 262 | 274 | } |
| @@ -306,7 +318,9 @@ export function noteSessionTime(request: Request, ms: number): void { | ||
| 306 | 318 | } |
| 307 | 319 | |
| 308 | 320 | export function takeSessionTime(request: Request): number { |
| 309 | return sessionTimes.get(request) ?? 0; | |
| 321 | const ms = sessionTimes.get(request) ?? 0; | |
| 322 | sessionTimes.delete(request); | |
| 323 | return ms; | |
| 310 | 324 | } |
| 311 | 325 | |
| 312 | 326 | const dbTimes = new WeakMap<Request, number>(); |
test/route-timing.test.ts +61
| @@ -11,9 +11,18 @@ import { | ||
| 11 | 11 | createRouteTiming, |
| 12 | 12 | KEEP_DAYS, |
| 13 | 13 | readTiming, |
| 14 | nameFrame, | |
| 15 | namesFrame, | |
| 16 | noteDbTime, | |
| 14 | 17 | notePhase, |
| 18 | noteSessionTime, | |
| 19 | noteStart, | |
| 15 | 20 | serverTiming, |
| 21 | takeDbTime, | |
| 16 | 22 | takePhases, |
| 23 | takeSessionTime, | |
| 24 | timePhase, | |
| 25 | timePhaseAsync, | |
| 17 | 26 | } from "../src/core/route_timing.ts"; |
| 18 | 27 | import { serve } from "../src/http/server.ts"; |
| 19 | 28 | import { migrate } from "../src/kernel/migrate.ts"; |
| @@ -98,3 +107,55 @@ test("phases follow app in the header, and a name that is not a token is refused | ||
| 98 | 107 | expect(takePhases(request)).toEqual([]); |
| 99 | 108 | expect(() => notePhase(request, "my repo", 1)).toThrow(); |
| 100 | 109 | }); |
| 110 | ||
| 111 | test("two phases timed on one request keep their order and each carries dur", async () => { | |
| 112 | const request = new Request("http://x/"); | |
| 113 | expect(timePhase(request, "first", () => 7)).toBe(7); | |
| 114 | expect(await timePhaseAsync(request, "second", async () => "ok")).toBe("ok"); | |
| 115 | const header = serverTiming(5, undefined, takePhases(request)); | |
| 116 | expect(header).toMatch(/^app;dur=5\.0, first;dur=\d+\.\d, second;dur=\d+\.\d$/); | |
| 117 | }); | |
| 118 | ||
| 119 | test("a throw inside a timed phase still records the phase and rethrows", async () => { | |
| 120 | const request = new Request("http://x/"); | |
| 121 | expect(() => timePhase(request, "boom", () => { throw new Error("sync"); })).toThrow("sync"); | |
| 122 | await expect(timePhaseAsync(request, "late", async () => { throw new Error("async"); })).rejects.toThrow("async"); | |
| 123 | expect(takePhases(request).map((p) => p.name)).toEqual(["boom", "late"]); | |
| 124 | }); | |
| 125 | ||
| 126 | test("a phase name with a separator, quote or line break is refused and the header stays one line", () => { | |
| 127 | const request = new Request("http://x/"); | |
| 128 | for (const name of ["a,b", "a;b", 'a"b', "a\rb", "a\nb", "a\r\nSet-Cookie: x=1", "", "A", "a b"]) { | |
| 129 | expect(() => notePhase(request, name, 1)).toThrow(); | |
| 130 | expect(() => timePhase(request, name, () => 1)).toThrow(); | |
| 131 | } | |
| 132 | notePhase(request, "fine", 1, true); | |
| 133 | const header = serverTiming(1, 0.5, takePhases(request)); | |
| 134 | expect(header).toBe('db;dur=0.5, app;dur=1.0, fine;dur=1.0;desc="hit"'); | |
| 135 | expect(header).not.toMatch(/[\r\n]/); | |
| 136 | }); | |
| 137 | ||
| 138 | test("route and compress frames are named once per request", () => { | |
| 139 | const request = new Request("http://x/"); | |
| 140 | expect(namesFrame(request)).toBe(false); | |
| 141 | noteStart(request, performance.now()); | |
| 142 | nameFrame(request); | |
| 143 | expect(namesFrame(request)).toBe(true); | |
| 144 | expect(takePhases(request).map((p) => p.name)).toEqual(["route"]); | |
| 145 | expect(namesFrame(new Request("http://x/"))).toBe(false); | |
| 146 | }); | |
| 147 | ||
| 148 | test("db and session time are given once, then nothing, and never cross requests", () => { | |
| 149 | const a = new Request("http://x/a"); | |
| 150 | const b = new Request("http://x/b"); | |
| 151 | expect(takeDbTime(a)).toBeUndefined(); | |
| 152 | noteDbTime(a, 1.5); | |
| 153 | noteDbTime(a, 2); | |
| 154 | noteSessionTime(a, 3); | |
| 155 | expect(takeDbTime(b)).toBeUndefined(); | |
| 156 | expect(takeSessionTime(b)).toBe(0); | |
| 157 | expect(takeDbTime(a)).toBe(3.5); | |
| 158 | expect(takeDbTime(a)).toBeUndefined(); | |
| 159 | expect(takeSessionTime(a)).toBe(3); | |
| 160 | expect(takeSessionTime(a)).toBe(0); | |
| 161 | }); |
new above
offline