From 4679b8f07da38294b54076c1b99d36d8075f5401 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 18 Jul 2026 06:09:40 +0000 Subject: [PATCH] feat(observability): admin-only per-request timing detail via X-OS-Debug-Timing: json (#2408) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Completes the optional "richer JSON" diagnostic from #2408. On top of the basic Server-Timing header, an admin/service caller can request a per-query breakdown — the slowest SQL statements + a query count — with `X-OS-Debug-Timing: json`, returned in a separate `X-OS-Debug-Timing-Detail` header (compact JSON). It is admin-only **even under global mode** — an ordinary caller never sees SQL shapes. - observability: `PerfTiming` gains opt-in per-event detail capture (`enableDetail` / `recordDetail` / `details`) + ambient `recordServerTimingDetail`. The disclosure gate gains a `privileged` level (set by `allowPerfDisclosure`, read via `isPerfDisclosurePrivileged`) so the richer detail is gated independently of the basic header. - driver-sql: with detail on, the query listener also records each query's PARAMETRIZED statement (knex `q.sql`, `?` placeholders) — never the bindings, so no literal row value enters the collector. Free when detail is off. - plugin-hono-server: `X-OS-Debug-Timing: json` enables capture; the middleware emits `X-OS-Debug-Timing-Detail` (slowest queries, capped + sanitized to header-safe ASCII) only for a proven admin. Tests: unit coverage for the detail collector, the privileged gate level, the driver's parametrized-SQL capture, the middleware's json/basic/global paths, and a real-HTTP end-to-end test (admin gets the detail header over a genuine socket running real SQL; a non-admin never does, even under global mode). Docs + changeset updated. Basic/global behavior unchanged; `json` is purely additive. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_011upHdyr5AnNc6dWAu63qxD --- .changeset/perf-timing-admin-detail.md | 29 ++++ docs/OBSERVABILITY.md | 30 +++- packages/observability/src/index.ts | 3 + .../observability/src/perf-timing.test.ts | 79 ++++++++++ packages/observability/src/perf-timing.ts | 115 ++++++++++++++- .../src/sql-driver-server-timing.test.ts | 27 ++++ packages/plugins/driver-sql/src/sql-driver.ts | 18 ++- .../plugin-hono-server/src/hono-plugin.ts | 101 ++++++++++++- .../src/server-timing.test.ts | 139 +++++++++++++++++- .../src/server-timing.integration.test.ts | 38 +++++ 10 files changed, 558 insertions(+), 21 deletions(-) create mode 100644 .changeset/perf-timing-admin-detail.md diff --git a/.changeset/perf-timing-admin-detail.md b/.changeset/perf-timing-admin-detail.md new file mode 100644 index 0000000000..c5822ad5de --- /dev/null +++ b/.changeset/perf-timing-admin-detail.md @@ -0,0 +1,29 @@ +--- +"@objectstack/observability": minor +"@objectstack/plugin-hono-server": minor +"@objectstack/driver-sql": minor +--- + +feat(observability): admin-only richer per-request timing detail via `X-OS-Debug-Timing: json` (#2408) + +Completes the optional "richer JSON" diagnostic from #2408. In addition to the +basic `Server-Timing` header, an admin/service caller can now request a +per-query breakdown — the slowest SQL statements and a query count — by sending +`X-OS-Debug-Timing: json`. The detail is returned in a separate +`X-OS-Debug-Timing-Detail` response header (compact JSON) and is **admin-only, +even under global mode**: an ordinary caller never sees SQL shapes. + +- **observability**: `PerfTiming` gains opt-in per-event detail capture + (`enableDetail` / `recordDetail` / `details`) plus the ambient + `recordServerTimingDetail`. The disclosure gate gains a `privileged` level + (set by `allowPerfDisclosure`, read via `isPerfDisclosurePrivileged`) so the + richer detail can be gated independently of the basic header. +- **driver-sql**: when detail capture is on, the query listener additionally + records each query's **parametrized** statement (knex's `q.sql`, `?` + placeholders) — never the bindings, so no literal row value ever enters the + collector. Zero overhead when detail is off. +- **plugin-hono-server**: `X-OS-Debug-Timing: json` enables detail capture; the + middleware emits `X-OS-Debug-Timing-Detail` (slowest queries, capped and + sanitized to header-safe ASCII) only when the principal is a proven admin. + +Basic and global behavior are unchanged; `json` is purely additive. diff --git a/docs/OBSERVABILITY.md b/docs/OBSERVABILITY.md index 9a8f2b106e..659b5598dd 100644 --- a/docs/OBSERVABILITY.md +++ b/docs/OBSERVABILITY.md @@ -271,6 +271,28 @@ they can never pull timings, so this is safe to leave available on a live environment. This is the path to reach for when diagnosing "why is *this* request slow?" against a running environment. +For a per-query breakdown, an admin sends `json` instead: + +``` +X-OS-Debug-Timing: json +``` + +which adds an **admin-only** `X-OS-Debug-Timing-Detail` response header — compact +JSON listing the slowest SQL statements (by shape), the single slowest, and the +query count: + +```json +{"db":{"count":6,"totalMs":210.3,"slowest":{"sql":"select * from widgets where id = ?","dur":88.1},"queries":[{"sql":"select * from widgets where id = ?","dur":88.1}, …]}} +``` + +The statements are **parametrized** — knex's `?` placeholders, never the +bindings — so the query *shape* (the useful part for spotting N round-trips) is +exposed while literal row values never leave the server. The detail is +**admin-only even under global mode**: an ordinary caller who sends `json` still +gets the basic `Server-Timing` header (if global mode is on) but never the +`X-OS-Debug-Timing-Detail` payload. The list is capped and the labels sanitized +to header-safe ASCII. + To hard-disable both paths (no middleware registered at all), set `serverTiming: false` explicitly. @@ -285,7 +307,7 @@ out of the box: | `handler` | HTTP adapter | Route-handler execution. | | `serialize` | HTTP adapter | Response JSON encoding. | | `auth` | Dispatcher | Identity / session resolution — the prime suspect for unexplained data-API overhead. | -| `db` | SQL driver | Total SQL time across the request; `desc` is the **query count** (folded from knex's per-query events, attributed to the originating request via `AsyncLocalStorage` so it is correct under concurrency). SQL text is never emitted. | +| `db` | SQL driver | Total SQL time across the request; `desc` is the **query count** (folded from knex's per-query events, attributed to the originating request via `AsyncLocalStorage` so it is correct under concurrency). The basic header carries no SQL text; individual **parametrized** statements appear only in the admin-only `X-OS-Debug-Timing: json` detail payload. | | `hooks` | ObjectQL engine | Total business-hook execution time; `desc` is the hook count. | Each phase is recorded through a request-scoped collector that is a no-op when @@ -336,5 +358,7 @@ countServerTiming('db', queryMs, 'queries'); // → db;dur=;desc=" queri - [ ] Alerts wired: error rate, p95 latency per route. - [ ] (Optional) `Server-Timing` verified in DevTools with global mode (`serverTiming: true` / `OS_PERF_TIMING=1`) on, confirmed **absent** for a - normal request, and confirmed the per-request `X-OS-Debug-Timing: 1` header - returns timing **only** to an admin/service caller. + normal request, confirmed the per-request `X-OS-Debug-Timing: 1` header + returns timing **only** to an admin/service caller, and confirmed + `X-OS-Debug-Timing: json` returns the `X-OS-Debug-Timing-Detail` payload + **only** to an admin (never to an ordinary caller, even under global mode). diff --git a/packages/observability/src/index.ts b/packages/observability/src/index.ts index 14afff89fb..6d0dff81a0 100644 --- a/packages/observability/src/index.ts +++ b/packages/observability/src/index.ts @@ -52,9 +52,12 @@ export { startServerTiming, measureServerTiming, countServerTiming, + recordServerTimingDetail, runWithPerfDisclosure, allowPerfDisclosure, isPerfDisclosureAllowed, + isPerfDisclosurePrivileged, type ServerTimingMark, + type ServerTimingDetail, type PerfDisclosureGate, } from './perf-timing.js'; diff --git a/packages/observability/src/perf-timing.test.ts b/packages/observability/src/perf-timing.test.ts index e49b8fd03c..7fb5b3eb71 100644 --- a/packages/observability/src/perf-timing.test.ts +++ b/packages/observability/src/perf-timing.test.ts @@ -13,6 +13,8 @@ import { runWithPerfDisclosure, allowPerfDisclosure, isPerfDisclosureAllowed, + isPerfDisclosurePrivileged, + recordServerTimingDetail, type PerfDisclosureGate, } from './perf-timing.js'; @@ -213,11 +215,88 @@ describe('ambient collector', () => { }); }); +describe('detail capture', () => { + it('is off by default — recordDetail is a no-op, details() empty', () => { + const t = new PerfTiming(); + expect(t.detailEnabled).toBe(false); + t.recordDetail('db', 'select * from x where id = ?', 5); + expect(t.details('db')).toEqual([]); + }); + + it('captures per-event samples once enabled', () => { + const t = new PerfTiming(); + t.enableDetail(); + t.recordDetail('db', 'select a from t', 3); + t.recordDetail('db', 'select b from t where id = ?', 9); + const db = t.details('db'); + expect(db).toHaveLength(2); + expect(db[1]).toEqual({ label: 'select b from t where id = ?', dur: 9 }); + }); + + it('keeps categories separate and coerces bad durations to 0', () => { + const t = new PerfTiming(); + t.enableDetail(); + t.recordDetail('db', 'q', Number.NaN); + t.recordDetail('hooks', 'h', -4); + expect(t.details('db')).toEqual([{ label: 'q', dur: 0 }]); + expect(t.details('hooks')).toEqual([{ label: 'h', dur: 0 }]); + }); + + it('bounds retained samples at the cap', () => { + const t = new PerfTiming(); + t.enableDetail(); + for (let i = 0; i < 1200; i++) t.recordDetail('db', `q${i}`, 1); + expect(t.details('db').length).toBe(1000); + }); + + it('recordServerTimingDetail folds onto the ambient collector only when enabled', async () => { + const off = new PerfTiming(); + await runWithPerfTiming(off, async () => { + recordServerTimingDetail('db', 'select 1', 2); // detail off → dropped + }); + expect(off.details('db')).toEqual([]); + + const on = new PerfTiming(); + on.enableDetail(); + await runWithPerfTiming(on, async () => { + recordServerTimingDetail('db', 'select 1 where id = ?', 2); + }); + expect(on.details('db')).toEqual([{ label: 'select 1 where id = ?', dur: 2 }]); + }); + + it('recordServerTimingDetail is a no-op with no active collector', () => { + recordServerTimingDetail('db', 'select 1', 1); // must not throw + }); +}); + describe('disclosure gate', () => { it('isPerfDisclosureAllowed() is false with no active gate', () => { expect(isPerfDisclosureAllowed()).toBe(false); }); + it('privileged is false with no active gate, and allowPerfDisclosure sets both', () => { + expect(isPerfDisclosurePrivileged()).toBe(false); + const gate: PerfDisclosureGate = { allowed: false }; + runWithPerfDisclosure(gate, () => { + expect(isPerfDisclosurePrivileged()).toBe(false); + allowPerfDisclosure(); + expect(isPerfDisclosureAllowed()).toBe(true); + expect(isPerfDisclosurePrivileged()).toBe(true); + }); + expect(gate.allowed).toBe(true); + expect(gate.privileged).toBe(true); + }); + + it('global-mode disclosure (allowed but not privileged) does not grant privilege', () => { + // The middleware seeds `{ allowed: true }` for global mode WITHOUT calling + // allowPerfDisclosure — so basic timing discloses but detail stays gated. + const gate: PerfDisclosureGate = { allowed: true }; + runWithPerfDisclosure(gate, () => { + expect(isPerfDisclosureAllowed()).toBe(true); + expect(isPerfDisclosurePrivileged()).toBe(false); + }); + }); + it('allowPerfDisclosure() is a no-op with no active gate (does not throw)', () => { allowPerfDisclosure(); expect(isPerfDisclosureAllowed()).toBe(false); diff --git a/packages/observability/src/perf-timing.ts b/packages/observability/src/perf-timing.ts index 6637f15eac..f4cbf7dad3 100644 --- a/packages/observability/src/perf-timing.ts +++ b/packages/observability/src/perf-timing.ts @@ -45,6 +45,21 @@ export interface ServerTimingMark { desc?: string; } +/** + * One recorded sub-event when DETAIL capture is on (see + * {@link PerfTiming.enableDetail}). Unlike the aggregate `db` mark — which folds + * every query into a single count+duration — a detail sample keeps the + * individual event so an admin can see *which* queries ran and which was + * slowest. `label` is a description of the event (for SQL: the PARAMETRIZED + * statement, bindings stripped — the query shape, never literal row values). + */ +export interface ServerTimingDetail { + /** Event label — e.g. a parametrized SQL statement (no bindings). */ + label: string; + /** Duration in milliseconds. */ + dur: number; +} + /** * Monotonic millisecond clock. Prefers `performance.now()` (monotonic, not * affected by wall-clock adjustments); falls back to `Date.now()` on the rare @@ -138,12 +153,64 @@ export class PerfTiming { * already inserted into {@link _marks}, mutated in place as events arrive. */ private _aggregates?: Map; + /** + * Per-event detail samples by category, populated only while detail capture + * is on (see {@link enableDetail}). Lazily created so a request that never + * enables detail pays nothing. + */ + private _detail?: Map; + private _detailOn = false; + /** + * Hard cap on stored detail samples per category — detail is only ever on + * for a deliberate debug request, but a pathological request must not pin + * unbounded memory. The aggregate {@link count} still reflects the true + * total; only the retained per-event list is bounded. + */ + private static readonly DETAIL_CAP = 1000; /** Record an already-measured phase. */ record(name: string, dur: number, desc?: string): void { this._marks.push({ name, dur, desc }); } + /** + * Turn on per-event DETAIL capture for this request. Off by default so the + * hot path never allocates a per-event list; the HTTP middleware enables it + * only for an admin-gated `X-OS-Debug-Timing: json` request. Idempotent. + */ + enableDetail(): void { + this._detailOn = true; + } + + /** Whether per-event detail capture is on. */ + get detailEnabled(): boolean { + return this._detailOn; + } + + /** + * Record one per-event detail sample under `category` (e.g. `'db'`). A no-op + * unless {@link enableDetail} was called, so the hot-path call site (the SQL + * driver's query listener) pays only a boolean check when detail is off. + * Bounded by {@link DETAIL_CAP}; excess events still count toward the + * aggregate via {@link count} but are not retained individually. + */ + recordDetail(category: string, label: string, dur: number): void { + if (!this._detailOn) return; + const detail = (this._detail ??= new Map()); + let list = detail.get(category); + if (!list) { + list = []; + detail.set(category, list); + } + if (list.length >= PerfTiming.DETAIL_CAP) return; + list.push({ label: String(label), dur: Number.isFinite(dur) && dur > 0 ? dur : 0 }); + } + + /** Retained detail samples for `category`, in record order (empty when none). */ + details(category: string): readonly ServerTimingDetail[] { + return this._detail?.get(category) ?? []; + } + /** * Begin timing a phase. Returns an idempotent `end()` - the first call * records the elapsed duration; later calls are ignored, so it is safe to @@ -284,6 +351,16 @@ export function countServerTiming(name: string, dur: number, unit?: string): voi store.getStore()?.count(name, dur, unit); } +/** + * Record a per-event DETAIL sample (e.g. one parametrized SQL statement) onto + * the ambient collector — see {@link PerfTiming.recordDetail}. A no-op when no + * collector is active OR detail capture is off, so the hot-path call site pays + * only an `AsyncLocalStorage` lookup + a boolean check when not debugging. + */ +export function recordServerTimingDetail(category: string, label: string, dur: number): void { + store.getStore()?.recordDetail(category, label, dur); +} + // --- Disclosure gate (WHO may see the timing) ------------------------- /** @@ -302,10 +379,23 @@ export function countServerTiming(name: string, dur: number, unit?: string): voi * * Keeping this out of {@link PerfTiming} preserves the collector's invariant * ("it only measures, it never decides whether to emit"). + * + * Two levels, because global mode discloses the basic header to everyone but the + * richer per-query detail must stay admin-only: + * - `allowed` — the basic `Server-Timing` header may be disclosed (opened by + * global mode for everyone, or by a proven admin per-request). + * - `privileged` — the principal is a proven admin/service. Gates the richer, + * SQL-shape-bearing detail payload, which must NEVER reach an + * ordinary caller even when global mode is on. */ export interface PerfDisclosureGate { - /** Whether the collected timing may be disclosed to the client. */ + /** Whether the basic collected timing may be disclosed to the client. */ allowed: boolean; + /** + * Whether the principal is a proven admin/service — gates the richer detail + * payload independently of `allowed`. Absent = not privileged. + */ + privileged?: boolean; } /** @@ -330,17 +420,30 @@ export function runWithPerfDisclosure(gate: PerfDisclosureGate, fn: () => T): } /** - * Open the ambient disclosure gate — the request has proven it may see its own - * `Server-Timing` header (admin/service identity). A no-op when no gate is - * active (perf-tuning off, or already-global mode with no gate to flip), so the - * call site stays branch-free. + * Open the ambient disclosure gate — the request has proven an admin/service + * identity, so it may see its own `Server-Timing` header AND the richer detail + * payload. Sets both {@link PerfDisclosureGate.allowed} and `privileged`. A + * no-op when no gate is active (perf-tuning off), so the call site stays + * branch-free. */ export function allowPerfDisclosure(): void { const g = gateStore.getStore(); - if (g) g.allowed = true; + if (g) { + g.allowed = true; + g.privileged = true; + } } /** Whether the ambient disclosure gate is open. `false` when none is active. */ export function isPerfDisclosureAllowed(): boolean { return gateStore.getStore()?.allowed ?? false; } + +/** + * Whether the ambient principal is a proven admin/service — gates the richer + * detail payload. `false` when no gate is active or only global-mode disclosure + * (not a proven admin) opened it. + */ +export function isPerfDisclosurePrivileged(): boolean { + return gateStore.getStore()?.privileged ?? false; +} diff --git a/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts b/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts index cfedf1e385..84dc093eee 100644 --- a/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts +++ b/packages/plugins/driver-sql/src/sql-driver-server-timing.test.ts @@ -100,4 +100,31 @@ describe('SqlDriver Server-Timing db span', () => { }); expect(dbMark(t)?.desc).toBe('1 queries'); }); + + describe('detail mode (admin-gated per-query SQL shapes)', () => { + it('records NO per-query detail when detail capture is off', async () => { + const t = new PerfTiming(); // detail not enabled + await runWithPerfTiming(t, async () => { + await knexInstance('orders').where({ status: 'open' }).select('*'); + }); + expect(dbMark(t)?.desc).toMatch(/^\d+ queries$/); // aggregate still recorded + expect(t.details('db')).toEqual([]); // …but no SQL shapes retained + }); + + it('records parametrized SQL (no bindings) when detail capture is on', async () => { + const t = new PerfTiming(); + t.enableDetail(); + await runWithPerfTiming(t, async () => { + await knexInstance('orders').where({ status: 'open' }).select('*'); + }); + const detail = t.details('db'); + expect(detail.length).toBeGreaterThanOrEqual(1); + const sql = detail[0].label; + // Parametrized: carries a `?` placeholder, never the literal 'open'. + expect(sql).toContain('?'); + expect(sql.toLowerCase()).toContain('select'); + expect(sql).not.toContain('open'); + expect(detail[0].dur).toBeGreaterThanOrEqual(0); + }); + }); }); diff --git a/packages/plugins/driver-sql/src/sql-driver.ts b/packages/plugins/driver-sql/src/sql-driver.ts index 086841a038..03a8ff0f89 100644 --- a/packages/plugins/driver-sql/src/sql-driver.ts +++ b/packages/plugins/driver-sql/src/sql-driver.ts @@ -561,8 +561,13 @@ export class SqlDriver implements IDataDriver { * nothing is tracked and the map stays empty, so the cost is a single ALS * lookup per query. * - * Only durations and a count are recorded — never SQL text — so the header - * can be surfaced without leaking query shapes to non-admins. + * The aggregate records only durations and a count — never SQL text — so the + * `Server-Timing` header can be surfaced without leaking query shapes to + * non-admins. When an admin opts into DETAIL mode (`X-OS-Debug-Timing: json`, + * admin-gated), each query's PARAMETRIZED statement (knex's `q.sql`, which + * carries `?` placeholders — the bindings live separately and are NEVER + * recorded) is additionally captured so the admin-only detail payload can list + * the slowest queries by shape. Literal row values never enter the collector. */ private installQueryTiming(): void { // uid → { start, collector }, populated only while a collector is active, @@ -580,7 +585,14 @@ export class SqlDriver implements IDataDriver { const rec = inflight.get(uid); if (!rec) return; inflight.delete(uid); - rec.timing.count('db', perfNow() - rec.t0, 'queries'); + const dur = perfNow() - rec.t0; + rec.timing.count('db', dur, 'queries'); + // Admin-gated detail mode: keep the query SHAPE (parametrized SQL, no + // bindings) so the slowest queries can be surfaced. `recordDetail` is a + // no-op unless detail capture is on, so this is free on the normal path. + if (rec.timing.detailEnabled && typeof q?.sql === 'string') { + rec.timing.recordDetail('db', q.sql, dur); + } }; this.knex.on('query-response', (_response: any, q: any) => settle(q)); this.knex.on('query-error', (_error: any, q: any) => settle(q)); diff --git a/packages/plugins/plugin-hono-server/src/hono-plugin.ts b/packages/plugins/plugin-hono-server/src/hono-plugin.ts index 07074f015c..e13e5194fe 100644 --- a/packages/plugins/plugin-hono-server/src/hono-plugin.ts +++ b/packages/plugins/plugin-hono-server/src/hono-plugin.ts @@ -80,6 +80,10 @@ export interface HonoPluginOptions { * `X-OS-Debug-Timing: 1` and the header is returned ONLY after the request * resolves an admin/service identity (the dispatcher opens the disclosure * gate). Ordinary users can never pull timings just by sending the header. + * `X-OS-Debug-Timing: json` additionally returns an admin-only + * `X-OS-Debug-Timing-Detail` header — compact JSON listing the slowest + * per-query SQL *shapes* (parametrized, no bindings) — never disclosed to + * a non-admin, even under global mode. * - `serverTiming: false` hard-disables BOTH paths (no middleware). * * `undefined` (the default) leaves global mode off but keeps the @@ -139,13 +143,77 @@ export function foldWildcardSuperUser(objects: Record): void { } /** - * Whether a request opted into per-request perf timing via `X-OS-Debug-Timing`. - * Accepts the common truthy spellings; anything else (including absent) is off. + * How much per-request timing the caller opted into via `X-OS-Debug-Timing`: + * - `off` — no header sent (or an unrecognized value). + * - `basic` — `1` / `true` / `yes` / `on`: the `Server-Timing` header only. + * - `json` — `json` / `detail` / `verbose`: also the admin-only richer detail + * payload (per-query SQL shapes, slowest query). */ -export function isDebugTimingRequested(value: string | undefined | null): boolean { - if (!value) return false; +export type DebugTimingMode = 'off' | 'basic' | 'json'; + +/** Parse the `X-OS-Debug-Timing` request-header value into a {@link DebugTimingMode}. */ +export function debugTimingMode(value: string | undefined | null): DebugTimingMode { + if (!value) return 'off'; const v = value.trim().toLowerCase(); - return v === '1' || v === 'true' || v === 'yes' || v === 'on'; + if (v === 'json' || v === 'detail' || v === 'verbose') return 'json'; + if (v === '1' || v === 'true' || v === 'yes' || v === 'on') return 'basic'; + return 'off'; +} + +/** + * Whether a request opted into per-request perf timing via `X-OS-Debug-Timing` + * (any recognized mode — basic or json). + */ +export function isDebugTimingRequested(value: string | undefined | null): boolean { + return debugTimingMode(value) !== 'off'; +} + +/** Max individual queries listed in the detail payload (bounds header size). */ +const DETAIL_MAX_QUERIES = 20; +/** Max characters kept per query label in the detail payload. */ +const DETAIL_MAX_LABEL = 300; + +/** + * Coerce a detail label (a parametrized SQL statement) to a header-safe, + * printable-ASCII string: non-token bytes and control chars become spaces so the + * JSON stays valid and the `X-OS-Debug-Timing-Detail` header can never carry a + * CR/LF (header-injection) or a non-latin1 byte the Fetch Headers API rejects. + */ +function sanitizeDetailLabel(s: string): string { + let out = ''; + for (const ch of String(s)) { + const c = ch.codePointAt(0)!; + out += c >= 0x20 && c <= 0x7e ? ch : ' '; + } + return out.replace(/\s+/g, ' ').trim().slice(0, DETAIL_MAX_LABEL); +} + +/** + * Build the admin-only `X-OS-Debug-Timing-Detail` payload (compact JSON) from a + * collector's captured `db` detail: the slowest queries by shape, the single + * slowest, and the captured count + total. Returns `''` when nothing was + * captured. SQL is parametrized (no bindings) and sanitized to printable ASCII. + */ +export function buildTimingDetail(timing: PerfTiming): string { + const db = timing.details('db'); + if (db.length === 0) return ''; + const round = (n: number) => Math.round(n * 100) / 100; + const sorted = [...db].sort((a, b) => b.dur - a.dur); + const queries = sorted.slice(0, DETAIL_MAX_QUERIES).map((d) => ({ + sql: sanitizeDetailLabel(d.label), + dur: round(d.dur), + })); + const totalMs = round(db.reduce((sum, d) => sum + d.dur, 0)); + const payload: Record = { + db: { + count: db.length, + totalMs, + slowest: queries[0] ?? null, + queries, + ...(sorted.length > queries.length ? { truncated: sorted.length - queries.length } : {}), + }, + }; + return JSON.stringify(payload); } /** Minimal schema shape the managed-write clamp needs. */ @@ -267,12 +335,15 @@ export class HonoServerPlugin implements Plugin { process.env.OS_PERF_TIMING === 'true'; const rawApp = this.server.getRawApp(); rawApp.use('*', async (c, next) => { - const perRequest = isDebugTimingRequested(c.req.header('X-OS-Debug-Timing')); + const mode = debugTimingMode(c.req.header('X-OS-Debug-Timing')); // Nothing asked for timing on this request — a single header // read, then straight through. Zero collector overhead. - if (!globalTiming && !perRequest) return next(); + if (!globalTiming && mode === 'off') return next(); const timing = new PerfTiming(); + // `json` opts into per-query DETAIL capture (parametrized SQL + // shapes) — recorded now, disclosed later only to an admin. + if (mode === 'json') timing.enableDetail(); // Global mode opens the gate for everyone; the per-request path // starts closed and is opened only if an admin/service identity // is proven during dispatch (`allowPerfDisclosure`). @@ -285,6 +356,22 @@ export class HonoServerPlugin implements Plugin { // `append` (not `set`) so we coexist with any upstream proxy // that already added a Server-Timing entry. if (header) c.res.headers.append('Server-Timing', header); + // Richer per-query detail is ADMIN-ONLY — even under global mode + // an ordinary caller must never see SQL shapes. Emit only when the + // principal was proven privileged (admin/service) AND detail was + // requested/captured. + if (gate.privileged && timing.detailEnabled) { + const detail = buildTimingDetail(timing); + // Guard the append: an exotic label the Fetch Headers API + // still rejects must never break the response. + if (detail) { + try { + c.res.headers.append('X-OS-Debug-Timing-Detail', detail); + } catch { + /* header rejected — skip the detail, keep the response */ + } + } + } }); ctx.logger.debug('Server-Timing (perf-tuning) middleware enabled'); } diff --git a/packages/plugins/plugin-hono-server/src/server-timing.test.ts b/packages/plugins/plugin-hono-server/src/server-timing.test.ts index 89abfa3971..432f383624 100644 --- a/packages/plugins/plugin-hono-server/src/server-timing.test.ts +++ b/packages/plugins/plugin-hono-server/src/server-timing.test.ts @@ -1,8 +1,18 @@ // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. import { describe, it, expect, beforeEach, afterEach } from 'vitest'; -import { HonoServerPlugin, isDebugTimingRequested } from './hono-plugin'; -import { countServerTiming, allowPerfDisclosure } from '@objectstack/observability'; +import { + HonoServerPlugin, + isDebugTimingRequested, + debugTimingMode, + buildTimingDetail, +} from './hono-plugin'; +import { + countServerTiming, + allowPerfDisclosure, + recordServerTimingDetail, + PerfTiming, +} from '@objectstack/observability'; import type { PluginContext } from '@objectstack/core'; /** @@ -31,6 +41,24 @@ async function setup(opts: { serverTiming?: boolean } = {}) { allowPerfDisclosure(); return res.json({ ok: true }); }); + // Records two "SQL" queries exactly as the driver does — the aggregate + // (`count`) AND, when detail is on, the per-query shape (`recordDetail`). + const recordQuery = (sql: string, dur: number) => { + countServerTiming('db', dur, 'queries'); + recordServerTimingDetail('db', sql, dur); + }; + // Admin: proves identity via allowPerfDisclosure (as the dispatcher would). + server.get('/admin-db', (_req: any, res: any) => { + recordQuery('select * from widgets where id = ?', 12); + recordQuery('select count(*) from widgets', 4); + allowPerfDisclosure(); + return res.json({ ok: true }); + }); + // Non-admin, same queries: never calls allowPerfDisclosure. + server.get('/user-db', (_req: any, res: any) => { + recordQuery('select * from widgets where id = ?', 12); + return res.json({ ok: true }); + }); const app = server.getRawApp(); return { plugin, server, app }; } @@ -146,6 +174,113 @@ describe('Server-Timing (perf-tuning) middleware', () => { expect(res.headers.get('Server-Timing')).toMatch(/total;dur=/); }); }); + + describe('richer detail via X-OS-Debug-Timing: json', () => { + it('returns the admin-only detail header for a proven admin', async () => { + const { app } = await setup(); + const res = await app.request('/admin-db', { + headers: { 'X-OS-Debug-Timing': 'json' }, + }); + expect(res.status).toBe(200); + // Basic header still present… + expect(res.headers.get('Server-Timing')).toContain('db;dur='); + // …plus the richer detail payload. + const raw = res.headers.get('X-OS-Debug-Timing-Detail'); + expect(raw).toBeTruthy(); + const detail = JSON.parse(raw!); + expect(detail.db.count).toBe(2); + // Sorted slowest-first: the 12ms query wins. + expect(detail.db.slowest.sql).toBe('select * from widgets where id = ?'); + expect(detail.db.queries).toHaveLength(2); + expect(detail.db.queries[0].dur).toBe(12); + }); + + it('withholds the detail header from a non-admin (even with json)', async () => { + const { app } = await setup(); + const res = await app.request('/user-db', { + headers: { 'X-OS-Debug-Timing': 'json' }, + }); + // Non-admin, per-request → no basic header AND no detail header. + expect(res.headers.get('Server-Timing')).toBeNull(); + expect(res.headers.get('X-OS-Debug-Timing-Detail')).toBeNull(); + }); + + it('NEVER leaks detail to a non-admin under GLOBAL mode', async () => { + // Global mode discloses the basic header to everyone, but the SQL-shape + // detail must stay admin-only — the key confidentiality invariant. + const { app } = await setup({ serverTiming: true }); + const res = await app.request('/user-db', { + headers: { 'X-OS-Debug-Timing': 'json' }, + }); + expect(res.headers.get('Server-Timing')).toMatch(/db;dur=/); // basic: yes + expect(res.headers.get('X-OS-Debug-Timing-Detail')).toBeNull(); // detail: no + }); + + it('does not emit a detail header for basic mode (X-OS-Debug-Timing: 1)', async () => { + const { app } = await setup(); + const res = await app.request('/admin-db', { + headers: { 'X-OS-Debug-Timing': '1' }, + }); + expect(res.headers.get('Server-Timing')).toBeTruthy(); + // basic mode never enables detail capture, so no detail header + expect(res.headers.get('X-OS-Debug-Timing-Detail')).toBeNull(); + }); + }); +}); + +describe('debugTimingMode', () => { + it('maps json/detail/verbose → json', () => { + for (const v of ['json', 'detail', 'verbose', 'JSON', ' Detail ']) { + expect(debugTimingMode(v)).toBe('json'); + } + }); + it('maps truthy spellings → basic', () => { + for (const v of ['1', 'true', 'yes', 'on']) expect(debugTimingMode(v)).toBe('basic'); + }); + it('maps absent / unknown → off', () => { + for (const v of [undefined, null, '', '0', 'false', 'maybe']) { + expect(debugTimingMode(v)).toBe('off'); + } + }); +}); + +describe('buildTimingDetail', () => { + it('returns empty string when nothing was captured', () => { + const t = new PerfTiming(); + t.enableDetail(); + expect(buildTimingDetail(t)).toBe(''); + }); + + it('sorts slowest-first, sums total, and reports the slowest', () => { + const t = new PerfTiming(); + t.enableDetail(); + t.recordDetail('db', 'select a', 3); + t.recordDetail('db', 'select b where id = ?', 20); + t.recordDetail('db', 'select c', 7); + const detail = JSON.parse(buildTimingDetail(t)); + expect(detail.db.count).toBe(3); + expect(detail.db.totalMs).toBe(30); + expect(detail.db.slowest).toEqual({ sql: 'select b where id = ?', dur: 20 }); + expect(detail.db.queries.map((q: any) => q.dur)).toEqual([20, 7, 3]); + }); + + it('caps the query list and reports how many were truncated', () => { + const t = new PerfTiming(); + t.enableDetail(); + for (let i = 0; i < 25; i++) t.recordDetail('db', `q${i}`, i); + const detail = JSON.parse(buildTimingDetail(t)); + expect(detail.db.queries).toHaveLength(20); + expect(detail.db.truncated).toBe(5); + }); + + it('sanitizes labels to header-safe printable ASCII (no CR/LF)', () => { + const t = new PerfTiming(); + t.enableDetail(); + t.recordDetail('db', 'select 1\r\n\tDROP', 1); + const raw = buildTimingDetail(t); + expect(raw).not.toMatch(/[\r\n\t]/); + expect(JSON.parse(raw).db.queries[0].sql).toBe('select 1 DROP'); + }); }); describe('isDebugTimingRequested', () => { diff --git a/packages/runtime/src/server-timing.integration.test.ts b/packages/runtime/src/server-timing.integration.test.ts index d2e3c8e85c..b978e46ea4 100644 --- a/packages/runtime/src/server-timing.integration.test.ts +++ b/packages/runtime/src/server-timing.integration.test.ts @@ -4,6 +4,7 @@ import { describe, it, expect, beforeAll, afterAll } from 'vitest'; import { LiteKernel } from '@objectstack/core'; import { HonoServerPlugin } from '@objectstack/plugin-hono-server'; import { SqlDriver } from '@objectstack/driver-sql'; +import { allowPerfDisclosure } from '@objectstack/observability'; /** * End-to-end regression for the Server-Timing `db` span (issue #2408). @@ -48,6 +49,14 @@ describe('Server-Timing db span over a real HTTP server (integration)', () => { const one = await driver.find('widgets', { where: { id: '1' } }); res.json({ all: all.length, one: one.length }); }); + // Same queries, but the handler proves an admin/service identity — exactly + // what the dispatcher does after resolving the execution context. + httpServer.get('/widgets-admin', async (_req: any, res: any) => { + const all = await driver.find('widgets', {}); + const one = await driver.find('widgets', { where: { id: '1' } }); + allowPerfDisclosure(); + res.json({ all: all.length, one: one.length }); + }); baseUrl = `http://127.0.0.1:${httpServer.getPort()}`; }, 30_000); @@ -75,4 +84,33 @@ describe('Server-Timing db span over a real HTTP server (integration)', () => { expect(m, `expected a db span in: ${header}`).toBeTruthy(); expect(Number(m![1])).toBeGreaterThanOrEqual(2); }); + + it('returns the admin-only per-query detail header end-to-end (admin + json)', async () => { + const res = await fetch(`${baseUrl}/widgets-admin`, { + headers: { 'X-OS-Debug-Timing': 'json' }, + }); + expect(res.status).toBe(200); + // Basic header still present under global mode… + expect(res.headers.get('Server-Timing')).toContain('db;dur='); + // …plus the richer detail payload, gated to the proven admin. + const raw = res.headers.get('X-OS-Debug-Timing-Detail'); + expect(raw, 'expected an admin detail header').toBeTruthy(); + const detail = JSON.parse(raw!); + expect(detail.db.count).toBeGreaterThanOrEqual(2); + expect(typeof detail.db.slowest.sql).toBe('string'); + // The parametrized id-lookup reached the header as a `?` placeholder — + // the real SQL shape, captured by the driver across a genuine request. + expect(detail.db.queries.some((q: any) => q.sql.includes('?'))).toBe(true); + }); + + it('withholds the detail header from a non-admin, even under global mode + json', async () => { + const res = await fetch(`${baseUrl}/widgets`, { + headers: { 'X-OS-Debug-Timing': 'json' }, + }); + expect(res.status).toBe(200); + // Global mode still discloses the basic header… + expect(res.headers.get('Server-Timing')).toBeTruthy(); + // …but the SQL-shape detail is admin-only — the confidentiality invariant. + expect(res.headers.get('X-OS-Debug-Timing-Detail')).toBeNull(); + }); });