feat(perf): measure the auth proxy per request (Server-Timing + proxy completed log) (#1922)

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>

lib/supabase/__tests__/middleware.test.ts

@@ -72,6 +72,19 @@ vi.mock('@supabase/ssr', () => ({
   })),
 }))
 
+const logState = vi.hoisted(() => ({ info: vi.fn() }))
+
+vi.mock('@/lib/logger', () => {
+  const logger = {
+    info: (...args: unknown[]) => logState.info(...args),
+    warn: vi.fn(),
+    error: vi.fn(),
+    debug: vi.fn(),
+    child: () => logger,
+  }
+  return { createLogger: () => logger }
+})
+
 import { updateSession } from '../middleware'
 import {
   createSessionTimeoutState,
@@ -103,6 +116,7 @@ describe('updateSession redirect destinations', () => {
 
   beforeEach(() => {
     vi.clearAllMocks()
+    logState.info.mockClear()
     state.user = null
     state.sessionId = 'session-1'
     state.authError = null
@@ -535,6 +549,67 @@ describe('updateSession redirect destinations', () => {
 
   // ── MFA semantics that must not change ────────────────────────────────
 
+  describe('per-request timing header and log line', () => {
+    const TIMING_RE =
+      /^mw-auth;dur=\d+, mw-session;dur=\d+, mw-company;dur=\d+, mw-mfa;dur=\d+, mw-total;dur=\d+$/
+
+    function lastLog() {
+      expect(logState.info).toHaveBeenCalledTimes(1)
+      const [msg, ctx] = logState.info.mock.calls[0] as [string, Record<string, unknown>]
+      expect(msg).toBe('proxy completed')
+      return ctx
+    }
+
+    it('page responses carry Server-Timing and log kind=page with the route', async () => {
+      state.user = SIGNED_IN
+      const res = await run('/invoices')
+      expect(res.status).toBe(200)
+      expect(res.headers.get('server-timing')).toMatch(TIMING_RE)
+      expect(res.headers.get('x-proxy-timing')).toBeNull()
+      const ctx = lastLog()
+      expect(ctx.kind).toBe('page')
+      expect(ctx.route).toBe('/invoices')
+      expect(ctx.status).toBe(200)
+      expect(typeof ctx.totalMs).toBe('number')
+      expect(typeof ctx.authMs).toBe('number')
+      expect(typeof ctx.companyMs).toBe('number')
+    })
+
+    it('classifies prefetch and RSC requests from the app-router headers', async () => {
+      state.user = SIGNED_IN
+      await run('/invoices', { headers: { 'next-router-prefetch': '1', rsc: '1' } })
+      expect(lastLog().kind).toBe('prefetch')
+      logState.info.mockClear()
+      await run('/invoices', { headers: { rsc: '1' } })
+      expect(lastLog().kind).toBe('rsc')
+    })
+
+    it('/api responses use X-Proxy-Timing and leave Server-Timing to the route wrapper', async () => {
+      state.user = SIGNED_IN
+      const res = await run('/api/settings')
+      expect(res.headers.get('x-proxy-timing')).toMatch(TIMING_RE)
+      expect(res.headers.get('server-timing')).toBeNull()
+      expect(lastLog().kind).toBe('api')
+    })
+
+    it('redirect responses also carry the header and log their status', async () => {
+      const res = await run('/invoices')
+      expect(res.status).toBe(307)
+      expect(res.headers.get('server-timing')).toMatch(TIMING_RE)
+      expect(lastLog().status).toBe(307)
+    })
+
+    it('never logs a token-carrying path or a raw entity id', async () => {
+      const res = await run('/invite/9f8e7d6c5b4a3928171605f4e3d2c1b0')
+      expect(res.status).toBe(200)
+      expect(lastLog().route).toBe('/invite/*')
+      logState.info.mockClear()
+      state.user = SIGNED_IN
+      await run('/invoices/6f1c2a3e-1234-4bcd-9abc-0123456789ab')
+      expect(lastLog().route).toBe('/invoices/:id')
+    })
+  })
+
   describe('MFA-disabled and self-hosted paths are unchanged', () => {
     it('does not redirect when NEXT_PUBLIC_REQUIRE_MFA is unset', async () => {
       state.user = SIGNED_IN

lib/supabase/__tests__/proxy-timing.test.ts

@@ -0,0 +1,83 @@
+import { describe, it, expect } from 'vitest'
+import {
+  classifyProxyRequest,
+  createProxyTimings,
+  formatProxyServerTiming,
+  proxyRouteTemplate,
+  timed,
+} from '../proxy-timing'
+
+describe('classifyProxyRequest', () => {
+  it('treats /api paths as api regardless of headers', () => {
+    const headers = new Headers({ 'next-router-prefetch': '1', rsc: '1' })
+    expect(classifyProxyRequest('/api/settings', headers)).toBe('api')
+  })
+
+  it('recognises app-router prefetch and RSC requests by header', () => {
+    expect(
+      classifyProxyRequest('/invoices', new Headers({ 'Next-Router-Prefetch': '1', RSC: '1' })),
+    ).toBe('prefetch')
+    expect(classifyProxyRequest('/invoices', new Headers({ RSC: '1' }))).toBe('rsc')
+  })
+
+  it('falls back to page for a plain document request', () => {
+    expect(classifyProxyRequest('/invoices', new Headers())).toBe('page')
+  })
+})
+
+describe('proxyRouteTemplate', () => {
+  it('replaces UUID and numeric segments with placeholders', () => {
+    expect(proxyRouteTemplate('/invoices/6f1c2a3e-1234-4bcd-9abc-0123456789ab/edit')).toBe(
+      '/invoices/:id/edit',
+    )
+    expect(proxyRouteTemplate('/salary/runs/42')).toBe('/salary/runs/:n')
+  })
+
+  it('collapses token-carrying prefixes so secrets never reach the log', () => {
+    expect(proxyRouteTemplate('/invite/9f8e7d6c5b4a3928171605f4e3d2c1b0')).toBe('/invite/*')
+    expect(proxyRouteTemplate('/payslip/abc')).toBe('/payslip/*')
+    expect(proxyRouteTemplate('/auth/callback')).toBe('/auth/*')
+    expect(proxyRouteTemplate('/auth')).toBe('/auth/*')
+  })
+
+  it('masks long opaque segments outside the known prefixes', () => {
+    expect(proxyRouteTemplate('/e/sector/aVeryLongOpaqueSlugThatLooksLikeAToken')).toBe(
+      '/e/sector/:token',
+    )
+  })
+
+  it('keeps ordinary routes and the root untouched', () => {
+    expect(proxyRouteTemplate('/settings/company')).toBe('/settings/company')
+    expect(proxyRouteTemplate('/')).toBe('/')
+  })
+})
+
+describe('formatProxyServerTiming', () => {
+  it('emits one mw-* metric per phase plus the total', () => {
+    const timing = { authMs: 12, sessionMs: 3, companyMs: 40, mfaMs: 0 }
+    expect(formatProxyServerTiming(timing, 61)).toBe(
+      'mw-auth;dur=12, mw-session;dur=3, mw-company;dur=40, mw-mfa;dur=0, mw-total;dur=61',
+    )
+  })
+})
+
+describe('timed', () => {
+  it('returns the wrapped value and accumulates elapsed time on the key', async () => {
+    const timing = createProxyTimings()
+    const value = await timed(timing, 'sessionMs', async () => 'ok')
+    expect(value).toBe('ok')
+    await timed(timing, 'sessionMs', async () => undefined)
+    expect(timing.sessionMs).toBeGreaterThanOrEqual(0)
+    expect(timing.authMs).toBe(0)
+  })
+
+  it('still records time when the wrapped call throws', async () => {
+    const timing = createProxyTimings()
+    await expect(
+      timed(timing, 'authMs', async () => {
+        throw new Error('boom')
+      }),
+    ).rejects.toThrow('boom')
+    expect(timing.authMs).toBeGreaterThanOrEqual(0)
+  })
+})