From 7ec6fe05bb7e32921b9dd06e52a850918f4e7bbc Mon Sep 17 00:00:00 2001 From: Anso Date: Sun, 24 May 2026 16:07:54 -0400 Subject: [PATCH] feat(stacks): in-process per-(nodeId, action) metrics + admin endpoint (#1196) Sencho exports no telemetry by design (privacy-first posture). That left operators with no answer for "why is this remote node slow today?" except scrolling logs. The audit log records mutations but has no latency information. Adds StackOpMetricsService - a tiny singleton holding per-(nodeId, action) counters and a 1000-sample ring buffer of latencies for p50/p95. Exposed through GET /api/stack-metrics (admin-only) so operators can pull the snapshot when debugging without touching disk or scrolling journalctl. No external export; the data never leaves the process. Wiring: deploy, down, restart, stop, start, update routes each capture t0 at entry, set ok=true after the success path, and record() in a finally block so failures count too. The record() call is cheap (one Map lookup, one push, occasional shift on the bounded ring buffer) and bounded in memory regardless of throughput. Resolves M-4 from the stack-management audit. API: GET /api/stack-metrics (admin-only) Response: { entries: [{ nodeId, action, count, successCount, errorCount, avgMs, p50Ms, p95Ms }, ...] } Ordering: nodeId ascending, then action ascending. Note on route mounting: /api/stack-metrics rather than the audit doc's suggested /api/meta/stack-metrics because metaRouter is intentionally mounted before authGate (public /api/health and /api/meta endpoints); adding an admin-only route to that group would either bypass auth or need a special inline gate that fights the existing structure. A dedicated /api/stack-metrics router after authGate is cleaner. Tests: - 9 unit tests in stack-op-metrics-service.test.ts: singleton, keyed-by-nodeId-action, p50/p95 math, ring-buffer cap at 1000, NaN/negative/Infinity rejection, ordering, reset. - 3 integration tests in stack-metrics-route.test.ts: 401 without auth, empty on fresh process, shape after recording. --- .../src/__tests__/stack-metrics-route.test.ts | 62 ++++++++++ .../stack-op-metrics-service.test.ts | 98 +++++++++++++++ backend/src/index.ts | 2 + backend/src/routes/stackMetrics.ts | 19 +++ backend/src/routes/stacks.ts | 19 ++- backend/src/services/StackOpMetricsService.ts | 115 ++++++++++++++++++ 6 files changed, 313 insertions(+), 2 deletions(-) create mode 100644 backend/src/__tests__/stack-metrics-route.test.ts create mode 100644 backend/src/__tests__/stack-op-metrics-service.test.ts create mode 100644 backend/src/routes/stackMetrics.ts create mode 100644 backend/src/services/StackOpMetricsService.ts 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; + } +}