diff --git a/backend/src/__tests__/cache-service.test.ts b/backend/src/__tests__/cache-service.test.ts index 40e46c93..24725c5d 100644 --- a/backend/src/__tests__/cache-service.test.ts +++ b/backend/src/__tests__/cache-service.test.ts @@ -4,7 +4,7 @@ * the entry-cap safety guard, and singleton identity. */ import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; -import { CacheService } from '../services/CacheService'; +import { CacheService, type CacheFetchOutcome } from '../services/CacheService'; describe('CacheService', () => { let cache: CacheService; @@ -71,6 +71,107 @@ describe('CacheService', () => { }); }); + // ─── getOrFetchWithMeta: observational outcomes ────────────────────── + + describe('getOrFetchWithMeta', () => { + it('reports "computed" when this caller runs the fetcher', async () => { + const fetcher = vi.fn().mockResolvedValue('fresh'); + const res = await cache.getOrFetchWithMeta('ns:key', 60_000, fetcher); + expect(res).toEqual({ value: 'fresh', outcome: 'computed' }); + expect(fetcher).toHaveBeenCalledTimes(1); + expect(cache.getStats().ns).toEqual({ hits: 0, misses: 1, stale: 0, size: 1 }); + }); + + it('reports "hit" for a fresh entry without waiting or re-running the fetcher', async () => { + await cache.getOrFetchWithMeta('ns:key', 60_000, async () => 'cached'); + const fetcher = vi.fn().mockResolvedValue('should-not-run'); + const res = await cache.getOrFetchWithMeta('ns:key', 60_000, fetcher); + expect(res).toEqual({ value: 'cached', outcome: 'hit' }); + expect(fetcher).not.toHaveBeenCalled(); + // First call: 1 miss (computed). Second call: 1 hit. + expect(cache.getStats().ns).toMatchObject({ hits: 1, misses: 1, stale: 0 }); + }); + + it('reports "inflight" for a caller that joins an existing in-flight promise', async () => { + let resolveFetch!: (value: string) => void; + const fetcher = vi.fn(() => new Promise((resolve) => { + resolveFetch = resolve; + })); + + const p1 = cache.getOrFetchWithMeta('ns:key', 60_000, fetcher); + const p2 = cache.getOrFetchWithMeta('ns:key', 60_000, fetcher); + const p3 = cache.getOrFetchWithMeta('ns:key', 60_000, fetcher); + + resolveFetch('shared'); + const [r1, r2, r3] = await Promise.all([p1, p2, p3]); + + expect(r1).toEqual({ value: 'shared', outcome: 'computed' }); + expect(r2).toEqual({ value: 'shared', outcome: 'inflight' }); + expect(r3).toEqual({ value: 'shared', outcome: 'inflight' }); + expect(fetcher).toHaveBeenCalledTimes(1); + // Every caller that did not hit a fresh entry recorded exactly one miss, + // including the two in-flight joins: 3 misses, no hits. + expect(cache.getStats().ns).toMatchObject({ hits: 0, misses: 3, stale: 0 }); + }); + + it('reports "stale" when the fetcher rejects but a stale entry exists', async () => { + vi.useFakeTimers({ shouldAdvanceTime: true }); + const fetcher = vi.fn() + .mockResolvedValueOnce('original') + .mockRejectedValueOnce(new Error('upstream down')); + + const first = await cache.getOrFetchWithMeta('ns:key', 1_000, fetcher); + expect(first).toEqual({ value: 'original', outcome: 'computed' }); + + await vi.advanceTimersByTimeAsync(1_100); + + const stale = await cache.getOrFetchWithMeta('ns:key', 1_000, fetcher); + expect(stale).toEqual({ value: 'original', outcome: 'stale' }); + expect(cache.getStats().ns).toMatchObject({ stale: 1 }); + }); + + it('propagates the error (no outcome) when the fetcher rejects with no stale entry', async () => { + const fetcher = vi.fn().mockRejectedValue(new Error('no fallback')); + await expect(cache.getOrFetchWithMeta('ns:key', 60_000, fetcher)).rejects.toThrow('no fallback'); + }); + + it('narrows to the CacheFetchOutcome union', async () => { + const { outcome } = await cache.getOrFetchWithMeta('ns:key', 60_000, async () => 1); + const accepted: CacheFetchOutcome[] = ['hit', 'computed', 'inflight', 'stale']; + expect(accepted).toContain(outcome); + }); + }); + + // ─── getOrFetch delegates to getOrFetchWithMeta (parity) ───────────── + + describe('getOrFetch parity with getOrFetchWithMeta', () => { + it('returns only the value and records identical hit/miss counters', async () => { + const fetcher = vi.fn().mockResolvedValue('v'); + const first = await cache.getOrFetch('ns:key', 60_000, fetcher); + const second = await cache.getOrFetch('ns:key', 60_000, fetcher); + expect(first).toBe('v'); + expect(second).toBe('v'); + expect(fetcher).toHaveBeenCalledTimes(1); + // One miss (compute) + one hit, matching the meta variant's accounting. + expect(cache.getStats().ns).toMatchObject({ hits: 1, misses: 1, stale: 0 }); + }); + + it('records one miss per in-flight join, exactly as the meta variant', async () => { + let resolveFetch!: (value: string) => void; + const fetcher = vi.fn(() => new Promise((resolve) => { + resolveFetch = resolve; + })); + + const p1 = cache.getOrFetch('ns:key', 60_000, fetcher); + const p2 = cache.getOrFetch('ns:key', 60_000, fetcher); + resolveFetch('shared'); + await Promise.all([p1, p2]); + + expect(fetcher).toHaveBeenCalledTimes(1); + expect(cache.getStats().ns).toMatchObject({ hits: 0, misses: 2, stale: 0 }); + }); + }); + // ─── inflight deduplication ────────────────────────────────────────── describe('inflight deduplication', () => { diff --git a/backend/src/__tests__/hydration-timing-routes.test.ts b/backend/src/__tests__/hydration-timing-routes.test.ts new file mode 100644 index 00000000..c7e56016 --- /dev/null +++ b/backend/src/__tests__/hydration-timing-routes.test.ts @@ -0,0 +1,208 @@ +/** + * Developer-mode hydration timing on the instrumented GET routes. + * + * Locks down that each instrumented handler emits exactly one structured + * `console.debug` line under developer_mode, stays silent when it is off, and + * carries the documented fields (counts, cache outcome, docker subspan, + * sanitized stack name, elapsed, outcome). Also verifies the /nodes/:id/meta + * diagnostic was folded into a single `[Nodes:debug]` line with no leftover + * `[Nodes:diag]` output. + */ +import { describe, it, expect, beforeAll, afterAll, afterEach, vi } from 'vitest'; +import request from 'supertest'; +import { setupTestDb, cleanupTestDb, loginAsTestAdmin } from './helpers/setupTestDb'; + +let tmpDir: string; +let app: import('express').Express; +let DatabaseService: typeof import('../services/DatabaseService').DatabaseService; +let CacheService: typeof import('../services/CacheService').CacheService; +let DockerController: typeof import('../services/DockerController').default; +let adminCookie: string; +let nodeId: number; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ DatabaseService } = await import('../services/DatabaseService')); + ({ CacheService } = await import('../services/CacheService')); + DockerController = (await import('../services/DockerController')).default; + ({ app } = await import('../index')); + adminCookie = await loginAsTestAdmin(app); + nodeId = DatabaseService.getInstance().getDefaultNode()!.id!; +}); + +afterAll(() => cleanupTestDb(tmpDir)); + +afterEach(() => { + DatabaseService.getInstance().updateGlobalSetting('developer_mode', '0'); +}); + +function setDeveloperMode(on: boolean): void { + DatabaseService.getInstance().updateGlobalSetting('developer_mode', on ? '1' : '0'); +} + +/** Run `fn` while capturing every console.debug line, returned as strings. */ +async function captureDebug(fn: () => Promise): Promise { + const spy = vi.spyOn(console, 'debug').mockImplementation(() => undefined); + let lines: string[]; + try { + await fn(); + lines = spy.mock.calls.map((args) => args.map((a) => (typeof a === 'string' ? a : String(a))).join(' ')); + } finally { + spy.mockRestore(); + } + return lines; +} + +describe('[Stacks:debug] GET /api/stacks', () => { + it('stays silent when developer_mode is off', async () => { + setDeveloperMode(false); + const lines = await captureDebug(async () => { + await request(app).get('/api/stacks').set('Cookie', adminCookie); + }); + expect(lines.filter((l) => l.startsWith('[Stacks:debug]'))).toHaveLength(0); + }); + + it('logs one line with nodeId, count, elapsed and outcome when on', async () => { + setDeveloperMode(true); + const lines = await captureDebug(async () => { + await request(app).get('/api/stacks').set('Cookie', adminCookie); + }); + const stacks = lines.filter((l) => l.startsWith('[Stacks:debug]')); + expect(stacks).toHaveLength(1); + expect(stacks[0]).toContain('route=GET /'); + expect(stacks[0]).toMatch(/nodeId=/); + expect(stacks[0]).toMatch(/count=\d+/); + expect(stacks[0]).toMatch(/elapsedMs=\d+/); + expect(stacks[0]).toMatch(/outcome=ok/); + }); +}); + +describe('[Stacks:debug] GET /api/stacks/statuses', () => { + it('reports cache outcome computed then hit, timing docker only on the compute', async () => { + setDeveloperMode(true); + CacheService.getInstance().invalidateNamespace('stack-statuses'); + // getInstance returns a fresh DockerController each call, so spy the shared + // prototype method rather than one instance. + const dockerSpy = vi.spyOn(DockerController.prototype, 'getBulkStackStatuses').mockResolvedValue({}); + + const firstLines = await captureDebug(async () => { + await request(app).get('/api/stacks/statuses').set('Cookie', adminCookie); + }); + const secondLines = await captureDebug(async () => { + await request(app).get('/api/stacks/statuses').set('Cookie', adminCookie); + }); + + // Capture the call count before restore; mockRestore() clears the history. + const dockerCalls = dockerSpy.mock.calls.length; + dockerSpy.mockRestore(); + + const first = firstLines.find((l) => l.startsWith('[Stacks:debug]') && l.includes('route=GET /statuses')); + const second = secondLines.find((l) => l.startsWith('[Stacks:debug]') && l.includes('route=GET /statuses')); + expect(first).toMatch(/cacheOutcome=computed/); + expect(first).toMatch(/dockerMs=\d+/); + expect(second).toMatch(/cacheOutcome=hit/); + // No docker call on a cache hit, so the subspan is null rather than 0. + expect(second).toMatch(/dockerMs=null/); + // The compute ran the fetcher exactly once across both requests. + expect(dockerCalls).toBe(1); + }); +}); + +describe('[Stacks:debug] GET /api/stacks/:stack/containers', () => { + it('logs the docker subspan and count without the stack name', async () => { + setDeveloperMode(true); + const dockerSpy = vi.spyOn(DockerController.prototype, 'getContainersByStack').mockResolvedValue([]); + + const lines = await captureDebug(async () => { + await request(app).get('/api/stacks/web/containers').set('Cookie', adminCookie); + }); + + dockerSpy.mockRestore(); + + const line = lines.find((l) => l.startsWith('[Stacks:debug]') && l.includes('/:stack/containers')); + expect(line).toBeDefined(); + expect(line).toContain('route=GET /:stack/containers'); + expect(line).not.toContain('web'); + expect(line).not.toMatch(/\bstack=/); + expect(line).toMatch(/count=0/); + expect(line).toMatch(/dockerMs=\d+/); + expect(line).toMatch(/outcome=ok/); + }); +}); + +describe('[Notifications:debug] GET /api/notifications', () => { + it('stays silent when developer_mode is off', async () => { + setDeveloperMode(false); + const lines = await captureDebug(async () => { + await request(app).get('/api/notifications').set('Cookie', adminCookie); + }); + expect(lines.filter((l) => l.startsWith('[Notifications:debug]'))).toHaveLength(0); + }); + + it('logs count and elapsed when on', async () => { + setDeveloperMode(true); + const lines = await captureDebug(async () => { + await request(app).get('/api/notifications').set('Cookie', adminCookie); + }); + const line = lines.find((l) => l.startsWith('[Notifications:debug]')); + expect(line).toBeDefined(); + expect(line).toMatch(/count=\d+/); + expect(line).toMatch(/elapsedMs=\d+/); + expect(line).toMatch(/outcome=ok/); + }); +}); + +describe('[Nodes:debug] GET /api/nodes', () => { + it('logs a gateway-owned count line when on', async () => { + setDeveloperMode(true); + const lines = await captureDebug(async () => { + await request(app).get('/api/nodes').set('Cookie', adminCookie); + }); + const line = lines.find((l) => l.startsWith('[Nodes:debug]') && l.includes('route=GET /nodes')); + expect(line).toBeDefined(); + expect(line).toMatch(/count=\d+/); + expect(line).toMatch(/outcome=ok/); + }); +}); + +describe('[Nodes:debug] GET /api/nodes/:id/meta', () => { + it('folds the old [Nodes:diag] meta line into a single [Nodes:debug] timing line', async () => { + setDeveloperMode(true); + const logSpy = vi.spyOn(console, 'log').mockImplementation(() => undefined); + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => undefined); + + await request(app).get(`/api/nodes/${nodeId}/meta`).set('Cookie', adminCookie); + + const logLines = logSpy.mock.calls.map((c) => String(c[0])); + const debugLines = debugSpy.mock.calls.map((c) => String(c[0])); + logSpy.mockRestore(); + debugSpy.mockRestore(); + + expect(logLines.some((l) => l.includes('[Nodes:diag] meta'))).toBe(false); + const line = debugLines.find((l) => l.startsWith('[Nodes:debug]') && l.includes('/nodes/:id/meta')); + expect(line).toBeDefined(); + expect(line).toContain('type=local'); + expect(line).toMatch(new RegExp(`node=${nodeId}`)); + expect(line).toMatch(/outcome=ok/); + }); +}); + +describe('[ImageUpdates:debug] status and detail', () => { + it('logs a line for /status and a counted line for /detail', async () => { + setDeveloperMode(true); + const statusLines = await captureDebug(async () => { + await request(app).get('/api/image-updates/status').set('Cookie', adminCookie); + }); + expect( + statusLines.find((l) => l.startsWith('[ImageUpdates:debug]') && l.includes('route=GET /status')), + ).toBeDefined(); + + const detailLines = await captureDebug(async () => { + await request(app).get('/api/image-updates/detail').set('Cookie', adminCookie); + }); + const detail = detailLines.find((l) => l.startsWith('[ImageUpdates:debug]') && l.includes('route=GET /detail')); + expect(detail).toBeDefined(); + expect(detail).toMatch(/count=\d+/); + expect(detail).toMatch(/outcome=ok/); + }); +}); diff --git a/backend/src/__tests__/proxy-timing.test.ts b/backend/src/__tests__/proxy-timing.test.ts new file mode 100644 index 00000000..a23f6cd2 --- /dev/null +++ b/backend/src/__tests__/proxy-timing.test.ts @@ -0,0 +1,195 @@ +/** + * Gateway hop timing for proxied critical hydration GETs ([Proxy:debug]). + * + * Verifies the exactly-once finalization contract: + * - a normal proxied request fires downstream finish then close but logs once + * (outcome ok, with upstreamStatus / ttfbMs / elapsedMs), + * - a client abort after headers finalizes as not-success (aborted/error), + * never ok, and still exactly once, + * - path templates never carry the real stack name or a query string, + * - nothing is logged when the gateway's developer_mode is off. + * + * The "remote" node is a loopback capture server; the gateway is exercised both + * via supertest (finish/close, templates, off) and via a raw client against a + * real listener (abort) so the downstream socket can be destroyed mid-body. + */ +import { describe, it, expect, beforeAll, afterAll, afterEach, vi } from 'vitest'; +import http from 'http'; +import type { AddressInfo } from 'net'; +import request from 'supertest'; +import jwt from 'jsonwebtoken'; +import { setupTestDb, cleanupTestDb, TEST_USERNAME, TEST_JWT_SECRET } from './helpers/setupTestDb'; + +let tmpDir: string; +let app: import('express').Express; +let DatabaseService: typeof import('../services/DatabaseService').DatabaseService; +let adminBearer: string; +let remoteNodeId: number; + +let captureServer: http.Server; +let appServer: http.Server; +let appPort: number; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ DatabaseService } = await import('../services/DatabaseService')); + ({ app } = await import('../index')); + + // authMiddleware resolves the role from the DB row, so a bearer for the + // seeded admin proxies with admin privileges (skips the cross-node RBAC probe). + adminBearer = `Bearer ${jwt.sign({ username: TEST_USERNAME }, TEST_JWT_SECRET, { expiresIn: '5m' })}`; + + // Loopback "remote": returns [] for GETs; hangs mid-body for the abort path. + captureServer = http.createServer((req, res) => { + if (req.url?.includes('/containers') && req.url.includes('hangstack')) { + res.writeHead(200, { 'Content-Type': 'application/json' }); + res.write('['); // partial body, intentionally never ended + return; + } + res.writeHead(200, { 'Content-Type': 'application/json' }); + res.end('[]'); + }); + await new Promise((resolve) => captureServer.listen(0, '127.0.0.1', resolve)); + const capturePort = (captureServer.address() as AddressInfo).port; + + remoteNodeId = DatabaseService.getInstance().addNode({ + name: 'timing-remote', + type: 'remote', + mode: 'proxy', + compose_dir: '/tmp', + is_default: false, + api_url: `http://127.0.0.1:${capturePort}`, + api_token: 'timing-node-token', + }); + + appServer = http.createServer(app); + await new Promise((resolve) => appServer.listen(0, '127.0.0.1', resolve)); + appPort = (appServer.address() as AddressInfo).port; +}); + +afterAll(async () => { + await new Promise((resolve) => appServer.close(() => resolve())); + await new Promise((resolve) => captureServer.close(() => resolve())); + cleanupTestDb(tmpDir); +}); + +afterEach(() => { + DatabaseService.getInstance().updateGlobalSetting('developer_mode', '0'); +}); + +function setDeveloperMode(on: boolean): void { + DatabaseService.getInstance().updateGlobalSetting('developer_mode', on ? '1' : '0'); +} + +/** Run `fn` while capturing console.debug lines; returns lines before restore. */ +async function captureDebug(fn: () => Promise): Promise { + const spy = vi.spyOn(console, 'debug').mockImplementation(() => undefined); + let lines: string[]; + try { + await fn(); + lines = spy.mock.calls.map((args) => args.map((a) => (typeof a === 'string' ? a : String(a))).join(' ')); + } finally { + spy.mockRestore(); + } + return lines; +} + +const proxyLinesFrom = (lines: string[]): string[] => lines.filter((l) => l.startsWith('[Proxy:debug]')); + +describe('[Proxy:debug] downstream finish/close finalization', () => { + it('logs exactly one line on a normal proxied GET (finish wins over close)', async () => { + setDeveloperMode(true); + const lines = await captureDebug(async () => { + const res = await request(app) + .get('/api/stacks') + .set('Authorization', adminBearer) + .set('x-node-id', String(remoteNodeId)); + expect(res.status).toBe(200); + await new Promise((r) => setTimeout(r, 50)); + }); + + const proxyLines = proxyLinesFrom(lines); + expect(proxyLines).toHaveLength(1); + expect(proxyLines[0]).toContain('route=/api/stacks'); + expect(proxyLines[0]).toMatch(/outcome=ok/); + expect(proxyLines[0]).toMatch(/upstreamStatus=200/); + expect(proxyLines[0]).toMatch(/ttfbMs=\d+/); + expect(proxyLines[0]).toMatch(/elapsedMs=\d+/); + }); + + it('templates the path and never logs the real stack name or query string', async () => { + setDeveloperMode(true); + const lines = await captureDebug(async () => { + await request(app) + .get('/api/stacks/supersecretstack/containers?token=leak') + .set('Authorization', adminBearer) + .set('x-node-id', String(remoteNodeId)); + await new Promise((r) => setTimeout(r, 50)); + }); + + const proxyLines = proxyLinesFrom(lines); + expect(proxyLines).toHaveLength(1); + expect(proxyLines[0]).toContain('route=/api/stacks/:stack/containers'); + expect(proxyLines[0]).not.toContain('supersecretstack'); + expect(proxyLines[0]).not.toContain('token=leak'); + }); + + it('logs nothing when the gateway developer_mode is off', async () => { + setDeveloperMode(false); + const lines = await captureDebug(async () => { + const res = await request(app) + .get('/api/stacks') + .set('Authorization', adminBearer) + .set('x-node-id', String(remoteNodeId)); + expect(res.status).toBe(200); + await new Promise((r) => setTimeout(r, 50)); + }); + expect(proxyLinesFrom(lines)).toHaveLength(0); + }); +}); + +describe('[Proxy:debug] client abort after headers', () => { + it('finalizes as not-success exactly once when the client aborts mid-body', async () => { + setDeveloperMode(true); + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => undefined); + // The proxy logs a [Proxy] error on the aborted upstream; keep it quiet. + const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => undefined); + + try { + await new Promise((resolve) => { + const clientReq = http.request( + { + host: '127.0.0.1', + port: appPort, + path: '/api/stacks/hangstack/containers', + method: 'GET', + headers: { Authorization: adminBearer, 'x-node-id': String(remoteNodeId) }, + }, + (resp) => { + // Headers have arrived from the gateway (upstream status + ttfb are + // already captured). Abort before the body finishes. + resp.destroy(); + clientReq.destroy(); + resolve(); + }, + ); + clientReq.on('error', () => resolve()); + clientReq.end(); + }); + + // Let the downstream 'close' / proxy 'error' fire and finalize. + await new Promise((r) => setTimeout(r, 200)); + + const proxyLines = debugSpy.mock.calls + .map((c) => String(c[0])) + .filter((l) => l.startsWith('[Proxy:debug]') && l.includes('/:stack/containers')); + + expect(proxyLines).toHaveLength(1); + expect(proxyLines[0]).not.toMatch(/outcome=ok/); + expect(proxyLines[0]).toMatch(/outcome=(aborted|error)/); + } finally { + debugSpy.mockRestore(); + errorSpy.mockRestore(); + } + }); +}); diff --git a/backend/src/proxy/remoteNodeProxy.ts b/backend/src/proxy/remoteNodeProxy.ts index 4c923d0b..156ddcd8 100644 --- a/backend/src/proxy/remoteNodeProxy.ts +++ b/backend/src/proxy/remoteNodeProxy.ts @@ -9,6 +9,67 @@ import { STACK_DOWN_REMOVE_VOLUMES_CAPABILITY } from '../services/CapabilityRegi import { getErrorMessage } from '../utils/errors'; import { DatabaseService } from '../services/DatabaseService'; import { redactSensitiveText } from '../utils/safeLog'; +import { isDebugEnabled } from '../utils/debug'; +import { logDebugTiming, templatizeHydrationPath } from '../utils/requestTiming'; + +/** + * Per-request hop timing for the critical hydration GETs, kept off the Request + * type via a WeakMap so the entry is collected with the request. `logged` + * enforces exactly-once finalization across the downstream finish/close events + * and the proxy error handler. + */ +type ProxyTimingOutcome = 'ok' | 'non2xx' | 'aborted' | 'error'; + +interface ProxyTiming { + startedAt: number; + template: string; + logged: boolean; + upstreamStatus?: number; + ttfbMs?: number; +} + +const proxyTimings = new WeakMap(); + +/** + * Arm hop timing for a request that is about to be proxied. No-op unless the + * gateway has developer_mode on and the path is a critical hydration GET, so + * non-instrumented traffic pays nothing. Templates never carry a real stack + * name or query string. + */ +function beginProxyTiming(req: Request, res: Response): void { + if (req.method !== 'GET' || !isDebugEnabled()) return; + const template = templatizeHydrationPath(`/api${req.path}`); + if (!template) return; + + const timing: ProxyTiming = { startedAt: Date.now(), template, logged: false }; + proxyTimings.set(req, timing); + + // A completed response fires 'finish' then 'close'; the logged guard lets the + // finish result win. A 'close' with no prior 'finish' means the downstream + // client aborted before the body finished streaming. + res.once('finish', () => { + const status = timing.upstreamStatus ?? res.statusCode; + finalizeProxyTiming(req, status >= 200 && status < 300 ? 'ok' : 'non2xx'); + }); + res.once('close', () => { + finalizeProxyTiming(req, 'aborted'); + }); +} + +/** Emit the single `[Proxy:debug]` line for a request, at most once. */ +function finalizeProxyTiming(req: Request, outcome: ProxyTimingOutcome): void { + const timing = proxyTimings.get(req); + if (!timing || timing.logged) return; + timing.logged = true; + logDebugTiming('[Proxy:debug]', { + route: timing.template, + nodeId: req.nodeId, + outcome, + upstreamStatus: timing.upstreamStatus ?? null, + ttfbMs: timing.ttfbMs ?? null, + elapsedMs: Date.now() - timing.startedAt, + }); +} /** * Build the remote-node HTTP proxy middleware. Mount once at `/api/` after @@ -77,7 +138,7 @@ export function createRemoteProxyMiddleware(): RequestHandler { // intact and http-proxy's req.pipe(proxyReq) forwards the body // automatically. }, - proxyRes: (proxyRes) => { + proxyRes: (proxyRes, req) => { // Mark every response forwarded from a remote node with a sentinel // header. The frontend (apiFetch / fetchForNode) checks this before // firing the global 'sencho-unauthorized' event: a 401 from a remote @@ -85,8 +146,19 @@ export function createRemoteProxyMiddleware(): RequestHandler { // user's own session expired. Without this distinction, any node with // a bad token causes an immediate logout loop. proxyRes.headers['x-sencho-proxy'] = '1'; + // Record upstream status and time-to-first-byte only; the log is + // finalized on the downstream finish/close so an abort mid-body is not + // mislabeled as success. + const timing = proxyTimings.get(req); + if (timing) { + timing.upstreamStatus = proxyRes.statusCode; + timing.ttfbMs = Date.now() - timing.startedAt; + } }, error: (err, req, proxyRes) => { + // Finalize the hop timing with an error outcome before the existing + // 502 handling; the logged guard keeps the later finish/close a no-op. + finalizeProxyTiming(req, 'error'); console.error('[Proxy] Remote node error:', getErrorMessage(err, 'unknown')); const path = req.originalUrl || req.url; if (req.method === 'POST' && /^\/api\/stacks\/[^/]+\/(?:deploy|update)(?:\?|$)/.test(path)) { @@ -168,6 +240,7 @@ export function createRemoteProxyMiddleware(): RequestHandler { } req.proxyTarget = target; + beginProxyTiming(req, res); proxy(req, res, next); }; diff --git a/backend/src/routes/imageUpdates.ts b/backend/src/routes/imageUpdates.ts index 5b081268..b8806776 100644 --- a/backend/src/routes/imageUpdates.ts +++ b/backend/src/routes/imageUpdates.ts @@ -18,6 +18,7 @@ import { buildPolicyGateOptions } from '../helpers/policyGate'; import { summarizeBlockReasons } from '../utils/policy-risk'; import { isValidStackName } from '../utils/validation'; import { sanitizeForLog } from '../utils/safeLog'; +import { logDebugTiming } from '../utils/requestTiming'; import { getErrorMessage } from '../utils/errors'; // Fleet aggregation cache: 2-minute TTL, shared across dashboard tabs. @@ -41,12 +42,26 @@ imageUpdatesRouter.get('/', authMiddleware, (req: Request, res: Response): void // readiness view. Auth-only, matching GET /; the boolean GET / is left intact so // the cross-version fleet aggregation contract is unaffected. imageUpdatesRouter.get('/detail', authMiddleware, (req: Request, res: Response): void => { + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let count = 0; try { const nodeId = req.nodeId ?? NodeRegistry.getInstance().getDefaultNodeId(); - res.json(DatabaseService.getInstance().getStackUpdateDetail(nodeId)); + const detail = DatabaseService.getInstance().getStackUpdateDetail(nodeId); + count = Object.keys(detail).length; + res.json(detail); } catch (error) { + outcome = 'error'; console.error('Failed to fetch image update detail:', error); res.status(500).json({ error: 'Failed to fetch image update detail' }); + } finally { + logDebugTiming('[ImageUpdates:debug]', { + route: 'GET /detail', + nodeId: req.nodeId, + count, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); @@ -66,8 +81,23 @@ imageUpdatesRouter.post('/refresh', authMiddleware, (req: Request, res: Response } }); -imageUpdatesRouter.get('/status', authMiddleware, (_req: Request, res: Response): void => { - res.json(ImageUpdateService.getInstance().getStatus()); +imageUpdatesRouter.get('/status', authMiddleware, (req: Request, res: Response): void => { + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + try { + res.json(ImageUpdateService.getInstance().getStatus()); + } catch (error) { + outcome = 'error'; + console.error('Failed to fetch image update status:', error); + res.status(500).json({ error: 'Failed to fetch image update status' }); + } finally { + logDebugTiming('[ImageUpdates:debug]', { + route: 'GET /status', + nodeId: req.nodeId, + elapsedMs: Date.now() - startedAt, + outcome, + }); + } }); /** diff --git a/backend/src/routes/nodes.ts b/backend/src/routes/nodes.ts index eabc54bf..b479afb1 100644 --- a/backend/src/routes/nodes.ts +++ b/backend/src/routes/nodes.ts @@ -22,6 +22,7 @@ import { getErrorMessage } from '../utils/errors'; import { toPublicNode } from '../helpers/publicNode'; import { isDebugEnabled } from '../utils/debug'; import { sanitizeForLog } from '../utils/safeLog'; +import { logDebugTiming } from '../utils/requestTiming'; const NODE_SCOPE_MESSAGE = 'API tokens cannot manage nodes.'; const REMOTE_META_CACHE_TTL = 3 * 60 * 1000; @@ -116,11 +117,25 @@ function mintPilotEnrollment(nodeId: number, req: Request): { token: string; exp export const nodesRouter = Router(); nodesRouter.get('/', async (req: Request, res: Response) => { + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let count = 0; try { const nodes = DatabaseService.getInstance().getNodes(); + count = nodes.length; res.json(nodes.map(toPublicNode)); } catch (error) { + outcome = 'error'; res.status(500).json({ error: 'Failed to fetch nodes' }); + } finally { + // Gateway-owned: /api/nodes is proxy-exempt, so this always runs on the + // control instance and gates on the gateway's developer_mode. + logDebugTiming('[Nodes:debug]', { + route: 'GET /nodes', + count, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); @@ -577,14 +592,19 @@ nodesRouter.post('/:id/test', async (req: Request, res: Response) => { }); nodesRouter.get('/:id/meta', authMiddleware, async (req: Request, res: Response) => { + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let id = NaN; + let nodeType = 'unknown'; try { - const id = parseInt(req.params.id as string); + id = parseInt(req.params.id as string); const node = DatabaseService.getInstance().getNode(id); if (!node) { + outcome = 'error'; res.status(404).json({ error: 'Node not found' }); return; } - if (isDebugEnabled()) console.log(`[Nodes:diag] meta node=${id} type=${node.type}`); + nodeType = node.type; if (node.type === 'local') { res.json({ version: getSenchoVersion(), capabilities: getActiveCapabilities() }); @@ -606,8 +626,19 @@ nodesRouter.get('/:id/meta', authMiddleware, async (req: Request, res: Response) res.json(meta); } catch (error: unknown) { + outcome = 'error'; console.error('Failed to fetch node meta:', error); const message = getErrorMessage(error, 'Failed to fetch node metadata'); res.status(500).json({ error: message }); + } finally { + // Gateway-owned: the frontend fetches meta with localOnly, so this runs on + // the control instance and gates on the gateway's developer_mode. + logDebugTiming('[Nodes:debug]', { + route: 'GET /nodes/:id/meta', + node: id, + type: nodeType, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); diff --git a/backend/src/routes/notifications.ts b/backend/src/routes/notifications.ts index f9fe2dc4..398b59e1 100644 --- a/backend/src/routes/notifications.ts +++ b/backend/src/routes/notifications.ts @@ -16,6 +16,7 @@ import { syncSuppressionRuleToFleet, } from '../helpers/notificationSuppressionSync'; import { isDebugEnabled } from '../utils/debug'; +import { logDebugTiming } from '../utils/requestTiming'; import { getErrorMessage } from '../utils/errors'; import { sanitizeForLog } from '../utils/safeLog'; import { parseIntParam } from '../utils/parseIntParam'; @@ -183,14 +184,27 @@ function parseSuppressionRuleBody( export const notificationsRouter = Router(); notificationsRouter.get('/', authMiddleware, async (req: Request, res: Response): Promise => { + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let count = 0; try { const nodeId = req.nodeId ?? 0; const category = typeof req.query.category === 'string' ? req.query.category : undefined; const history = DatabaseService.getInstance().getNotificationHistory(nodeId, 50, category); + count = history.length; res.json(history); } catch (error) { + outcome = 'error'; console.error('Failed to fetch notifications:', error); res.status(500).json({ error: 'Failed to fetch notifications' }); + } finally { + logDebugTiming('[Notifications:debug]', { + route: 'GET /', + nodeId: req.nodeId, + count, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); diff --git a/backend/src/routes/stacks.ts b/backend/src/routes/stacks.ts index d6d24835..f184ab29 100644 --- a/backend/src/routes/stacks.ts +++ b/backend/src/routes/stacks.ts @@ -16,7 +16,7 @@ import { ComposeService, getComposeRollbackInfo } from '../services/ComposeServi import DockerController, { type BulkStackInfo } from '../services/DockerController'; import { DatabaseService, type StackDossierFields } from '../services/DatabaseService'; import { MeshService } from '../services/MeshService'; -import { CacheService } from '../services/CacheService'; +import { CacheService, type CacheFetchOutcome } from '../services/CacheService'; import { UpdatePreviewService } from '../services/UpdatePreviewService'; import { GitSourceService, GitSourceError, repoHost as gitRepoHost } from '../services/GitSourceService'; import { enforcePolicyPreDeploy } from '../services/PolicyEnforcement'; @@ -47,6 +47,7 @@ import { normalizeBulkPaths, destWithinAnySource } from '../utils/bulkPaths'; import { getErrorMessage } from '../utils/errors'; import { isDebugEnabled } from '../utils/debug'; import { sanitizeForLog } from '../utils/safeLog'; +import { logDebugTiming } from '../utils/requestTiming'; import { sendGitSourceError } from '../utils/gitSourceHttp'; import { buildPolicyGateOptions, runPolicyGate, triggerPostDeployScan, describePolicyBlock } from '../helpers/policyGate'; import { parseComposePreview, type ComposePreview } from '../helpers/composePreview'; @@ -234,25 +235,45 @@ stacksRouter.param('stackName', (req, res, next, stackName) => { stacksRouter.get('/', async (req: Request, res: Response) => { if (!requirePermission(req, res, 'stack:read')) return; + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let count = 0; try { const stacks = await FileSystemService.getInstance(req.nodeId).getStacks(); + count = stacks.length; res.json(stacks); } catch (error) { + outcome = 'error'; res.status(500).json({ error: 'Failed to fetch stacks' }); + } finally { + logDebugTiming('[Stacks:debug]', { + route: 'GET /', + nodeId: req.nodeId, + count, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); stacksRouter.get('/statuses', async (req: Request, res: Response) => { if (!requirePermission(req, res, 'stack:read')) return; + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let cacheOutcome: CacheFetchOutcome | null = null; + let dockerMs: number | null = null; + let count = 0; try { - const result = await CacheService.getInstance().getOrFetch( + const { value: result, outcome: fetchOutcome } = await CacheService.getInstance().getOrFetchWithMeta( `stack-statuses:${req.nodeId}`, STACK_STATUSES_CACHE_TTL_MS, async () => { const stacks = await FileSystemService.getInstance(req.nodeId).getStacks(); const stackNames = stacks.map((s: string) => s.replace(/\.(yml|yaml)$/, '')); const dockerController = DockerController.getInstance(req.nodeId); + const dockerStartedAt = Date.now(); const bulkInfo = await dockerController.getBulkStackStatuses(stackNames); + dockerMs = Date.now() - dockerStartedAt; const data: Record = {}; for (const stack of stacks) { const name = stack.replace(/\.(yml|yaml)$/, ''); @@ -261,6 +282,8 @@ stacksRouter.get('/statuses', async (req: Request, res: Response) => { return data; }, ); + cacheOutcome = fetchOutcome; + count = Object.keys(result).length; // Git-source labels are computed live, outside the cache, so linking or // unlinking a stack's Git source is reflected immediately. The Docker // status portion keeps its short TTL; only the cheap source label is fresh. @@ -285,8 +308,19 @@ stacksRouter.get('/statuses', async (req: Request, res: Response) => { } res.json(withSource); } catch (error) { + outcome = 'error'; console.error('Failed to fetch stack statuses:', error); res.status(500).json({ error: 'Failed to fetch stack statuses' }); + } finally { + logDebugTiming('[Stacks:debug]', { + route: 'GET /statuses', + nodeId: req.nodeId, + cacheOutcome, + count, + dockerMs, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); @@ -1151,13 +1185,30 @@ stacksRouter.get('/:stackName/containers', async (req: Request, res: Response) = return; } if (!requirePermission(req, res, 'stack:read', 'stack', stackName)) return; + const startedAt = Date.now(); + let outcome: 'ok' | 'error' = 'ok'; + let dockerMs: number | null = null; + let count = 0; try { const dockerController = DockerController.getInstance(req.nodeId); + const dockerStartedAt = Date.now(); const containers = await dockerController.getContainersByStack(stackName); + dockerMs = Date.now() - dockerStartedAt; + count = containers.length; res.json(containers); } catch (error) { + outcome = 'error'; console.error('[Stacks] Failed to fetch containers for %s:', sanitizeForLog(stackName), error); res.status(500).json({ error: 'Failed to fetch containers' }); + } finally { + logDebugTiming('[Stacks:debug]', { + route: 'GET /:stack/containers', + nodeId: req.nodeId, + count, + dockerMs, + elapsedMs: Date.now() - startedAt, + outcome, + }); } }); diff --git a/backend/src/services/CacheService.ts b/backend/src/services/CacheService.ts index 7fa6aa18..c1b5e4f7 100644 --- a/backend/src/services/CacheService.ts +++ b/backend/src/services/CacheService.ts @@ -26,6 +26,24 @@ interface CacheEntry { expiresAt: number; } +/** + * Observational outcome of a single getOrFetchWithMeta call. Truthful under + * concurrency: an `inflight` join is never reported as a `hit`. + * + * - hit: fresh entry returned without waiting + * - computed: this caller ran the fetcher and it succeeded + * - inflight: joined an existing in-flight promise (this caller did not run + * the fetcher) + * - stale: the fetcher this caller ran failed and a stale entry was + * returned instead + */ +export type CacheFetchOutcome = 'hit' | 'computed' | 'inflight' | 'stale'; + +export interface CacheFetchResult { + value: T; + outcome: CacheFetchOutcome; +} + interface NamespaceStats { hits: number; misses: number; @@ -61,26 +79,51 @@ export class CacheService { * * On fetcher rejection: if a stale entry exists, return it (counted as * `stale`); otherwise propagate the error. + * + * Thin wrapper over getOrFetchWithMeta that discards the outcome; all + * stats / TTL / inflight-dedup / stale-on-error semantics are identical. */ public async getOrFetch( key: string, ttlMs: number, fetcher: () => Promise, ): Promise { + const { value } = await this.getOrFetchWithMeta(key, ttlMs, fetcher); + return value; + } + + /** + * Same behaviour as getOrFetch, but also reports how the value was obtained + * (see CacheFetchOutcome). Intended for diagnostic logging that must not + * mislabel an in-flight join as a cache hit. The stats counters, TTL, cap, + * and stale-on-error fallback are recorded exactly as getOrFetch does: one + * miss per in-flight join, one stale per failed computation. + */ + public async getOrFetchWithMeta( + key: string, + ttlMs: number, + fetcher: () => Promise, + ): Promise> { const ns = namespaceOf(key); const now = Date.now(); const existing = this.store.get(key) as CacheEntry | undefined; if (existing && existing.expiresAt > now) { this.recordHit(ns); - return existing.value; + return { value: existing.value, outcome: 'hit' }; } this.recordMiss(ns); const inflight = this.inflight.get(key) as Promise | undefined; - if (inflight) return inflight; + if (inflight) { + const value = await inflight; + return { value, outcome: 'inflight' }; + } + // This caller owns the computation; the closure records whether it ended + // as a fresh compute or a stale fallback, read after the promise settles. + let outcome: CacheFetchOutcome = 'computed'; const promise = (async () => { try { const value = await fetcher(); @@ -89,6 +132,7 @@ export class CacheService { } catch (err) { if (existing) { this.recordStale(ns); + outcome = 'stale'; return existing.value; } throw err; @@ -98,7 +142,8 @@ export class CacheService { })(); this.inflight.set(key, promise); - return promise; + const value = await promise; + return { value, outcome }; } /** diff --git a/backend/src/utils/requestTiming.ts b/backend/src/utils/requestTiming.ts new file mode 100644 index 00000000..b669432b --- /dev/null +++ b/backend/src/utils/requestTiming.ts @@ -0,0 +1,60 @@ +import { isDebugEnabled } from './debug'; +import { sanitizeForLog } from './safeLog'; + +/** + * Developer-mode hydration timing helpers. + * + * These emit one structured line per instrumented request via console.debug, + * gated on the same `developer_mode` flag as every other diagnostic log. The + * lines carry durations, counts, and outcomes only. Callers must never place + * a raw URL, query string, or token into `fields`; use templatizeHydrationPath + * for paths so a real stack name can never reach the log. + */ + +/** Render one field value: numbers/booleans verbatim, everything else sanitized. */ +function formatFieldValue(value: unknown): string { + if (typeof value === 'number' || typeof value === 'boolean') return String(value); + if (value === null || value === undefined) return String(value); + return sanitizeForLog(value); +} + +/** + * Emit a ` key=value ...` timing line, but only when developer_mode is + * enabled. String values are control-char stripped to prevent log injection. + */ +export function logDebugTiming(prefix: string, fields: Record): void { + if (!isDebugEnabled()) return; + const rendered = Object.entries(fields) + .map(([key, value]) => `${key}=${formatFieldValue(value)}`) + .join(' '); + console.debug(`${prefix} ${rendered}`); +} + +/** + * Critical hydration GET route templates, ordered most-specific-first so the + * bare `/api/stacks` collection never shadows a nested match. The templates + * are static strings, so a real stack name is never substituted back in. + */ +const HYDRATION_PATH_TEMPLATES: ReadonlyArray<{ pattern: RegExp; template: string }> = [ + { pattern: /^\/api\/stacks\/statuses$/, template: '/api/stacks/statuses' }, + { pattern: /^\/api\/stacks\/[^/]+\/containers$/, template: '/api/stacks/:stack/containers' }, + { pattern: /^\/api\/stacks$/, template: '/api/stacks' }, + { pattern: /^\/api\/image-updates\/status$/, template: '/api/image-updates/status' }, + { pattern: /^\/api\/image-updates\/detail$/, template: '/api/image-updates/detail' }, + { pattern: /^\/api\/notifications$/, template: '/api/notifications' }, +]; + +/** + * Map a request path to a stable route template for logging. The query string + * is stripped before matching, and only the critical hydration GETs resolve; + * any other path returns null so callers skip logging. The returned value is + * always a fixed template (e.g. `/api/stacks/:stack/containers`), never a path + * segment taken from the request. + */ +export function templatizeHydrationPath(rawPath: string): string | null { + const pathname = rawPath.split('?')[0]; + for (const { pattern, template } of HYDRATION_PATH_TEMPLATES) { + if (pattern.test(pathname)) return template; + } + return null; +} diff --git a/docs/reference/settings.mdx b/docs/reference/settings.mdx index 794ee4c4..25880b98 100644 --- a/docs/reference/settings.mdx +++ b/docs/reference/settings.mdx @@ -547,6 +547,12 @@ Debug diagnostics for this node. Most operators can leave this off. The masthead |---------|---------|-------------| | **Developer mode** | Off | Enables real-time metrics streams and verbose debug diagnostics in the UI. Does not affect [Global Observability](/features/global-observability) streaming, which is always on. | + + With Developer mode on, reload the dashboard to capture the startup timeline. A small timing chip appears in the lower corner showing how long the stack list took to become visible from boot; click it to expand the full phase report, which you can copy as JSON. The overlay follows the active node, so switching nodes starts a fresh timeline. + + For the matching server-side timings, filter the backend logs for `[Stacks:debug]` (stack list, statuses, and per-container timing, including the Docker call duration), `[Nodes:debug]`, and `[Proxy:debug]`. When the active node is remote, the `[Nodes:debug]` and `[Proxy:debug]` lines, along with the overlay's proxy note, depend on Developer mode being enabled on the gateway you sign in to, while the destination route logs and the overlay itself follow Developer mode on the active node. + + Click **Save settings** to apply. --- diff --git a/frontend/src/components/EditorLayout.tsx b/frontend/src/components/EditorLayout.tsx index ea953611..9679191b 100644 --- a/frontend/src/components/EditorLayout.tsx +++ b/frontend/src/components/EditorLayout.tsx @@ -58,6 +58,9 @@ import { deriveMobileSurface, type MobileView } from './EditorLayout/mobile-surf import { BESPOKE_MOBILE_VIEWS } from './EditorLayout/mobile-treatments'; import { CapabilityGate } from './CapabilityGate'; import { HubOnlyGate } from './HubOnlyGate'; +import { HydrationTimingPanel } from './HydrationTimingPanel'; +import { useDeveloperMode } from '@/hooks/useDeveloperMode'; +import { markMilestone } from '@/lib/hydrationTiming'; import type { SectionId } from './settings/types'; import type { NotificationItem } from './dashboard/types'; @@ -151,6 +154,14 @@ export default function EditorLayout() { const canOfferVolumeRemoval = activeNodeMeta?.capabilities.includes(STACK_DOWN_REMOVE_VOLUMES_CAPABILITY) === true; + // One-shot boot milestone: the app shell has mounted. Developer mode gates the + // hydration-timing overlay for the active node; it follows node switches. + useEffect(() => { + markMilestone('shell_committed'); + }, []); + const developerMode = useDeveloperMode(activeNode?.id); + const hydrationOverlay = developerMode ? : null; + // Mirror activeNode.id in a ref so async handlers (e.g. CreateStackDialog's // post-create handoff) can detect a node switch that happened mid-flight. // Closure capture of activeNode would always match the value at handler-creation @@ -1120,6 +1131,7 @@ export default function EditorLayout() { /> {adoptDialogEl} {shellOverlaysEl} + {hydrationOverlay} ); } @@ -1137,6 +1149,7 @@ export default function EditorLayout() { {adoptDialogEl} {shellOverlaysEl} + {hydrationOverlay} ); })()} diff --git a/frontend/src/components/EditorLayout/hooks/useNotifications.ts b/frontend/src/components/EditorLayout/hooks/useNotifications.ts index 91a3d9c8..f0a8e2a0 100644 --- a/frontend/src/components/EditorLayout/hooks/useNotifications.ts +++ b/frontend/src/components/EditorLayout/hooks/useNotifications.ts @@ -1,5 +1,6 @@ import { useEffect, useRef, useState } from 'react'; import { apiFetch, fetchForNode } from '@/lib/api'; +import { beginSpan, endSpan, markMilestone } from '@/lib/hydrationTiming'; import { toast } from '@/components/ui/toast-store'; import type { Node } from '@/context/NodeContext'; import type { NotificationItem } from '../../dashboard/types'; @@ -23,6 +24,10 @@ export function useNotifications({ nodes, onStateInvalidate, onImageUpdatesChang onStateInvalidateRef.current = onStateInvalidate; const onImageUpdatesChangeRef = useRef(onImageUpdatesChange); onImageUpdatesChangeRef.current = onImageUpdatesChange; + // One-shot: the notifications_ready milestone reflects the first local settle. + // Its spans instrument only that first fetch so later polls do not pollute the + // report. + const notificationsReadyRef = useRef(false); const fetchNotifications = async () => { try { @@ -31,18 +36,41 @@ export function useNotifications({ nodes, onStateInvalidate, onImageUpdatesChang // Skip offline nodes: polling a removed/unreachable node only yields 502s. const remoteNodes = currentNodes.filter(n => n.type === 'remote' && n.status !== 'offline'); - const [localResult, ...remoteNodeResults] = await Promise.allSettled([ - apiFetch('/notifications', { localOnly: true } as Parameters[1]), - ...remoteNodes.map(n => fetchForNode('/notifications', n.id)), - ]); + // Launch every request concurrently, but settle the local one first so the + // notifications_ready milestone is not held back by the slowest remote. + const localPromise = apiFetch('/notifications', { localOnly: true } as Parameters[1]); + const remotePromises = remoteNodes.map(n => fetchForNode('/notifications', n.id)); const all: NotificationItem[] = []; - if (localResult.status === 'fulfilled' && localResult.value.ok) { - const data = await localResult.value.json() as Omit[]; - data.forEach(n => all.push({ ...n, nodeId: localNode?.id ?? -1, nodeName: localNode?.name ?? 'Local' })); + const instrument = !notificationsReadyRef.current; + const headersSpan = instrument ? beginSpan('fetch_headers', { background: true }) : null; + let bodySpan: ReturnType | null = null; + try { + const localRes = await localPromise; + if (headersSpan !== null) endSpan(headersSpan, { detail: { status: localRes.status } }); + if (localRes.ok) { + bodySpan = instrument ? beginSpan('body_decode', { background: true }) : null; + const data = await localRes.json() as Omit[]; + if (bodySpan !== null) endSpan(bodySpan); + bodySpan = null; + const dispatchSpan = instrument ? beginSpan('state_dispatch', { background: true }) : null; + data.forEach(n => all.push({ ...n, nodeId: localNode?.id ?? -1, nodeName: localNode?.name ?? 'Local' })); + if (dispatchSpan !== null) endSpan(dispatchSpan); + } + } catch (e) { + if (headersSpan !== null) endSpan(headersSpan, { outcome: 'error' }); + if (bodySpan !== null) endSpan(bodySpan, { outcome: 'error' }); + console.error('[Notifications] local fetch error:', e); + } finally { + if (!notificationsReadyRef.current) { + notificationsReadyRef.current = true; + markMilestone('notifications_ready'); + } } + // Remotes settle in the background; they never gate the milestone above. + const remoteNodeResults = await Promise.allSettled(remotePromises); for (let i = 0; i < remoteNodes.length; i++) { const result = remoteNodeResults[i]; if (result?.status === 'fulfilled' && result.value.ok) { diff --git a/frontend/src/components/EditorLayout/hooks/useStackActions.ts b/frontend/src/components/EditorLayout/hooks/useStackActions.ts index 11a49ee0..66e38a96 100644 --- a/frontend/src/components/EditorLayout/hooks/useStackActions.ts +++ b/frontend/src/components/EditorLayout/hooks/useStackActions.ts @@ -1,5 +1,14 @@ -import { useRef, useCallback, useEffect } from 'react'; +import { useRef, useCallback, useEffect, useState } from 'react'; import { apiFetch, withDeploySession } from '@/lib/api'; +import { + newAttemptId, + abortAttempt, + beginSpan, + endSpan, + flushPendingCommit, + type PendingCommit, + type SpanHandle, +} from '@/lib/hydrationTiming'; import { toast } from '@/components/ui/toast-store'; import { buildServiceUrl, openServiceUrl } from '@/lib/serviceUrl'; import type { useEditorViewState } from './useEditorViewState'; @@ -268,6 +277,17 @@ export function useStackActions(options: UseStackActionsOptions) { // late responses never overwrite freshly-loaded state. const loadFileAbortRef = useRef(null); + // Hydration-timing: the current detail (loadFileCore) attempt, the file it is + // loading, and the commits waiting for React to observe committed state. + const detailAttemptRef = useRef(null); + const detailFileRef = useRef(null); + const detailVisiblePendingRef = useRef(null); + const detailContainersPendingRef = useRef(null); + const detailHydratedPendingRef = useRef(null); + // Bumped when arming detail_visible so same-file reloads (selectedFile and + // activeView unchanged) still re-run the commit effect. + const [detailVisibleEpoch, setDetailVisibleEpoch] = useState(0); + useEffect(() => { return () => { if (checkUpdatesIntervalRef.current !== null) { @@ -277,6 +297,28 @@ export function useStackActions(options: UseStackActionsOptions) { }; }, []); + // Commit-aligned detail milestones. Each fires once React has committed the + // observed state for the owning attempt; commitMilestone no-ops for a + // superseded (node switch) or aborted (re-load) attempt so an interrupted + // load never records a success milestone. + useEffect(() => { + if (stackListState.selectedFile !== detailFileRef.current) return; + if (navState.activeView !== 'editor') return; + flushPendingCommit(detailVisiblePendingRef, 'detail_visible'); + }, [stackListState.selectedFile, navState.activeView, detailVisibleEpoch]); + + useEffect(() => { + if (stackListState.selectedFile !== detailFileRef.current) return; + flushPendingCommit(detailContainersPendingRef, 'detail_containers_ready'); + }, [editorState.containers, stackListState.selectedFile]); + + useEffect(() => { + // Wait for the load to settle so this reflects the fully hydrated detail. + if (editorState.isFileLoading) return; + if (stackListState.selectedFile !== detailFileRef.current) return; + flushPendingCommit(detailHydratedPendingRef, 'detail_hydrated'); + }, [editorState.isFileLoading, stackListState.selectedFile, editorState.containers]); + const isAbortError = (err: unknown): boolean => err instanceof Error && err.name === 'AbortError'; @@ -476,16 +518,47 @@ export function useStackActions(options: UseStackActionsOptions) { } }; - const loadContainerState = async (filename: string, signal?: AbortSignal) => { + const loadContainerState = async ( + filename: string, + signal?: AbortSignal, + attemptId?: string, + proxied?: boolean, + ): Promise => { + let headersSpan: SpanHandle | null = null; + let bodySpan: SpanHandle | null = null; try { + headersSpan = attemptId + ? beginSpan('fetch_headers', { attemptId, proxied }) + : null; const containersRes = await apiFetch(`/stacks/${filename}/containers`, { signal }); - if (signal?.aborted) return; + const hopProxied = containersRes.headers.get('x-sencho-proxy') === '1' || proxied === true; + if (headersSpan !== null) { + endSpan(headersSpan, { proxied: hopProxied, detail: { status: containersRes.status } }); + headersSpan = null; + } + if (signal?.aborted) return 0; + bodySpan = attemptId + ? beginSpan('body_decode', { attemptId, proxied: hopProxied }) + : null; const conts = await containersRes.json(); - editorState.setContainers(Array.isArray(conts) ? conts : []); + if (bodySpan !== null) { + endSpan(bodySpan); + bodySpan = null; + } + const list = Array.isArray(conts) ? conts : []; + const dispatchSpan = attemptId + ? beginSpan('state_dispatch', { attemptId, proxied: hopProxied }) + : null; + editorState.setContainers(list); + if (dispatchSpan !== null) endSpan(dispatchSpan); + return list.length; } catch (error) { - if (isAbortError(error)) return; + if (headersSpan !== null) endSpan(headersSpan, { outcome: 'error' }); + if (bodySpan !== null) endSpan(bodySpan, { outcome: 'error' }); + if (isAbortError(error)) return 0; console.error('Failed to load containers:', error); editorState.setContainers([]); + return 0; } }; @@ -520,29 +593,58 @@ export function useStackActions(options: UseStackActionsOptions) { return { ok: false }; } loadFileAbortRef.current?.abort(); + // Supersede the previous detail attempt so a late commit from an interrupted + // load can never record a success milestone. + if (detailAttemptRef.current) abortAttempt(detailAttemptRef.current); + detailVisiblePendingRef.current = null; + detailContainersPendingRef.current = null; + detailHydratedPendingRef.current = null; const controller = new AbortController(); loadFileAbortRef.current = controller; const { signal } = controller; + const attemptId = newAttemptId(); + detailAttemptRef.current = attemptId; + detailFileRef.current = filename; editorState.setIsFileLoading(true); editorState.setIsEditing(false); editorState.setEditingCompose(false); editorState.setActiveTab('compose'); + let headersSpan: SpanHandle | null = null; + let bodySpan: SpanHandle | null = null; try { + headersSpan = beginSpan('fetch_headers', { attemptId }); const res = await apiFetch(`/stacks/${filename}`, { signal }); - if (signal.aborted) return { ok: false }; + const proxied = res.headers.get('x-sencho-proxy') === '1'; + endSpan(headersSpan, { proxied, detail: { status: res.status } }); + headersSpan = null; + if (signal.aborted) { abortAttempt(attemptId); return { ok: false }; } + bodySpan = beginSpan('body_decode', { attemptId, proxied }); const text = await res.text(); - if (signal.aborted) return { ok: false }; + endSpan(bodySpan); + bodySpan = null; + if (signal.aborted) { abortAttempt(attemptId); return { ok: false }; } if (!res.ok) { throw new Error(`Failed to load stack: ${res.status}`); } + const dispatchSpan = beginSpan('state_dispatch', { attemptId, proxied }); stackListState.setSelectedFile(filename); navState.setActiveView('editor'); editorState.setContent(text || ''); editorState.setOriginalContent(text || ''); editorState.setComposeEtag(res.headers.get('etag')); + endSpan(dispatchSpan); + detailVisiblePendingRef.current = { attemptId, token: filename, proxied }; + setDetailVisibleEpoch((n) => n + 1); const envFiles = await loadEnvState(filename, signal); - await loadContainerState(filename, signal); + const containerCount = await loadContainerState(filename, signal, attemptId, proxied); + if (!signal.aborted) { + detailContainersPendingRef.current = { + attemptId, + token: `${filename}:${containerCount}`, + proxied, + }; + } await loadBackupState(filename, signal); // Post-load auto-edit evaluates permission for the loaded target, not // the previously selected stack (selectedFile was just updated above). @@ -551,9 +653,14 @@ export function useStackActions(options: UseStackActionsOptions) { editorState.setActiveTab('compose'); editorState.setIsEditing(true); } + if (!signal.aborted) { + detailHydratedPendingRef.current = { attemptId, token: filename, proxied }; + } return { ok: true, envFiles }; } catch (error) { - if (isAbortError(error) || signal.aborted) return { ok: false }; + if (headersSpan !== null) endSpan(headersSpan, { outcome: 'error' }); + if (bodySpan !== null) endSpan(bodySpan, { outcome: 'error' }); + if (isAbortError(error) || signal.aborted) { abortAttempt(attemptId); return { ok: false }; } console.error('Failed to load file:', error); toast.error(`Could not open "${filename.replace(/\.(ya?ml)$/, '')}". Check your connection and try again.`); stackListState.setSelectedFile(null); diff --git a/frontend/src/components/EditorLayout/hooks/useStackListState.ts b/frontend/src/components/EditorLayout/hooks/useStackListState.ts index 3b4b04d0..0d598ffd 100644 --- a/frontend/src/components/EditorLayout/hooks/useStackListState.ts +++ b/frontend/src/components/EditorLayout/hooks/useStackListState.ts @@ -1,5 +1,15 @@ import { useState, useEffect, useRef, useMemo, useCallback } from 'react'; import { apiFetch } from '@/lib/api'; +import { + newAttemptId, + abortAttempt, + beginSpan, + endSpan, + flushPendingCommit, + markMilestone, + type SpanHandle, + type PendingCommit, +} from '@/lib/hydrationTiming'; import { toast } from '@/components/ui/toast-store'; import { useNodes } from '@/context/NodeContext'; import { useImageUpdates } from '@/hooks/useImageUpdates'; @@ -85,6 +95,13 @@ export function useStackListState() { // state writes so a rapid node switch cannot leave a stale files/filesNodeId. const fetchSeqRef = useRef(0); + // Hydration-timing: the current foreground list attempt and the commits it is + // waiting for React to observe. Only foreground loads arm these; background + // refreshes still record diagnostic spans but do not re-commit the milestones. + const listAttemptRef = useRef(null); + const listVisiblePendingRef = useRef(null); + const listHydratedPendingRef = useRef(null); + // Per-stack terminal failure records driving the in-detail recovery panel. // In-memory only. Node scoping is enforced by the caller, which clears these // on active-node change (see EditorLayout's node-switch effect) so a repeated @@ -196,6 +213,20 @@ export function useStackListState() { const mySeq = ++fetchSeqRef.current; const stale = () => fetchSeqRef.current !== mySeq; + // Supersede any in-flight list attempt so a late commit from an interrupted + // load cannot record list_visible / list_hydrated for a stale fetch. + if (listAttemptRef.current) abortAttempt(listAttemptRef.current); + listVisiblePendingRef.current = null; + listHydratedPendingRef.current = null; + + const attemptId = newAttemptId(); + listAttemptRef.current = attemptId; + // True once the list itself is committed, so the shared catch below can tell + // a list-fetch failure (nothing visible) from a status-path failure (list is + // visible, hydration errored). + let listSucceeded = false; + let proxied = false; + if (!background) setIsLoading(true); setStacksLoadNodeId(fetchNodeId); if (!background || !hadSuccessfulListRef.current) { @@ -203,9 +234,13 @@ export function useStackListState() { setStacksLoadError(null); } + const headersSpan = beginSpan('fetch_headers', { attemptId, background }); + let bodySpan: SpanHandle | null = null; try { const res = await apiFetch('/stacks'); - if (stale()) return []; + proxied = res.headers.get('x-sencho-proxy') === '1'; + endSpan(headersSpan, { proxied, detail: { status: res.status } }); + if (stale()) { abortAttempt(attemptId); return []; } if (!res.ok) { const message = `Could not load stacks (${res.status})`; if (background && hadSuccessfulListRef.current) { @@ -218,26 +253,51 @@ export function useStackListState() { setStacksLoadError(message); return []; } + bodySpan = beginSpan('body_decode', { attemptId, background, proxied }); const data = await res.json(); + endSpan(bodySpan); + bodySpan = null; const fileList: string[] = Array.isArray(data) ? data : []; + const listDispatch = beginSpan('state_dispatch', { attemptId, background, proxied }); setFiles(fileList); setFilesNodeId(fetchNodeId); hadSuccessfulListRef.current = true; setStacksLoadStatus('success'); setStacksLoadError(null); + endSpan(listDispatch); + listSucceeded = true; + // Token folds node + count so an empty->empty commit still fires once per + // attempt even when the committed `files` is referentially equal. + const listToken = `${fetchNodeId}:${fileList.length}`; + if (!background) { + listVisiblePendingRef.current = { attemptId, token: listToken, proxied }; + } // Fetch all stack statuses in a single bulk call. Only the current object // format can express `partial`; a node lacking the endpoint or returning // the legacy plain-string format is re-derived from per-stack containers // so a crashed container is not hidden behind a healthy sibling. + const statusHeaders = beginSpan('fetch_headers', { attemptId, background, proxied }); const statusRes = await apiFetch('/stacks/statuses'); - if (stale()) return fileList; + const statusProxied = statusRes.headers.get('x-sencho-proxy') === '1' || proxied; + endSpan(statusHeaders, { proxied: statusProxied, detail: { status: statusRes.status } }); + if (stale()) { abortAttempt(attemptId); return fileList; } let bulkStatuses: Record = {}; const bulkPorts: Record = {}; const bulkSelf: Record = {}; const bulkCounts: StackCounts = {}; - const raw: unknown = statusRes.ok ? await statusRes.json() : null; + let raw: unknown = null; + if (statusRes.ok) { + const statusBodySpan = beginSpan('body_decode', { attemptId, background, proxied: statusProxied }); + try { + raw = await statusRes.json(); + endSpan(statusBodySpan); + } catch (decodeErr) { + endSpan(statusBodySpan, { outcome: 'error' }); + throw decodeErr; + } + } if (isBulkStatusObjectFormat(raw)) { for (const [key, val] of Object.entries(raw as Record)) { bulkStatuses[key] = val.status; @@ -250,6 +310,7 @@ export function useStackListState() { } else { bulkStatuses = await deriveStatusesFromContainers(fileList); } + const statusDispatch = beginSpan('state_dispatch', { attemptId, background, proxied: statusProxied }); setStackStatuses(prev => { const next: StackStatus = {}; for (const file of fileList) { @@ -265,12 +326,24 @@ export function useStackListState() { }); setStackSelfFlags(bulkSelf); setStackCounts(bulkCounts); + endSpan(statusDispatch); refreshLabels(); + if (!background) { + listHydratedPendingRef.current = { attemptId, token: listToken, proxied: statusProxied }; + } return fileList; } catch (error) { - if (stale()) return []; + // endSpan is a no-op when the span was already closed (or never opened). + endSpan(headersSpan, { outcome: 'error' }); + if (bodySpan !== null) endSpan(bodySpan, { outcome: 'error' }); + if (stale()) { abortAttempt(attemptId); return []; } console.error('Failed to refresh stacks:', error); const message = error instanceof Error ? error.message : 'Failed to load stacks'; + // The list committed but hydrating its statuses threw: record the list + // path as hydrated-with-error rather than leaving it hanging. + if (listSucceeded && !background) { + markMilestone('list_hydrated', { attemptId, outcome: 'error', proxied }); + } if (background && hadSuccessfulListRef.current) { setStacksLoadError(message); return files; @@ -290,6 +363,20 @@ export function useStackListState() { const refreshStacksRef = useRef(refreshStacks); useEffect(() => { refreshStacksRef.current = refreshStacks; }); + // Commit-aligned list milestones: fire once React has actually committed the + // file list (list_visible) and the statuses (list_hydrated) for the owning + // attempt. commitMilestone no-ops for a superseded/aborted attempt, so a stale + // load can never complete a session it no longer owns. Empty lists still fire + // via the completion token. + useEffect(() => { + if (stacksLoadStatus !== 'success') return; + flushPendingCommit(listVisiblePendingRef, 'list_visible'); + }, [files, filesNodeId, stacksLoadStatus]); + + useEffect(() => { + flushPendingCommit(listHydratedPendingRef, 'list_hydrated'); + }, [stackStatuses, filesNodeId]); + const handleScanStacks = async () => { if (isScanning) return; setIsScanning(true); diff --git a/frontend/src/components/HydrationTimingPanel.tsx b/frontend/src/components/HydrationTimingPanel.tsx new file mode 100644 index 00000000..47eba42d --- /dev/null +++ b/frontend/src/components/HydrationTimingPanel.tsx @@ -0,0 +1,184 @@ +import { useCallback, useEffect, useState } from 'react'; +import { Copy, Timer, Trash2, X } from 'lucide-react'; +import { cn } from '@/lib/utils'; +import { copyToClipboard } from '@/lib/clipboard'; +import { toast } from '@/components/ui/toast-store'; +import { useHydrationTiming } from '@/hooks/useHydrationTiming'; +import { clearReport, getHydrationReport } from '@/lib/hydrationTiming'; +import type { HydrationOutcome } from '@/lib/hydrationTiming'; + +/** Format an elapsed duration compactly: seconds with one decimal at or above + * 1s, whole milliseconds below. */ +function formatMs(ms: number): string { + return ms >= 1000 ? `${(ms / 1000).toFixed(1)}s` : `${Math.round(ms)}ms`; +} + +function formatOffset(ms: number | null): string { + return ms == null ? '-' : formatMs(ms); +} + +function outcomeDotClass(outcome: HydrationOutcome | undefined, critical: boolean): string { + if (outcome === 'error') return 'bg-destructive'; + if (outcome === 'aborted' || outcome === 'superseded') return 'bg-muted-foreground'; + return critical ? 'bg-brand' : 'bg-success'; +} + +const POSITION_CLASS = + 'fixed left-4 bottom-6 z-[100] max-md:left-3 max-md:right-3 max-md:bottom-[calc(var(--sn-mobile-tabbar-h)_+_env(safe-area-inset-bottom)_+_0.75rem)]'; + +/** + * Developer-mode-only overlay for startup and stack-hydration timing. + * + * Mount this only when developer mode is on for the active node; it does not + * gate itself. It shows a collapsed chip with the boot-to-`list_visible` + * elapsed time, expanding to a phase table with copy/clear actions. It sits + * below toasts and modals and never covers the mobile tab bar or safe area. + */ +export function HydrationTimingPanel() { + const { listVisibleMs } = useHydrationTiming(); + const [expanded, setExpanded] = useState(false); + + useEffect(() => { + if (!expanded) return; + const onKey = (e: KeyboardEvent) => { + if (e.key === 'Escape') setExpanded(false); + }; + window.addEventListener('keydown', onKey); + return () => window.removeEventListener('keydown', onKey); + }, [expanded]); + + const chipLabel = listVisibleMs == null ? 'list …' : `list ${formatMs(listVisibleMs)}`; + + const handleCopy = useCallback(async () => { + try { + await copyToClipboard(JSON.stringify(getHydrationReport(), null, 2)); + toast.success('Hydration report copied.'); + } catch (e) { + console.error('[HydrationTiming] copy failed:', e); + toast.error('Could not copy the hydration report.'); + } + }, []); + + if (!expanded) { + return ( + + ); + } + + // Only build the (potentially large) report while the panel is open. + const report = getHydrationReport(); + + return ( +
+
+ + + Hydration timing + + {chipLabel} +
+ +
+ + + + + + + + + + {report.phases.length === 0 ? ( + + + + ) : ( + report.phases.map((p, i) => ( + + + + + + )) + )} + +
PhaseAtDur
+ No events recorded yet. +
+ + + {p.phase} + {p.proxied && proxy} + + + {formatOffset(p.offsetMs)} + + {p.durationMs == null ? '-' : formatMs(p.durationMs)} +
+
+ + {report.anyProxied && ( +

+ Some requests were proxied to a remote node. Nodes and proxy debug logs + need developer mode enabled on the gateway to appear. +

+ )} + +
+ + + +
+
+ ); +} diff --git a/frontend/src/components/__tests__/HydrationTimingPanel.test.tsx b/frontend/src/components/__tests__/HydrationTimingPanel.test.tsx new file mode 100644 index 00000000..1c7c211c --- /dev/null +++ b/frontend/src/components/__tests__/HydrationTimingPanel.test.tsx @@ -0,0 +1,117 @@ +import { render, screen, fireEvent, waitFor, act } from '@testing-library/react'; +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import type { HydrationReport, HydrationSnapshot } from '@/lib/hydrationTiming'; + +let mockSnapshot: HydrationSnapshot; +let mockListVisibleMs: number | null; +let mockReport: HydrationReport; + +vi.mock('@/hooks/useHydrationTiming', () => ({ + useHydrationTiming: () => ({ snapshot: mockSnapshot, listVisibleMs: mockListVisibleMs }), +})); + +const clearReportMock = vi.fn(); +vi.mock('@/lib/hydrationTiming', () => ({ + getHydrationReport: () => mockReport, + clearReport: () => clearReportMock(), +})); + +const copyMock = vi.fn().mockResolvedValue(undefined); +vi.mock('@/lib/clipboard', () => ({ copyToClipboard: (text: string) => copyMock(text) })); + +import { HydrationTimingPanel } from '../HydrationTimingPanel'; + +function snapshot(events: HydrationSnapshot['events'] = []): HydrationSnapshot { + return { + schemaVersion: 1, + clock: 'performance.now', + bootSessionId: 'boot-1', + bootStartAt: 0, + nodeSessionId: 'node-2', + nodeId: 1, + events, + }; +} + +function report(over: Partial = {}): HydrationReport { + return { + schemaVersion: 1, + capturedAt: 0, + clock: 'performance.now', + bootSessionId: 'boot-1', + nodeSessionId: 'node-2', + nodeId: 1, + listVisibleMs: 1200, + anyProxied: false, + phases: [ + { phase: 'boot_start', kind: 'milestone', offsetMs: 0, critical: true, outcome: 'ok' }, + { phase: 'list_visible', kind: 'milestone', offsetMs: 1200, uiCommitMs: 1200, critical: true, outcome: 'ok' }, + ], + ...over, + }; +} + +beforeEach(() => { + clearReportMock.mockClear(); + copyMock.mockClear(); + mockSnapshot = snapshot(); + mockListVisibleMs = 1200; + mockReport = report(); +}); + +describe('HydrationTimingPanel', () => { + it('shows the list_visible elapsed time on the collapsed chip', () => { + render(); + expect(screen.getByTestId('hydration-chip')).toHaveTextContent('list 1.2s'); + }); + + it('shows an ellipsis before list_visible commits', () => { + mockListVisibleMs = null; + render(); + expect(screen.getByTestId('hydration-chip')).toHaveTextContent('list …'); + }); + + it('expands into the phase table and collapses again', () => { + render(); + fireEvent.click(screen.getByTestId('hydration-chip')); + + expect(screen.getByTestId('hydration-panel')).toBeInTheDocument(); + expect(screen.getByText('list_visible')).toBeInTheDocument(); + + fireEvent.click(screen.getByTestId('hydration-collapse')); + expect(screen.queryByTestId('hydration-panel')).toBeNull(); + expect(screen.getByTestId('hydration-chip')).toBeInTheDocument(); + }); + + it('collapses on Escape', () => { + render(); + fireEvent.click(screen.getByTestId('hydration-chip')); + act(() => { + window.dispatchEvent(new KeyboardEvent('keydown', { key: 'Escape' })); + }); + expect(screen.queryByTestId('hydration-panel')).toBeNull(); + }); + + it('copies the hydration report as pretty JSON', async () => { + render(); + fireEvent.click(screen.getByTestId('hydration-chip')); + fireEvent.click(screen.getByTestId('hydration-copy')); + + await waitFor(() => expect(copyMock).toHaveBeenCalledTimes(1)); + expect(copyMock).toHaveBeenCalledWith(JSON.stringify(mockReport, null, 2)); + }); + + it('clears the report', () => { + render(); + fireEvent.click(screen.getByTestId('hydration-chip')); + fireEvent.click(screen.getByTestId('hydration-clear')); + expect(clearReportMock).toHaveBeenCalledTimes(1); + }); + + it('notes gateway developer mode when any event was proxied', () => { + mockReport = report({ anyProxied: true }); + render(); + fireEvent.click(screen.getByTestId('hydration-chip')); + expect(screen.getByText(/gateway/i)).toBeInTheDocument(); + }); +}); diff --git a/frontend/src/context/AuthContext.tsx b/frontend/src/context/AuthContext.tsx index c04cab65..9c4cee32 100644 --- a/frontend/src/context/AuthContext.tsx +++ b/frontend/src/context/AuthContext.tsx @@ -1,4 +1,5 @@ import { createContext, useContext, useState, useEffect, useCallback, type ReactNode } from 'react'; +import { markMilestone } from '@/lib/hydrationTiming'; type AppStatus = 'loading' | 'needsSetup' | 'notAuthenticated' | 'mfaChallenge' | 'authenticated'; @@ -109,6 +110,13 @@ export function AuthProvider({ children }: { children: ReactNode }) { } }; + // One-shot boot milestone: the auth gate has resolved to a terminal status + // (setup, login, MFA, or authenticated), so the app can leave the splash. + useEffect(() => { + if (appStatus === 'loading') return; + markMilestone('auth_resolved'); + }, [appStatus]); + useEffect(() => { checkAuth(); const handleUnauthorized = () => { diff --git a/frontend/src/context/NodeContext.tsx b/frontend/src/context/NodeContext.tsx index 6b9f39b9..80397e45 100644 --- a/frontend/src/context/NodeContext.tsx +++ b/frontend/src/context/NodeContext.tsx @@ -1,5 +1,6 @@ import React, { createContext, useContext, useState, useEffect, useCallback, useRef, useMemo } from 'react'; import { apiFetch } from '@/lib/api'; +import { beginNodeSession, markMilestone } from '@/lib/hydrationTiming'; import type { Capability } from '@/lib/capabilities'; export type NodeMode = 'proxy' | 'pilot_agent'; @@ -56,6 +57,18 @@ export function NodeProvider({ children }: { children: React.ReactNode }) { const nodeMetaRef = useRef>(nodeMeta); nodeMetaRef.current = nodeMeta; + // Open a fresh hydration-timing session the moment the active node id changes, + // during render (guarded by a ref to fire once per id). This must precede the + // shell's stack-list refresh so its attempt binds to the new node session: + // child effects (EditorLayout's node-switch effect that calls refreshStacks) + // run before this provider's effects, so an effect here would begin the + // session too late and the list milestone would never commit. + const hydrationNodeRef = useRef(null); + if (activeNode && hydrationNodeRef.current !== activeNode.id) { + hydrationNodeRef.current = activeNode.id; + beginNodeSession(activeNode.id); + } + const fetchNodeMeta = useCallback(async (nodeId: number, force = false) => { const cached = nodeMetaRef.current.get(nodeId); if (cached && !force) { @@ -157,6 +170,13 @@ export function NodeProvider({ children }: { children: React.ReactNode }) { return () => window.removeEventListener('node-not-found', handleNodeNotFound); }, [refreshNodes]); + // One-shot boot milestone: nodes have finished loading and an active node is + // resolved. Deduped by the store, so a later re-run is a no-op. + useEffect(() => { + if (isLoading || !activeNode) return; + markMilestone('nodes_resolved'); + }, [isLoading, activeNode]); + const activeNodeMeta = useMemo(() => { if (!activeNode) return null; return nodeMeta.get(activeNode.id) ?? null; diff --git a/frontend/src/hooks/__tests__/useDeveloperMode.test.ts b/frontend/src/hooks/__tests__/useDeveloperMode.test.ts new file mode 100644 index 00000000..9db91ae1 --- /dev/null +++ b/frontend/src/hooks/__tests__/useDeveloperMode.test.ts @@ -0,0 +1,96 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { renderHook, waitFor, act } from '@testing-library/react'; + +vi.mock('@/lib/api', () => ({ apiFetch: vi.fn() })); + +import { apiFetch } from '@/lib/api'; +import { SENCHO_SETTINGS_CHANGED } from '@/lib/events'; +import { useDeveloperMode } from '../useDeveloperMode'; + +const mockedFetch = apiFetch as unknown as ReturnType; + +function settingsResponse(developerMode: string) { + return { ok: true, status: 200, json: async () => ({ developer_mode: developerMode }) }; +} + +beforeEach(() => { + mockedFetch.mockReset(); + // Failures are logged, not thrown; silence the expected console noise. + vi.spyOn(console, 'error').mockImplementation(() => {}); +}); + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe('useDeveloperMode', () => { + it('enables when the active node has developer_mode on', async () => { + mockedFetch.mockResolvedValue(settingsResponse('1')); + const { result } = renderHook(() => useDeveloperMode(1)); + await waitFor(() => expect(result.current).toBe(true)); + }); + + it('discards a delayed node A response after switching to node B', async () => { + mockedFetch.mockImplementation((_url: string, opts?: { nodeId?: number | null }) => { + if (opts?.nodeId === 1) { + // Node A: developer mode on, but its response is slow. + return new Promise((resolve) => setTimeout(() => resolve(settingsResponse('1')), 50)); + } + // Node B: developer mode off, fast. + return Promise.resolve(settingsResponse('0')); + }); + + const { result, rerender } = renderHook(({ id }) => useDeveloperMode(id), { + initialProps: { id: 1 as number | undefined }, + }); + rerender({ id: 2 }); + + await waitFor(() => expect(result.current).toBe(false)); + // Node A's late response must not flip node B to enabled. + await new Promise((r) => setTimeout(r, 80)); + expect(result.current).toBe(false); + }); + + it('returns false when the settings fetch rejects', async () => { + mockedFetch.mockRejectedValue(new Error('network down')); + const { result } = renderHook(() => useDeveloperMode(1)); + await waitFor(() => expect(mockedFetch).toHaveBeenCalled()); + expect(result.current).toBe(false); + }); + + it('returns false on a non-ok settings response', async () => { + mockedFetch.mockResolvedValue({ ok: false, status: 500, json: async () => ({}) }); + const { result } = renderHook(() => useDeveloperMode(1)); + await waitFor(() => expect(mockedFetch).toHaveBeenCalled()); + expect(result.current).toBe(false); + }); + + it('refetches when a developer_mode settings change is broadcast', async () => { + let dev = '0'; + mockedFetch.mockImplementation(() => Promise.resolve(settingsResponse(dev))); + const { result } = renderHook(() => useDeveloperMode(1)); + await waitFor(() => expect(result.current).toBe(false)); + + dev = '1'; + act(() => { + window.dispatchEvent( + new CustomEvent(SENCHO_SETTINGS_CHANGED, { detail: { changedKeys: ['developer_mode'] } }), + ); + }); + await waitFor(() => expect(result.current).toBe(true)); + }); + + it('ignores a settings change that does not touch developer_mode', async () => { + mockedFetch.mockResolvedValue(settingsResponse('0')); + const { result } = renderHook(() => useDeveloperMode(1)); + await waitFor(() => expect(result.current).toBe(false)); + + const callsBefore = mockedFetch.mock.calls.length; + act(() => { + window.dispatchEvent( + new CustomEvent(SENCHO_SETTINGS_CHANGED, { detail: { changedKeys: ['log_retention_days'] } }), + ); + }); + expect(mockedFetch.mock.calls.length).toBe(callsBefore); + }); +}); diff --git a/frontend/src/hooks/useDeveloperMode.ts b/frontend/src/hooks/useDeveloperMode.ts new file mode 100644 index 00000000..05735650 --- /dev/null +++ b/frontend/src/hooks/useDeveloperMode.ts @@ -0,0 +1,82 @@ +import { useState, useEffect, useCallback, useRef } from 'react'; +import { apiFetch } from '@/lib/api'; +import { SENCHO_SETTINGS_CHANGED } from '@/lib/events'; +import type { SenchoSettingsChangedDetail } from '@/lib/events'; + +/** + * Reads the active node's `developer_mode` setting, race-safe against node + * switches (mirrors the ownership pattern in `useImageUpdates`). + * + * The setting is node-scoped: `/settings` is proxied to whichever node is + * active, so a mid-flight switch must never let node A's response flip the + * result for node B. A generation counter discards stale responses, and an + * owner check returns `false` on the render before the reset effect fires. + * + * Any failure (network, non-ok, parse) resolves to `false` so the developer + * overlay stays hidden rather than flickering on a transient error. + */ +export function useDeveloperMode(activeNodeId: number | undefined): boolean { + const [enabled, setEnabled] = useState(false); + + // Which node owns the current `enabled` value. When `activeNodeId` changes, + // React renders once with the old owner before the reset effect clears it; + // returning false on a mismatch avoids a one-frame flash of the wrong node's + // developer state. + const [ownerNodeId, setOwnerNodeId] = useState(activeNodeId); + + // Every node change increments this, and every await is gated against it so a + // slow response from a previous node is dropped. + const genRef = useRef(0); + + const refresh = useCallback(async () => { + const gen = ++genRef.current; + const targetNodeId = activeNodeId ?? null; + try { + const res = await apiFetch('/settings', { nodeId: targetNodeId }); + if (genRef.current !== gen) return; + if (!res.ok) { + console.error('[DeveloperMode] settings fetch returned', res.status); + setEnabled(false); + return; + } + const data = (await res.json()) as Record; + if (genRef.current !== gen) return; + setEnabled(data.developer_mode === '1'); + } catch (e) { + if (genRef.current !== gen) return; + console.error('[DeveloperMode] settings fetch failed:', e); + setEnabled(false); + } + }, [activeNodeId]); + + // Pin the settings-event handler to the latest closure without retriggering + // the listener effect on every render. + const refreshRef = useRef(refresh); + refreshRef.current = refresh; + + // Reset and refetch on mount and on node change. Capture the owning node and + // clear the flag BEFORE fetching so the guard returns false until the new + // node's response arrives. + useEffect(() => { + genRef.current += 1; + setEnabled(false); // eslint-disable-line react-hooks/set-state-in-effect + setOwnerNodeId(activeNodeId); // eslint-disable-line react-hooks/set-state-in-effect + void refreshRef.current(); + }, [activeNodeId]); + + // Propagate a developer-mode toggle immediately. Refetch when the change set + // names developer_mode, or when the detail is missing (unknown change set). + useEffect(() => { + const handler = (e: Event) => { + const detail = (e as CustomEvent>).detail; + if (!detail?.changedKeys || detail.changedKeys.includes('developer_mode')) { + void refreshRef.current(); + } + }; + window.addEventListener(SENCHO_SETTINGS_CHANGED, handler); + return () => window.removeEventListener(SENCHO_SETTINGS_CHANGED, handler); + }, []); + + const isOwner = activeNodeId !== undefined && activeNodeId === ownerNodeId; + return isOwner ? enabled : false; +} diff --git a/frontend/src/hooks/useHydrationTiming.ts b/frontend/src/hooks/useHydrationTiming.ts new file mode 100644 index 00000000..34a52bf8 --- /dev/null +++ b/frontend/src/hooks/useHydrationTiming.ts @@ -0,0 +1,21 @@ +import { useSyncExternalStore } from 'react'; +import { subscribe, getSnapshot, listVisibleMsFrom } from '@/lib/hydrationTiming'; +import type { HydrationSnapshot } from '@/lib/hydrationTiming'; + +export interface UseHydrationTiming { + snapshot: HydrationSnapshot; + /** Elapsed ms from boot to `list_visible`, or null before it commits. */ + listVisibleMs: number | null; +} + +/** Subscribe to the hydration timing store and expose the current snapshot + * plus the derived `list_visible` elapsed time for the collapsed chip. + * Derives from the snapshot React last read so the chip stays consistent + * with the events on screen, not a later live store mutation. */ +export function useHydrationTiming(): UseHydrationTiming { + const snapshot = useSyncExternalStore(subscribe, getSnapshot, getSnapshot); + return { + snapshot, + listVisibleMs: listVisibleMsFrom(snapshot.events, snapshot.bootStartAt), + }; +} diff --git a/frontend/src/hooks/useImageUpdates.ts b/frontend/src/hooks/useImageUpdates.ts index a775741c..15a70c94 100644 --- a/frontend/src/hooks/useImageUpdates.ts +++ b/frontend/src/hooks/useImageUpdates.ts @@ -1,5 +1,6 @@ import { useState, useEffect, useCallback, useRef } from 'react'; import { apiFetch } from '@/lib/api'; +import { markMilestone } from '@/lib/hydrationTiming'; import { SENCHO_SETTINGS_CHANGED } from '@/lib/events'; import type { ImageUpdateStatus, StackUpdateInfo } from '@/types/imageUpdates'; @@ -31,6 +32,10 @@ export function useImageUpdates(activeNodeId: number | undefined) { // discarded. const genRef = useRef(0); + // Node the image_updates_ready milestone last fired for, so it records once + // per node session (re-firing after a node switch) rather than every poll. + const imageUpdatesReadyNodeRef = useRef(undefined); + const refresh = useCallback(async () => { const gen = ++genRef.current; const targetNodeId = activeNodeId ?? null; @@ -92,6 +97,14 @@ export function useImageUpdates(activeNodeId: number | undefined) { }; await Promise.allSettled([fetchStatus(), fetchDetail()]); + + // Background milestone: both image-update requests have settled for the + // active node. Fire once per node session, and only if this refresh still + // owns the generation (a node switch mid-flight defers to the new node). + if (genRef.current === gen && imageUpdatesReadyNodeRef.current !== targetNodeId) { + imageUpdatesReadyNodeRef.current = targetNodeId; + markMilestone('image_updates_ready'); + } }, [activeNodeId]); // Pin the interval to the latest closure without retriggering it on diff --git a/frontend/src/lib/__tests__/hydrationTiming.test.ts b/frontend/src/lib/__tests__/hydrationTiming.test.ts new file mode 100644 index 00000000..2f31185f --- /dev/null +++ b/frontend/src/lib/__tests__/hydrationTiming.test.ts @@ -0,0 +1,185 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { waitFor } from '@testing-library/react'; + +// Each test gets a fresh module instance so the module-scoped boot session and +// event buffer start clean. Resetting modules re-runs the boot_start init. +type Store = typeof import('../hydrationTiming'); + +async function loadStore(setup?: () => void): Promise { + vi.resetModules(); + setup?.(); + return import('../hydrationTiming'); +} + +/** Stub `performance` with a caller-controlled clock so durations are exact. */ +function stubClock(getT: () => number): void { + vi.stubGlobal('performance', { + now: () => getT(), + mark: vi.fn(), + measure: vi.fn(), + clearMarks: vi.fn(), + clearMeasures: vi.fn(), + }); +} + +afterEach(() => { + vi.unstubAllGlobals(); + vi.restoreAllMocks(); +}); + +describe('hydrationTiming store', () => { + it('records boot_start once and dedupes one-shot milestones (StrictMode)', async () => { + const store = await loadStore(); + // Simulate a StrictMode double invocation plus an explicit re-mark. + store.markMilestone('boot_start'); + store.markMilestone('boot_start', { oneShot: true }); + store.markMilestone('auth_resolved'); + store.markMilestone('auth_resolved'); + + const phases = store.getHydrationReport().phases.map((p) => p.phase); + expect(phases.filter((p) => p === 'boot_start')).toHaveLength(1); + expect(phases.filter((p) => p === 'auth_resolved')).toHaveLength(1); + }); + + it('evicts the oldest events beyond the 200-event cap (FIFO)', async () => { + const store = await loadStore(); + for (let i = 0; i < 250; i++) { + const handle = store.beginSpan('fetch_headers'); + store.endSpan(handle); + } + const report = store.getHydrationReport(); + expect(report.phases).toHaveLength(200); + // boot_start was the very first event, so it has been evicted. + expect(report.phases.some((p) => p.phase === 'boot_start')).toBe(false); + }); + + it('never completes a superseded or aborted attempt', async () => { + const store = await loadStore(); + store.beginNodeSession(1); + const superseded = store.newAttemptId(); + store.beginNodeSession(2); // supersedes node session 1's attempts + store.commitMilestone('list_visible', superseded); + expect(store.getHydrationReport().phases.some((p) => p.phase === 'list_visible')).toBe(false); + + const aborted = store.newAttemptId(); + store.abortAttempt(aborted); + store.commitMilestone('detail_hydrated', aborted); + expect(store.getHydrationReport().phases.some((p) => p.phase === 'detail_hydrated')).toBe(false); + + // A live attempt for the current node session still commits. + const live = store.newAttemptId(); + store.commitMilestone('list_visible', live); + expect(store.getHydrationReport().phases.some((p) => p.phase === 'list_visible')).toBe(true); + }); + + it('marks unknown attempts as no-ops for commit milestones', async () => { + const store = await loadStore(); + store.beginNodeSession(1); + store.commitMilestone('list_visible', 'attempt-does-not-exist'); + expect(store.getHydrationReport().phases.some((p) => p.phase === 'list_visible')).toBe(false); + }); + + it('falls back to Date.now when performance is unavailable', async () => { + const store = await loadStore(() => vi.stubGlobal('performance', undefined)); + expect(() => store.markMilestone('auth_resolved')).not.toThrow(); + expect(store.getHydrationReport().clock).toBe('date.now-fallback'); + }); + + it('tolerates a performance object missing mark and measure', async () => { + const store = await loadStore(() => vi.stubGlobal('performance', { now: () => 5 })); + expect(() => { + store.beginNodeSession(1); + const a = store.newAttemptId(); + store.commitMilestone('list_visible', a); + const handle = store.beginSpan('body_decode', { attemptId: a }); + store.endSpan(handle); + }).not.toThrow(); + expect(store.getHydrationReport().clock).toBe('performance.now'); + }); + + it('clears node session events but keeps boot markers', async () => { + const store = await loadStore(); + store.markMilestone('auth_resolved'); + store.beginNodeSession(1); + const a = store.newAttemptId(); + store.commitMilestone('list_visible', a); + + store.clearReport(); + + const phases = store.getHydrationReport().phases.map((p) => p.phase); + expect(phases).toContain('boot_start'); + expect(phases).toContain('auth_resolved'); + expect(phases).not.toContain('list_visible'); + }); + + it('reports list_visible elapsed from boot_start', async () => { + let t = 0; + const store = await loadStore(() => stubClock(() => t)); + t = 1200; + store.beginNodeSession(1); + const a = store.newAttemptId(); + store.commitMilestone('list_visible', a); + expect(store.getListVisibleMs()).toBe(1200); + expect(store.getHydrationReport().listVisibleMs).toBe(1200); + }); + + it('returns null list_visible timing before it commits', async () => { + const store = await loadStore(); + expect(store.getListVisibleMs()).toBeNull(); + }); + + it('records span duration between begin and end', async () => { + let t = 0; + const store = await loadStore(() => stubClock(() => t)); + store.beginNodeSession(1); + const a = store.newAttemptId(); + t = 10; + const handle = store.beginSpan('fetch_headers', { attemptId: a }); + t = 35; + store.endSpan(handle); + const span = store.getHydrationReport().phases.find((p) => p.phase === 'fetch_headers'); + expect(span?.durationMs).toBe(25); + }); + + it('fires an empty->empty commit once per attempt via completion token', async () => { + const store = await loadStore(); + store.beginNodeSession(1); + const a = store.newAttemptId(); + store.commitMilestone('list_visible', a, { completionToken: 'empty' }); + store.commitMilestone('list_visible', a, { completionToken: 'empty' }); + + const listVisible = store.getHydrationReport().phases.filter((p) => p.phase === 'list_visible'); + expect(listVisible).toHaveLength(1); + expect(listVisible[0].detail?.completionToken).toBe('empty'); + + // Without a token, a repeat commit for the same attempt still dedupes. + const b = store.newAttemptId(); + store.commitMilestone('list_hydrated', b); + store.commitMilestone('list_hydrated', b); + expect(store.getHydrationReport().phases.filter((p) => p.phase === 'list_hydrated')).toHaveLength(1); + }); + + it('classifies background phases as non-critical', async () => { + const store = await loadStore(); + expect(store.classifyCritical('list_visible')).toBe(true); + expect(store.classifyCritical('notifications_ready')).toBe(false); + expect(store.classifyCritical('image_updates_ready')).toBe(false); + }); + + it('keeps snapshots referentially stable until an emit fires', async () => { + const store = await loadStore(); + const before = store.getSnapshot(); + expect(store.getSnapshot()).toBe(before); + + const listener = vi.fn(); + const unsubscribe = store.subscribe(listener); + store.markMilestone('auth_resolved'); + + await waitFor(() => expect(listener).toHaveBeenCalled()); + + const after = store.getSnapshot(); + expect(after).not.toBe(before); + expect(after.events.some((e) => e.phase === 'auth_resolved')).toBe(true); + unsubscribe(); + }); +}); diff --git a/frontend/src/lib/hydrationTiming.ts b/frontend/src/lib/hydrationTiming.ts new file mode 100644 index 00000000..629a4dc5 --- /dev/null +++ b/frontend/src/lib/hydrationTiming.ts @@ -0,0 +1,639 @@ +/** + * Session-scoped startup and stack-hydration timing store. + * + * The store lives for the lifetime of the page (one boot session) and tracks + * the latest node session on top of that. It is consumed through + * `useSyncExternalStore` (see `useHydrationTiming`) and copied out as a + * versioned JSON report from the developer-mode overlay. + * + * Design constraints: + * - Instrumentation only. Recording an event must never throw into a caller + * and must never perturb the timing it measures, so emits are coalesced. + * - Truthful ownership. A milestone committed from a React effect carries the + * owning attempt id; a late commit for a superseded or aborted attempt is a + * no-op so a stale render can never complete a session it no longer owns. + * - Degrade safely. `performance` and the User Timing API are optional; a + * `Date.now()` fallback keeps durations flowing when they are absent. + */ + +/** Commit-aligned lifecycle phases surfaced in the chip, panel, and report. */ +export type HydrationPhase = + | 'boot_start' + | 'auth_resolved' + | 'nodes_resolved' + | 'shell_committed' + | 'list_visible' + | 'list_hydrated' + | 'detail_visible' + | 'detail_containers_ready' + | 'detail_hydrated' + | 'notifications_ready' + | 'image_updates_ready'; + +/** Immediate post-setter debug marks, kept distinct from commit-aligned phases. */ +export type StateDispatchedMark = `${string}_state_dispatched`; + +/** Anything `markMilestone` accepts: a known phase or a debug dispatch mark. */ +export type HydrationMark = HydrationPhase | StateDispatchedMark; + +/** The subset of phases that are committed via `commitMilestone` (effect-observed). */ +export type UiCommitPhase = + | 'list_visible' + | 'list_hydrated' + | 'detail_visible' + | 'detail_containers_ready' + | 'detail_hydrated'; + +/** Instrumented request stages at each `apiFetch` call site. */ +export type HydrationStage = 'fetch_headers' | 'body_decode' | 'state_dispatch'; + +export type HydrationEventKind = 'milestone' | 'span' | 'background'; + +export type HydrationOutcome = 'ok' | 'error' | 'aborted' | 'superseded'; + +export type HydrationClock = 'performance.now' | 'date.now-fallback'; + +export type HydrationDetail = Record; + +export interface HydrationEvent { + /** Monotonic sequence id, stable for the lifetime of the event. */ + id: number; + /** The boot or node session that owns this event. */ + sessionId: string; + attemptId?: string; + /** Phase name (milestone) or stage name (span). */ + phase: string; + kind: HydrationEventKind; + /** Clock start (milestone mark time, or span begin). */ + t0: number; + /** Clock end for spans; absent for point milestones. */ + t1?: number; + outcome?: HydrationOutcome; + detail?: HydrationDetail; + /** True when the underlying request crossed the remote-node proxy. */ + proxied?: boolean; + /** True for milestones committed from an effect that observed committed state. */ + commit?: boolean; + nodeId?: number | null; +} + +export interface HydrationSnapshot { + schemaVersion: 1; + clock: HydrationClock; + bootSessionId: string; + bootStartAt: number | null; + nodeSessionId: string | null; + nodeId: number | null; + events: readonly HydrationEvent[]; +} + +export interface HydrationReportPhase { + phase: string; + kind: HydrationEventKind; + outcome?: HydrationOutcome; + /** Elapsed ms from `boot_start` to this event, or null if boot is unknown. */ + offsetMs: number | null; + /** Span duration in ms (t1 - t0). */ + durationMs?: number; + /** Elapsed ms from `boot_start` for commit-aligned milestones. */ + uiCommitMs?: number; + critical: boolean; + proxied?: boolean; + attemptId?: string; + detail?: HydrationDetail; +} + +export interface HydrationReport { + schemaVersion: 1; + /** Wall-clock capture time (Date.now), only for human reference. */ + capturedAt: number; + clock: HydrationClock; + appVersion?: string; + bootSessionId: string; + nodeSessionId: string | null; + nodeId: number | null; + listVisibleMs: number | null; + anyProxied: boolean; + phases: HydrationReportPhase[]; +} + +export interface MilestoneOptions { + attemptId?: string; + outcome?: HydrationOutcome; + oneShot?: boolean; + detail?: HydrationDetail; + proxied?: boolean; +} + +export interface CommitOptions { + outcome?: HydrationOutcome; + detail?: HydrationDetail; + proxied?: boolean; + /** Lets an empty->empty commit still fire once per attempt when committed + * state may be referentially equal to the previous render. */ + completionToken?: string; +} + +/** Armed by a fetch, flushed from a React effect once committed state is observed. */ +export interface PendingCommit { + attemptId: string; + token: string; + proxied: boolean; +} + +export interface SpanOptions { + attemptId?: string; + detail?: HydrationDetail; + proxied?: boolean; + /** Marks the span as belonging to a background refresh rather than the + * critical hydration path. */ + background?: boolean; +} + +export interface EndSpanOptions { + outcome?: HydrationOutcome; + detail?: HydrationDetail; + proxied?: boolean; +} + +/** Opaque handle returned by `beginSpan` and passed back to `endSpan`. */ +export type SpanHandle = number; + +const MAX_EVENTS = 200; +const MAX_ATTEMPTS = 200; +/** Coalesce emits to at most 4 Hz so the store never perturbs the timings. */ +const MIN_EMIT_INTERVAL_MS = 250; +const USER_TIMING_PREFIX = 'sn-hyd'; + +/** Phases recorded exactly once per boot session (deduped under StrictMode). */ +const ONE_SHOT_PHASES: ReadonlySet = new Set([ + 'boot_start', + 'auth_resolved', + 'nodes_resolved', + 'shell_committed', +]); + +/** Phases that hydrate off the critical path (reported as non-critical). */ +const BACKGROUND_PHASES: ReadonlySet = new Set([ + 'notifications_ready', + 'image_updates_ready', +]); + +const appVersion: string | undefined = + typeof __APP_VERSION__ !== 'undefined' ? __APP_VERSION__ : undefined; + +const clockKind: HydrationClock = + typeof performance !== 'undefined' && typeof performance.now === 'function' + ? 'performance.now' + : 'date.now-fallback'; + +function now(): number { + return clockKind === 'performance.now' ? performance.now() : Date.now(); +} + +function round(n: number): number { + return Math.round(n * 100) / 100; +} + +interface AttemptRecord { + sessionId: string; + aborted: boolean; + superseded: boolean; +} + +interface OpenSpan { + stage: HydrationStage; + sessionId: string; + attemptId?: string; + t0: number; + kind: HydrationEventKind; + detail?: HydrationDetail; + proxied?: boolean; +} + +let seq = 0; +function nextId(): number { + return ++seq; +} +function newSessionId(prefix: string): string { + return `${prefix}-${nextId()}`; +} + +const bootSessionId = newSessionId('boot'); +let bootStartAt: number | null = null; +let nodeSessionId: string | null = null; +let currentNodeId: number | null = null; + +let events: HydrationEvent[] = []; +const attempts = new Map(); +const openSpans = new Map(); +/** Boot one-shot dedupe keys (`phase::bootSessionId`). */ +const oneShotKeys = new Set(); +/** Commit dedupe keys (`phase::attemptId::completionToken`). */ +const committedKeys = new Set(); + +// User Timing helpers. Every entry point tolerates a missing API surface so a +// browser or test environment without `performance`, `mark`, or `measure` +// records durations off the clock fallback without throwing. +function hasPerformance(): boolean { + return typeof performance !== 'undefined'; +} + +const userTiming = { + mark(name: string): void { + if (!hasPerformance() || typeof performance.mark !== 'function') return; + try { + performance.mark(name); + } catch { + // User Timing is best-effort diagnostics; never surface a failure. + } + }, + measure(name: string, startMark: string, endMark: string): void { + if (!hasPerformance() || typeof performance.measure !== 'function') return; + try { + performance.measure(name, startMark, endMark); + } catch { + // A missing start/end mark must not break timing capture. + } + }, + clear(name: string): void { + if (!hasPerformance()) return; + try { + performance.clearMarks?.(name); + performance.clearMarks?.(`${name}:start`); + performance.clearMarks?.(`${name}:end`); + performance.clearMeasures?.(name); + } catch { + // Clearing stale entries is best-effort. + } + }, +}; + +function markName(sessionId: string, attemptId: string | undefined, phase: string): string { + return `${USER_TIMING_PREFIX}:${sessionId}:${attemptId ?? '-'}:${phase}`; +} + +function milestoneKind(phase: string): HydrationEventKind { + return BACKGROUND_PHASES.has(phase) ? 'background' : 'milestone'; +} + +/** Boot-scoped one-shots belong to the boot session; everything else to the + * active node session (falling back to boot before the first node resolves). */ +function phaseSessionId(phase: string): string { + return ONE_SHOT_PHASES.has(phase) ? bootSessionId : nodeSessionId ?? bootSessionId; +} + +function sessionNodeId(sessionId: string): number | null { + return sessionId === bootSessionId ? null : currentNodeId; +} + +function currentSessionId(): string { + return nodeSessionId ?? bootSessionId; +} + +function mergeDetail(a?: HydrationDetail, b?: HydrationDetail): HydrationDetail | undefined { + if (!a && !b) return undefined; + return { ...a, ...b }; +} + +// --------------------------------------------------------------------------- +// Snapshot + emit scheduling (useSyncExternalStore contract) +// --------------------------------------------------------------------------- + +let snapshot: HydrationSnapshot; +const listeners = new Set<() => void>(); +let flushScheduled = false; +let lastEmitAt = 0; + +function rebuildSnapshot(): void { + snapshot = { + schemaVersion: 1, + clock: clockKind, + bootSessionId, + bootStartAt, + nodeSessionId, + nodeId: currentNodeId, + events: events.slice(), + }; +} + +function doEmit(): void { + flushScheduled = false; + lastEmitAt = now(); + rebuildSnapshot(); + for (const listener of listeners) listener(); +} + +function scheduleEmit(): void { + if (flushScheduled) return; + flushScheduled = true; + const run = (): void => { + const elapsed = now() - lastEmitAt; + if (elapsed >= MIN_EMIT_INTERVAL_MS) { + doEmit(); + } else { + setTimeout(doEmit, MIN_EMIT_INTERVAL_MS - elapsed); + } + }; + if (typeof requestAnimationFrame === 'function') { + requestAnimationFrame(run); + } else { + setTimeout(run, 16); + } +} + +function pushEvent(event: HydrationEvent): void { + events.push(event); + if (events.length > MAX_EVENTS) { + events.splice(0, events.length - MAX_EVENTS); + } + scheduleEmit(); +} + +// --------------------------------------------------------------------------- +// Public API +// --------------------------------------------------------------------------- + +export function subscribe(listener: () => void): () => void { + listeners.add(listener); + return () => { + listeners.delete(listener); + }; +} + +export function getSnapshot(): HydrationSnapshot { + return snapshot; +} + +/** Start a fresh node session, superseding the prior one and its attempts. */ +export function beginNodeSession(nodeId: number): string { + if (nodeSessionId) { + const prior = nodeSessionId; + for (const attempt of attempts.values()) { + if (attempt.sessionId === prior && !attempt.aborted) attempt.superseded = true; + } + for (const [handle, span] of openSpans) { + if (span.sessionId === prior) openSpans.delete(handle); + } + // Retain only boot markers plus the incoming node session's events. + events = events.filter((e) => e.sessionId === bootSessionId); + committedKeys.clear(); + } + nodeSessionId = newSessionId('node'); + currentNodeId = nodeId; + scheduleEmit(); + return nodeSessionId; +} + +export function newAttemptId(): string { + const id = newSessionId('attempt'); + attempts.set(id, { sessionId: currentSessionId(), aborted: false, superseded: false }); + if (attempts.size > MAX_ATTEMPTS) { + const oldest = attempts.keys().next().value; + if (oldest !== undefined) attempts.delete(oldest); + } + return id; +} + +/** Mark an attempt aborted; its in-flight spans finalize as aborted and later + * commit milestones for it become no-ops. */ +export function abortAttempt(attemptId: string): void { + const attempt = attempts.get(attemptId); + if (!attempt) return; + attempt.aborted = true; + for (const [handle, span] of openSpans) { + if (span.attemptId !== attemptId) continue; + openSpans.delete(handle); + pushEvent({ + id: handle, + sessionId: span.sessionId, + attemptId, + phase: span.stage, + kind: span.kind, + t0: span.t0, + t1: now(), + outcome: 'aborted', + detail: span.detail, + proxied: span.proxied, + nodeId: sessionNodeId(span.sessionId), + }); + } +} + +export function markMilestone(phase: HydrationMark, opts: MilestoneOptions = {}): void { + const oneShot = opts.oneShot ?? ONE_SHOT_PHASES.has(phase); + if (oneShot) { + const key = `${phase}::${bootSessionId}`; + if (oneShotKeys.has(key)) return; + oneShotKeys.add(key); + } + const sessionId = phaseSessionId(phase); + const t = now(); + pushEvent({ + id: nextId(), + sessionId, + attemptId: opts.attemptId, + phase, + kind: milestoneKind(phase), + t0: t, + outcome: opts.outcome ?? 'ok', + detail: opts.detail, + proxied: opts.proxied, + nodeId: sessionNodeId(sessionId), + }); + userTiming.mark(markName(sessionId, opts.attemptId, phase)); +} + +/** Record a commit-aligned UI milestone. No-op unless the attempt is still the + * current, non-superseded, non-aborted attempt for the active node session. */ +export function commitMilestone( + phase: UiCommitPhase, + attemptId: string, + opts: CommitOptions = {}, +): void { + const attempt = attempts.get(attemptId); + if (!attempt) return; + if (attempt.aborted || attempt.superseded) return; + if (attempt.sessionId !== nodeSessionId) return; + + const key = `${phase}::${attemptId}::${opts.completionToken ?? ''}`; + if (committedKeys.has(key)) return; + committedKeys.add(key); + + const t = now(); + const detail = opts.completionToken + ? { ...(opts.detail ?? {}), completionToken: opts.completionToken } + : opts.detail; + pushEvent({ + id: nextId(), + sessionId: attempt.sessionId, + attemptId, + phase, + kind: milestoneKind(phase), + t0: t, + outcome: opts.outcome ?? 'ok', + detail, + proxied: opts.proxied, + commit: true, + nodeId: currentNodeId, + }); + userTiming.mark(markName(attempt.sessionId, attemptId, phase)); +} + +/** Commit and clear a pending UI milestone ref. No-op when the ref is empty; + * callers still own the readiness guards (selected file, load status, etc.). */ +export function flushPendingCommit( + pendingRef: { current: PendingCommit | null }, + phase: UiCommitPhase, +): void { + const pending = pendingRef.current; + if (!pending) return; + commitMilestone(phase, pending.attemptId, { + completionToken: pending.token, + proxied: pending.proxied, + }); + pendingRef.current = null; +} + +export function beginSpan(stage: HydrationStage, opts: SpanOptions = {}): SpanHandle { + const handle = nextId(); + const sessionId = currentSessionId(); + openSpans.set(handle, { + stage, + sessionId, + attemptId: opts.attemptId, + t0: now(), + kind: opts.background ? 'background' : 'span', + detail: opts.detail, + proxied: opts.proxied, + }); + const name = markName(sessionId, opts.attemptId, stage); + userTiming.clear(name); + userTiming.mark(`${name}:start`); + return handle; +} + +export function endSpan(handle: SpanHandle, opts: EndSpanOptions = {}): void { + const span = openSpans.get(handle); + if (!span) return; + openSpans.delete(handle); + + const t1 = now(); + const outcome = resolveSpanOutcome(span.attemptId, opts.outcome); + const name = markName(span.sessionId, span.attemptId, span.stage); + userTiming.mark(`${name}:end`); + userTiming.measure(name, `${name}:start`, `${name}:end`); + + pushEvent({ + id: handle, + sessionId: span.sessionId, + attemptId: span.attemptId, + phase: span.stage, + kind: span.kind, + t0: span.t0, + t1, + outcome, + detail: mergeDetail(span.detail, opts.detail), + proxied: opts.proxied ?? span.proxied, + nodeId: sessionNodeId(span.sessionId), + }); +} + +function resolveSpanOutcome( + attemptId: string | undefined, + requested: HydrationOutcome | undefined, +): HydrationOutcome { + if (attemptId) { + const attempt = attempts.get(attemptId); + if (attempt?.aborted) return 'aborted'; + if (attempt?.superseded) return 'superseded'; + } + return requested ?? 'ok'; +} + +/** True when a phase is on the critical hydration path (not a background fill). */ +export function classifyCritical(phase: string): boolean { + return !BACKGROUND_PHASES.has(phase); +} + +/** Elapsed ms from `boot_start` to the most recent `list_visible` in `events`. */ +export function listVisibleMsFrom( + eventList: readonly HydrationEvent[], + bootAt: number | null, +): number | null { + if (bootAt == null) return null; + for (let i = eventList.length - 1; i >= 0; i--) { + if (eventList[i].phase === 'list_visible') { + return round(eventList[i].t0 - bootAt); + } + } + return null; +} + +/** Elapsed ms from `boot_start` to the most recent `list_visible`, or null. */ +export function getListVisibleMs(): number | null { + return listVisibleMsFrom(events, bootStartAt); +} + +function toReportPhase(event: HydrationEvent): HydrationReportPhase { + const offsetMs = bootStartAt == null ? null : round(event.t0 - bootStartAt); + const durationMs = event.t1 != null ? round(event.t1 - event.t0) : undefined; + const uiCommitMs = event.commit && offsetMs != null ? offsetMs : undefined; + return { + phase: event.phase, + kind: event.kind, + outcome: event.outcome, + offsetMs, + durationMs, + uiCommitMs, + // Background fills already use kind 'background' (see milestoneKind / beginSpan). + critical: event.kind !== 'background', + proxied: event.proxied, + attemptId: event.attemptId, + detail: event.detail, + }; +} + +export function getHydrationReport(): HydrationReport { + return { + schemaVersion: 1, + capturedAt: Date.now(), + clock: clockKind, + ...(appVersion ? { appVersion } : {}), + bootSessionId, + nodeSessionId, + nodeId: currentNodeId, + listVisibleMs: getListVisibleMs(), + anyProxied: events.some((e) => e.proxied === true), + phases: events.map(toReportPhase), + }; +} + +/** Clear the current node session's events (and commit dedupe), keeping boot + * markers so the boot timeline survives a manual clear. */ +export function clearReport(): void { + events = events.filter((e) => e.sessionId === bootSessionId); + committedKeys.clear(); + for (const [handle, span] of openSpans) { + if (span.sessionId !== bootSessionId) openSpans.delete(handle); + } + scheduleEmit(); +} + +// --------------------------------------------------------------------------- +// Boot session init: record boot_start once and seed the initial snapshot +// synchronously so the first `getSnapshot()` read already carries it. +// --------------------------------------------------------------------------- +bootStartAt = now(); +oneShotKeys.add(`boot_start::${bootSessionId}`); +events.push({ + id: nextId(), + sessionId: bootSessionId, + phase: 'boot_start', + kind: 'milestone', + t0: bootStartAt, + outcome: 'ok', + nodeId: null, +}); +userTiming.mark(markName(bootSessionId, undefined, 'boot_start')); +rebuildSnapshot(); diff --git a/frontend/src/main.tsx b/frontend/src/main.tsx index ed20ae00..c7555438 100644 --- a/frontend/src/main.tsx +++ b/frontend/src/main.tsx @@ -1,3 +1,6 @@ +// Side-effect import first so the timing store records boot_start at the +// earliest possible point, before React mounts. +import '@/lib/hydrationTiming' import { StrictMode } from 'react' import { createRoot } from 'react-dom/client' import './index.css'