b2e15bbd2a
The proxy in front of every page, RSC, prefetch and /api request makes several sequential network calls (getUser, session state, the resolve_active_company RPC, MFA factor lookups) and nothing measured them, while the route wrapper has logged authMs/companyMs/handlerMs per API call for months. This is the first PR of the responsiveness plan (customer report: "it takes time before all fields load when clicking around"): the baseline every later change is measured against. - lib/supabase/proxy-timing.ts: pure helpers (request classification from the app-router headers, route template that collapses ids and tokens, Server-Timing formatting, a timed() accumulator). - lib/supabase/middleware.ts: updateSession wraps updateSessionInner, times each phase, sets Server-Timing on page/RSC/prefetch responses and X-Proxy-Timing on /api responses (withRouteContext owns Server-Timing there), and emits one "proxy completed" log line per request. - scripts/perf/log-percentiles.ts: p50/p90/p99 per group over `vercel logs --json` output, for both "op completed" and "proxy completed"; scripts/perf/README.md documents the protocol and targets. Co-authored-by: Jakob Wennberg <311770904+jakobwennberg-oss@users.noreply.github.com> Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
116 lines
4.0 KiB
TypeScript
116 lines
4.0 KiB
TypeScript
/**
|
|
* Per-request timing for the auth proxy (lib/supabase/middleware.ts).
|
|
*
|
|
* The proxy runs in front of every page, RSC, prefetch and /api request and
|
|
* makes several sequential network calls (Supabase Auth, the active-company
|
|
* RPC, MFA factor lookups). Nothing measured that cost until now, while the
|
|
* route wrapper (lib/api/with-route-context.ts) has logged authMs/companyMs/
|
|
* handlerMs per API call for months. These helpers give the proxy the same
|
|
* Server-Timing header and one structured "proxy completed" log line per
|
|
* request so the fixed per-request cost can be read off Vercel logs and the
|
|
* browser Timing tab instead of guessed.
|
|
*
|
|
* Pure functions only: the middleware test suite mocks Supabase heavily, so
|
|
* classification and formatting live here where they can be unit-tested
|
|
* without that harness.
|
|
*/
|
|
|
|
export type ProxyRequestKind = 'api' | 'prefetch' | 'rsc' | 'page'
|
|
|
|
export interface ProxyTimings {
|
|
/** supabase.auth.getUser(): a network round trip to Supabase Auth. */
|
|
authMs: number
|
|
/** Session-timeout state: getClaims + HMAC verify + auto_logout read. */
|
|
sessionMs: number
|
|
/** resolve_active_company RPC (or the query fallback) incl. write-back. */
|
|
companyMs: number
|
|
/** MFA assurance level + listFactors (the latter is a network call). */
|
|
mfaMs: number
|
|
}
|
|
|
|
export type ProxyTimingKey = keyof ProxyTimings
|
|
|
|
/**
|
|
* Header used on /api responses. withRouteContext owns `Server-Timing` on
|
|
* API routes and only sets it when absent, so the proxy's numbers travel on
|
|
* a separate header there; on page/RSC responses nothing else sets
|
|
* Server-Timing and the proxy uses the standard header directly.
|
|
*/
|
|
export const PROXY_TIMING_HEADER = 'X-Proxy-Timing'
|
|
|
|
export function createProxyTimings(): ProxyTimings {
|
|
return { authMs: 0, sessionMs: 0, companyMs: 0, mfaMs: 0 }
|
|
}
|
|
|
|
/** Run `fn` and add its wall time to `timing[key]` (accumulates on repeats). */
|
|
export async function timed<T>(
|
|
timing: ProxyTimings,
|
|
key: ProxyTimingKey,
|
|
fn: () => Promise<T>,
|
|
): Promise<T> {
|
|
const start = Date.now()
|
|
try {
|
|
return await fn()
|
|
} finally {
|
|
timing[key] += Date.now() - start
|
|
}
|
|
}
|
|
|
|
/**
|
|
* Which kind of request the proxy is fronting. Prefetch and RSC requests
|
|
* are recognised by the headers the Next.js app router sends
|
|
* (`Next-Router-Prefetch: 1`, `RSC: 1`); header names are case-insensitive
|
|
* on the Fetch `Headers` interface, so lower-case lookups are fine.
|
|
*/
|
|
export function classifyProxyRequest(
|
|
pathname: string,
|
|
headers: Headers,
|
|
): ProxyRequestKind {
|
|
if (pathname.startsWith('/api')) return 'api'
|
|
if (headers.get('next-router-prefetch') === '1') return 'prefetch'
|
|
if (headers.get('rsc') === '1') return 'rsc'
|
|
return 'page'
|
|
}
|
|
|
|
const UUID_RE =
|
|
/^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i
|
|
const NUMERIC_RE = /^\d+$/
|
|
/** Prefixes whose tail is a secret (invite tokens, payslip links, PKCE). */
|
|
const TOKEN_PREFIXES = ['/invite', '/payslip', '/auth']
|
|
|
|
/**
|
|
* Collapse a concrete pathname to a loggable route template: UUIDs become
|
|
* `:id`, numbers `:n`, long opaque segments `:token`, and paths under the
|
|
* token-carrying prefixes are cut to the prefix so a secret never lands in
|
|
* a log line.
|
|
*/
|
|
export function proxyRouteTemplate(pathname: string): string {
|
|
for (const prefix of TOKEN_PREFIXES) {
|
|
if (pathname === prefix || pathname.startsWith(`${prefix}/`)) {
|
|
return `${prefix}/*`
|
|
}
|
|
}
|
|
const segments = pathname.split('/').map((segment) => {
|
|
if (segment === '') return segment
|
|
if (UUID_RE.test(segment)) return ':id'
|
|
if (NUMERIC_RE.test(segment)) return ':n'
|
|
if (segment.length >= 24) return ':token'
|
|
return segment
|
|
})
|
|
return segments.join('/') || '/'
|
|
}
|
|
|
|
/** `Server-Timing` value: one `mw-*` metric per phase plus the total. */
|
|
export function formatProxyServerTiming(
|
|
timing: ProxyTimings,
|
|
totalMs: number,
|
|
): string {
|
|
return [
|
|
`mw-auth;dur=${timing.authMs}`,
|
|
`mw-session;dur=${timing.sessionMs}`,
|
|
`mw-company;dur=${timing.companyMs}`,
|
|
`mw-mfa;dur=${timing.mfaMs}`,
|
|
`mw-total;dur=${totalMs}`,
|
|
].join(', ')
|
|
}
|