diff --git a/backend/src/__tests__/stack-metrics-route.test.ts b/backend/src/__tests__/stack-metrics-route.test.ts new file mode 100644 index 00000000..1f6c2eb7 --- /dev/null +++ b/backend/src/__tests__/stack-metrics-route.test.ts @@ -0,0 +1,62 @@ +/** + * Integration tests for GET /api/stack-metrics. Admin-only endpoint + * surfacing the in-process snapshot from StackOpMetricsService. + */ +import { describe, it, expect, beforeAll, afterAll, beforeEach, vi } from 'vitest'; +import request from 'supertest'; +import { setupTestDb, cleanupTestDb, loginAsTestAdmin } from './helpers/setupTestDb'; + +let tmpDir: string; +let app: import('express').Express; +let authCookie: string; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ app } = await import('../index')); + authCookie = await loginAsTestAdmin(app); +}); + +afterAll(() => { + vi.restoreAllMocks(); + cleanupTestDb(tmpDir); +}); + +beforeEach(async () => { + const { StackOpMetricsService } = await import('../services/StackOpMetricsService'); + StackOpMetricsService.resetForTests(); +}); + +describe('GET /api/stack-metrics', () => { + it('returns 401 without an auth cookie', async () => { + const res = await request(app).get('/api/stack-metrics'); + expect(res.status).toBe(401); + }); + + it('returns an empty array on a fresh process', async () => { + const res = await request(app).get('/api/stack-metrics').set('Cookie', authCookie); + expect(res.status).toBe(200); + expect(res.body).toEqual({ entries: [] }); + }); + + it('returns recorded entries with the expected shape', async () => { + const { StackOpMetricsService } = await import('../services/StackOpMetricsService'); + const svc = StackOpMetricsService.getInstance(); + svc.record(1, 'deploy', 100, true); + svc.record(1, 'deploy', 200, false); + svc.record(2, 'restart', 50, true); + + const res = await request(app).get('/api/stack-metrics').set('Cookie', authCookie); + expect(res.status).toBe(200); + expect(res.body.entries).toHaveLength(2); + expect(res.body.entries[0]).toMatchObject({ + nodeId: 1, + action: 'deploy', + count: 2, + successCount: 1, + errorCount: 1, + avgMs: 150, + }); + expect(typeof res.body.entries[0].p50Ms).toBe('number'); + expect(typeof res.body.entries[0].p95Ms).toBe('number'); + }); +}); diff --git a/backend/src/__tests__/stack-op-metrics-service.test.ts b/backend/src/__tests__/stack-op-metrics-service.test.ts new file mode 100644 index 00000000..6c12768b --- /dev/null +++ b/backend/src/__tests__/stack-op-metrics-service.test.ts @@ -0,0 +1,98 @@ +/** + * Unit tests for StackOpMetricsService — the in-process per-(nodeId, action) + * counter + p50/p95 latency facility surfaced by GET /api/stack-metrics. + */ +import { describe, it, expect, beforeEach } from 'vitest'; +import { StackOpMetricsService } from '../services/StackOpMetricsService'; + +beforeEach(() => { + StackOpMetricsService.resetForTests(); +}); + +describe('StackOpMetricsService', () => { + it('returns a singleton', () => { + expect(StackOpMetricsService.getInstance()).toBe(StackOpMetricsService.getInstance()); + }); + + it('starts empty', () => { + expect(StackOpMetricsService.getInstance().size()).toBe(0); + expect(StackOpMetricsService.getInstance().snapshot()).toEqual([]); + }); + + it('records counts split between success and error', () => { + const svc = StackOpMetricsService.getInstance(); + svc.record(1, 'deploy', 100, true); + svc.record(1, 'deploy', 200, false); + svc.record(1, 'deploy', 300, true); + + const entries = svc.snapshot(); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + nodeId: 1, + action: 'deploy', + count: 3, + successCount: 2, + errorCount: 1, + avgMs: 200, + }); + }); + + it('keys independently by (nodeId, action)', () => { + const svc = StackOpMetricsService.getInstance(); + svc.record(1, 'deploy', 10, true); + svc.record(1, 'restart', 20, true); + svc.record(2, 'deploy', 30, true); + expect(svc.size()).toBe(3); + const entries = svc.snapshot(); + expect(entries.map(e => `${e.nodeId}:${e.action}`)).toEqual([ + '1:deploy', '1:restart', '2:deploy', + ]); + }); + + it('computes p50 and p95 from recent samples', () => { + const svc = StackOpMetricsService.getInstance(); + for (let i = 1; i <= 100; i++) { + svc.record(1, 'deploy', i, true); + } + const [entry] = svc.snapshot(); + expect(entry.p50Ms).toBe(50); + expect(entry.p95Ms).toBe(95); + }); + + it('caps the sample ring buffer at 1000 to bound memory', () => { + const svc = StackOpMetricsService.getInstance(); + for (let i = 1; i <= 1500; i++) { + svc.record(1, 'deploy', i, true); + } + const [entry] = svc.snapshot(); + expect(entry.count).toBe(1500); + // p95 uses only the last 1000 samples (501..1500), so p95 = 501 + floor((1000-1) * 0.95) = 501 + 949 = 1450 + expect(entry.p95Ms).toBe(1450); + }); + + it('ignores non-finite or negative durations', () => { + const svc = StackOpMetricsService.getInstance(); + svc.record(1, 'deploy', NaN, true); + svc.record(1, 'deploy', -5, true); + svc.record(1, 'deploy', Infinity, true); + expect(svc.size()).toBe(0); + }); + + it('snapshot ordering: nodeId asc, then action asc', () => { + const svc = StackOpMetricsService.getInstance(); + svc.record(3, 'start', 1, true); + svc.record(1, 'update', 1, true); + svc.record(2, 'deploy', 1, true); + svc.record(1, 'deploy', 1, true); + const keys = svc.snapshot().map(e => `${e.nodeId}:${e.action}`); + expect(keys).toEqual(['1:deploy', '1:update', '2:deploy', '3:start']); + }); + + it('resetForTests clears all state', () => { + const before = StackOpMetricsService.getInstance(); + before.record(1, 'deploy', 100, true); + StackOpMetricsService.resetForTests(); + expect(StackOpMetricsService.getInstance()).not.toBe(before); + expect(StackOpMetricsService.getInstance().size()).toBe(0); + }); +}); diff --git a/backend/src/index.ts b/backend/src/index.ts index 380b9de7..2eddd417 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -49,6 +49,7 @@ import { containersRouter, portsRouter } from './routes/containers'; import { nodesRouter } from './routes/nodes'; import { stacksRouter } from './routes/stacks'; import { stackActivityRouter } from './routes/stackActivity'; +import { stackMetricsRouter } from './routes/stackMetrics'; import { secretsRouter } from './routes/secrets'; // Suppress [DEP0060] DeprecationWarning emitted by http-proxy@1.18.1 which calls @@ -141,6 +142,7 @@ app.use('/api/dashboard', dashboardRouter); app.use('/api/nodes', nodesRouter); app.use('/api/stacks', stackActivityRouter); app.use('/api/stacks', stacksRouter); +app.use('/api/stack-metrics', stackMetricsRouter); const { server, wss, pilotTunnelWss } = createServer(app); attachUpgrade(server, { wss, pilotTunnelWss }); diff --git a/backend/src/routes/stackMetrics.ts b/backend/src/routes/stackMetrics.ts new file mode 100644 index 00000000..66e70c39 --- /dev/null +++ b/backend/src/routes/stackMetrics.ts @@ -0,0 +1,19 @@ +import { Router, type Request, type Response } from 'express'; +import { requireAdmin } from '../middleware/tierGates'; +import { StackOpMetricsService } from '../services/StackOpMetricsService'; + +export const stackMetricsRouter = Router(); + +/** + * Admin-only snapshot of in-process stack lifecycle metrics. No external + * export: this endpoint exists so an operator debugging "why is this remote + * node slow today?" can pull per-(nodeId, action) counts and latencies + * without scrolling logs. + * + * Mounted at /api/stack-metrics after the global authGate, so it inherits + * the standard session/Bearer auth surface like every other authed route. + */ +stackMetricsRouter.get('/', (req: Request, res: Response): void => { + if (!requireAdmin(req, res)) return; + res.json({ entries: StackOpMetricsService.getInstance().snapshot() }); +}); diff --git a/backend/src/routes/stacks.ts b/backend/src/routes/stacks.ts index 22cc56db..40b7bbac 100644 --- a/backend/src/routes/stacks.ts +++ b/backend/src/routes/stacks.ts @@ -15,6 +15,7 @@ import { requirePermission, checkPermission } from '../middleware/permissions'; import { requirePaid, requireAdmin, effectiveTier } from '../middleware/tierGates'; import { NotificationService, type NotificationCategory } from '../services/NotificationService'; import { StackOpLockService, type StackOpAction } from '../services/StackOpLockService'; +import { StackOpMetricsService, type StackOpAction as StackMetricAction } from '../services/StackOpMetricsService'; import { isValidGitSourcePath, isValidStackName, isValidServiceName, isPathWithinBase, isValidRelativeStackPath } from '../utils/validation'; import { getErrorMessage } from '../utils/errors'; import { isDebugEnabled } from '../utils/debug'; @@ -930,17 +931,19 @@ stacksRouter.post('/:stackName/deploy', async (req: Request, res: Response) => { if (!(await requireStackExists(req.nodeId, stackName, res))) return; // Lock held below. All early-returns must stay inside the try so finally fires. if (!tryAcquireStackOpLock(req, res, stackName, 'deploy')) return; + const t0 = Date.now(); + let ok = false; try { if (!(await runPolicyGate(req, res, stackName, req.nodeId))) return; const skipScan = req.body?.skip_scan === true; const debug = isDebugEnabled(); const atomic = effectiveTier(req) === 'paid'; if (debug) console.debug('[Stacks:debug] Deploy starting', { stackName, atomic, nodeId: req.nodeId }); - const t0 = Date.now(); await ComposeService.getInstance(req.nodeId).deployStack(stackName, getTerminalWs(), atomic); invalidateNodeCaches(req.nodeId); dlog(`[Stacks] Deploy completed: ${sanitizeForLog(stackName)}`); if (debug) console.debug(`[Stacks:debug] Deploy finished in ${Date.now() - t0}ms`); + ok = true; res.json({ message: 'Deployed successfully' }); notifyActionSuccess('deploy_success', `${stackName} deployed`, stackName, req.user?.username ?? 'system'); if (!skipScan) { @@ -968,6 +971,7 @@ stacksRouter.post('/:stackName/deploy', async (req: Request, res: Response) => { } } finally { releaseStackOpLock(req, stackName); + StackOpMetricsService.getInstance().record(req.nodeId, 'deploy', Date.now() - t0, ok); } }); @@ -977,11 +981,14 @@ stacksRouter.post('/:stackName/down', async (req: Request, res: Response) => { if (!(await requireStackExists(req.nodeId, stackName, res))) return; // Lock held below. All early-returns must stay inside the try so finally fires. if (!tryAcquireStackOpLock(req, res, stackName, 'down')) return; + const t0 = Date.now(); + let ok = false; try { if (isDebugEnabled()) console.debug(`[Stacks:debug] Down starting`, { stackName: sanitizeForLog(stackName), nodeId: req.nodeId }); await ComposeService.getInstance(req.nodeId).runCommand(stackName, 'down', getTerminalWs()); invalidateNodeCaches(req.nodeId); dlog(`[Stacks] Down completed: ${sanitizeForLog(stackName)}`); + ok = true; res.json({ status: 'Command started' }); } catch (error: unknown) { console.error('[Stacks] Down failed: %s', sanitizeForLog(stackName), error); @@ -995,6 +1002,7 @@ stacksRouter.post('/:stackName/down', async (req: Request, res: Response) => { } } finally { releaseStackOpLock(req, stackName); + StackOpMetricsService.getInstance().record(req.nodeId, 'down', Date.now() - t0, ok); } }); @@ -1066,6 +1074,8 @@ async function bulkContainerOp( if (!requirePermission(req, res, 'stack:deploy', 'stack', stackName)) return; // Lock held below. All early-returns must stay inside the try so finally fires. if (!tryAcquireStackOpLock(req, res, stackName, action)) return; + const t0 = Date.now(); + let ok = false; try { const titleCase = action.charAt(0).toUpperCase() + action.slice(1); if (isDebugEnabled()) console.debug(`[Stacks:debug] ${titleCase} starting`, { stackName: sanitizeForLog(stackName), nodeId: req.nodeId }); @@ -1090,6 +1100,7 @@ async function bulkContainerOp( invalidateNodeCaches(req.nodeId); dlog(`[Stacks] ${titleCase} completed: ${sanitizeForLog(stackName)} (${outcome.count} containers)`); + ok = true; res.json({ success: true, message: `${titleCase} completed via Engine API.` }); const { category, pastTense } = CONTAINER_ACTION_META[action]; notifyActionSuccess(category, `${stackName} ${pastTense}`, stackName, req.user?.username ?? 'system'); @@ -1100,6 +1111,7 @@ async function bulkContainerOp( } } finally { releaseStackOpLock(req, stackName); + StackOpMetricsService.getInstance().record(req.nodeId, action as StackMetricAction, Date.now() - t0, ok); } } @@ -1179,13 +1191,14 @@ stacksRouter.post('/:stackName/update', async (req: Request, res: Response) => { if (!(await requireStackExists(req.nodeId, stackName, res))) return; // Lock held below. All early-returns must stay inside the try so finally fires. if (!tryAcquireStackOpLock(req, res, stackName, 'update')) return; + const t0 = Date.now(); + let ok = false; try { if (!(await runPolicyGate(req, res, stackName, req.nodeId))) return; const skipScan = req.body?.skip_scan === true; const debug = isDebugEnabled(); const atomic = effectiveTier(req) === 'paid'; if (debug) console.debug('[Stacks:debug] Update starting', { stackName, atomic, nodeId: req.nodeId }); - const t0 = Date.now(); await ComposeService.getInstance(req.nodeId).updateStack(stackName, getTerminalWs(), atomic); DatabaseService.getInstance().clearStackUpdateStatus(req.nodeId, stackName); invalidateNodeCaches(req.nodeId); @@ -1199,6 +1212,7 @@ stacksRouter.post('/:stackName/update', async (req: Request, res: Response) => { }); dlog(`[Stacks] Update completed: ${sanitizeForLog(stackName)}`); if (debug) console.debug(`[Stacks:debug] Update finished in ${Date.now() - t0}ms`); + ok = true; res.json({ status: 'Update completed' }); notifyActionSuccess('image_update_applied', `${stackName} updated`, stackName, req.user?.username ?? 'system'); if (!skipScan) { @@ -1225,6 +1239,7 @@ stacksRouter.post('/:stackName/update', async (req: Request, res: Response) => { } } finally { releaseStackOpLock(req, stackName); + StackOpMetricsService.getInstance().record(req.nodeId, 'update', Date.now() - t0, ok); } }); diff --git a/backend/src/services/StackOpMetricsService.ts b/backend/src/services/StackOpMetricsService.ts new file mode 100644 index 00000000..aff6c6bd --- /dev/null +++ b/backend/src/services/StackOpMetricsService.ts @@ -0,0 +1,115 @@ +/** + * In-memory counters + latency samples for stack lifecycle operations. + * Internal-only - never exported to any external system. Surfaced to + * admins via GET /api/stack-metrics so operators have a way to debug + * "why is this remote node slow today?" without scrolling logs. + * + * State is process-local on purpose. A Sencho restart clears all metrics; + * the alternative (persisting to SQLite) would add write amplification + * to every lifecycle op for very little operator value. + */ + +export type StackOpAction = 'deploy' | 'down' | 'restart' | 'stop' | 'start' | 'update'; + +interface StackOpStats { + count: number; + successCount: number; + errorCount: number; + totalMs: number; + /** + * Ring buffer of recent latencies (newest at the end). Capped at + * MAX_SAMPLES to bound memory regardless of throughput. p50/p95 are + * computed from this window on demand. + */ + recentSamples: number[]; +} + +export interface StackOpSnapshotEntry { + nodeId: number; + action: StackOpAction; + count: number; + successCount: number; + errorCount: number; + avgMs: number; + p50Ms: number; + p95Ms: number; +} + +const MAX_SAMPLES = 1000; + +function percentile(sorted: readonly number[], p: number): number { + if (sorted.length === 0) return 0; + const idx = Math.min(sorted.length - 1, Math.floor((sorted.length - 1) * p)); + return sorted[idx]; +} + +export class StackOpMetricsService { + private static instance: StackOpMetricsService; + private readonly stats = new Map(); + + public static getInstance(): StackOpMetricsService { + if (!StackOpMetricsService.instance) { + StackOpMetricsService.instance = new StackOpMetricsService(); + } + return StackOpMetricsService.instance; + } + + public static resetForTests(): void { + this.instance = new StackOpMetricsService(); + } + + private key(nodeId: number, action: StackOpAction): string { + return `${nodeId}:${action}`; + } + + /** + * Record one completed op. Call from the route layer after the lifecycle + * call resolves or rejects; `ok=false` for the rejection path. + */ + public record(nodeId: number, action: StackOpAction, durationMs: number, ok: boolean): void { + if (!Number.isFinite(durationMs) || durationMs < 0) return; + const k = this.key(nodeId, action); + let s = this.stats.get(k); + if (!s) { + s = { count: 0, successCount: 0, errorCount: 0, totalMs: 0, recentSamples: [] }; + this.stats.set(k, s); + } + s.count += 1; + if (ok) s.successCount += 1; + else s.errorCount += 1; + s.totalMs += durationMs; + s.recentSamples.push(durationMs); + if (s.recentSamples.length > MAX_SAMPLES) { + // Drop oldest. Array.shift is O(n) but n is bounded to MAX_SAMPLES + // and this path is once-per-stack-op (low cadence). + s.recentSamples.shift(); + } + } + + public snapshot(): StackOpSnapshotEntry[] { + const out: StackOpSnapshotEntry[] = []; + for (const [key, s] of this.stats.entries()) { + const [nodeIdStr, action] = key.split(':'); + const nodeId = Number(nodeIdStr); + if (!Number.isFinite(nodeId)) continue; + const sorted = [...s.recentSamples].sort((a, b) => a - b); + out.push({ + nodeId, + action: action as StackOpAction, + count: s.count, + successCount: s.successCount, + errorCount: s.errorCount, + avgMs: s.count === 0 ? 0 : Math.round(s.totalMs / s.count), + p50Ms: percentile(sorted, 0.5), + p95Ms: percentile(sorted, 0.95), + }); + } + // Stable ordering: nodeId asc, then action asc. + out.sort((a, b) => a.nodeId - b.nodeId || a.action.localeCompare(b.action)); + return out; + } + + public size(): number { + return this.stats.size; + } +}