feat(stack-activity): in-process metrics, structured diagnostic logs, docs (#1229)

Phase 3 + Phase 6 of the Stack Activity audit (PR 2 of 2):

- StackActivityMetricsService: in-process counters and ring-buffered
  latency histogram (1000 samples per nodeId/op pair). Mirrors the
  FileExplorerMetricsService pattern shipped in #1216. No external
  export. Records (nodeId, op) where op is read or write, with
  success/error counts and p50/p95 latency on demand.

- Admin endpoint GET /api/stack-activity-metrics returns the snapshot.
  Admin-only via requireAdmin, mounted next to the file-explorer
  metrics route. An operator debugging "why is the activity tab slow
  on this node?" can pull per-(nodeId, op) counts and latencies
  without scrolling logs.

- Diagnostic logs: route handler emits a structured [StackActivity:diag]
  read entry per request (stackName, nodeId, limit, before, beforeId,
  returned, elapsedMs); dispatchAlert emits a [StackActivity:diag] write
  entry per persisted notification (category, stackName, nodeId, actor,
  messageLen). Both gated on developer_mode via isDebugEnabled. Same
  namespace so a single grep covers reads and writes on the timeline
  path. Per-request and per-event, never inside a poll loop.

- Metric record points: the route's try/finally records a read metric
  with the outcome of the DB call; dispatchAlert records a write metric
  on both the success path and (before re-throwing) the failure path,
  so error rates from the insert path stay visible.

- docs/features/stack-activity.mdx: refreshed to reflect PR 1's
  retention behavior (30 days plus per-(node, stack) 500-row cap, 1000
  per-node unattached), composite (timestamp, id) cursor, error-vs-
  empty UI distinction, and "by username" vs "via Subsystem" actor
  rendering. Adds Troubleshooting entries for "Activity unavailable"
  (node disconnect or fetch failure), "expected event missing"
  (retention windows), and "same restart shows twice" (manual click
  vs Auto-Heal redeploy are distinct events).

No tier, role, or capability gate touched. The admin metrics endpoint
inherits the standard requireAdmin gate already used by /api/file-
explorer-metrics and /api/stack-metrics.
This commit is contained in:
Anso
2026-05-25 21:25:59 -04:00
committed by GitHub
parent 2d56ea958a
commit 80499ee18d
7 changed files with 285 additions and 22 deletions
@@ -0,0 +1,69 @@
import { describe, it, expect, beforeEach } from 'vitest';
import { StackActivityMetricsService } from '../services/StackActivityMetricsService';
beforeEach(() => {
StackActivityMetricsService.resetForTests();
});
describe('StackActivityMetricsService', () => {
it('counts success and error per (nodeId, op) independently', () => {
const m = StackActivityMetricsService.getInstance();
m.record(1, 'read', 5, true);
m.record(1, 'read', 10, true);
m.record(1, 'read', 8, false);
m.record(1, 'write', 2, true);
m.record(2, 'read', 3, true);
const snap = m.snapshot();
const oneRead = snap.entries.find(e => e.nodeId === 1 && e.op === 'read');
expect(oneRead).toMatchObject({ count: 3, successCount: 2, errorCount: 1 });
const oneWrite = snap.entries.find(e => e.nodeId === 1 && e.op === 'write');
expect(oneWrite).toMatchObject({ count: 1, successCount: 1, errorCount: 0 });
const twoRead = snap.entries.find(e => e.nodeId === 2 && e.op === 'read');
expect(twoRead).toMatchObject({ count: 1, successCount: 1 });
});
it('computes avg, p50, p95 over the ring buffer', () => {
const m = StackActivityMetricsService.getInstance();
for (let i = 1; i <= 100; i++) m.record(0, 'read', i, true);
const snap = m.snapshot();
const e = snap.entries[0];
expect(e.count).toBe(100);
expect(e.avgMs).toBe(Math.round((1 + 100) / 2));
expect(e.p50Ms).toBeGreaterThanOrEqual(48);
expect(e.p50Ms).toBeLessThanOrEqual(52);
expect(e.p95Ms).toBeGreaterThanOrEqual(94);
expect(e.p95Ms).toBeLessThanOrEqual(96);
});
it('drops oldest samples once the ring buffer is full', () => {
const m = StackActivityMetricsService.getInstance();
for (let i = 0; i < 1500; i++) m.record(0, 'read', i, true);
const snap = m.snapshot();
// count is unbounded; only the latency window is capped.
expect(snap.entries[0].count).toBe(1500);
// Samples 500..1499 are retained (oldest 500 evicted), so p50 is 999.
expect(snap.entries[0].p50Ms).toBeGreaterThanOrEqual(990);
expect(snap.entries[0].p50Ms).toBeLessThanOrEqual(1010);
});
it('ignores invalid durations', () => {
const m = StackActivityMetricsService.getInstance();
m.record(0, 'read', Number.NaN, true);
m.record(0, 'read', -5, true);
m.record(0, 'read', Number.POSITIVE_INFINITY, true);
expect(m.snapshot().entries).toEqual([]);
});
it('orders snapshot entries by nodeId then op', () => {
const m = StackActivityMetricsService.getInstance();
m.record(2, 'write', 1, true);
m.record(2, 'read', 1, true);
m.record(1, 'write', 1, true);
m.record(1, 'read', 1, true);
const order = m.snapshot().entries.map(e => `${e.nodeId}:${e.op}`);
expect(order).toEqual(['1:read', '1:write', '2:read', '2:write']);
});
});
+2
View File
@@ -51,6 +51,7 @@ import { stacksRouter } from './routes/stacks';
import { stackActivityRouter } from './routes/stackActivity';
import { stackMetricsRouter } from './routes/stackMetrics';
import { fileExplorerMetricsRouter } from './routes/fileExplorerMetrics';
import { stackActivityMetricsRouter } from './routes/stackActivityMetrics';
import { secretsRouter } from './routes/secrets';
// Suppress [DEP0060] DeprecationWarning emitted by http-proxy@1.18.1 which calls
@@ -145,6 +146,7 @@ app.use('/api/stacks', stackActivityRouter);
app.use('/api/stacks', stacksRouter);
app.use('/api/stack-metrics', stackMetricsRouter);
app.use('/api/file-explorer-metrics', fileExplorerMetricsRouter);
app.use('/api/stack-activity-metrics', stackActivityMetricsRouter);
const { server, wss, pilotTunnelWss } = createServer(app);
attachUpgrade(server, { wss, pilotTunnelWss });
+16 -2
View File
@@ -2,9 +2,15 @@ import { Router, type Request, type Response } from 'express';
import { DatabaseService } from '../services/DatabaseService';
import { requirePermission } from '../middleware/permissions';
import { isValidStackName } from '../utils/validation';
import { isDebugEnabled } from '../utils/debug';
import { StackActivityMetricsService } from '../services/StackActivityMetricsService';
export const stackActivityRouter = Router();
function dlog(message: string, details: Record<string, unknown>): void {
if (isDebugEnabled()) console.log(`[StackActivity:diag] ${message}`, details);
}
function parseStrictPositiveInt(raw: unknown): number | null {
if (raw === undefined || raw === null) return null;
const s = String(raw).trim();
@@ -14,6 +20,7 @@ function parseStrictPositiveInt(raw: unknown): number | null {
}
stackActivityRouter.get('/:stackName/activity', (req: Request, res: Response): void => {
const t0 = Date.now();
const stackName = req.params.stackName as string;
if (!isValidStackName(stackName)) {
res.status(400).json({ error: 'Invalid stack name' });
@@ -57,6 +64,13 @@ stackActivityRouter.get('/:stackName/activity', (req: Request, res: Response): v
beforeId = parsed;
}
const events = DatabaseService.getInstance().getStackActivity(req.nodeId, stackName, { limit, before, beforeId });
res.json({ events });
let ok = false;
try {
const events = DatabaseService.getInstance().getStackActivity(req.nodeId, stackName, { limit, before, beforeId });
ok = true;
res.json({ events });
dlog('read', { stackName, nodeId: req.nodeId, limit, before, beforeId, returned: events.length, elapsedMs: Date.now() - t0 });
} finally {
StackActivityMetricsService.getInstance().record(req.nodeId, 'read', Date.now() - t0, ok);
}
});
@@ -0,0 +1,19 @@
import { Router, type Request, type Response } from 'express';
import { requireAdmin } from '../middleware/tierGates';
import { StackActivityMetricsService } from '../services/StackActivityMetricsService';
export const stackActivityMetricsRouter = Router();
/**
* Admin-only snapshot of in-process stack activity metrics. No external
* export: this endpoint exists so an operator debugging "why is the
* activity tab slow?" or "are we logging unexpected error rates on the
* dispatch path?" can pull per-(nodeId, op) counts and latencies without
* scrolling logs.
*
* Mounted at /api/stack-activity-metrics after the global authGate.
*/
stackActivityMetricsRouter.get('/', (req: Request, res: Response): void => {
if (!requireAdmin(req, res)) return;
res.json(StackActivityMetricsService.getInstance().snapshot());
});
+28 -10
View File
@@ -5,6 +5,7 @@ import { isDebugEnabled } from '../utils/debug';
import { getErrorMessage } from '../utils/errors';
import { sanitizeForLog } from '../utils/safeLog';
import { sanitizeNotificationMessage } from '../utils/notificationMessage';
import { StackActivityMetricsService } from './StackActivityMetricsService';
export type NotificationCategory =
| 'deploy_success'
@@ -115,25 +116,42 @@ export class NotificationService {
message: string,
options?: { stackName?: string; containerName?: string; actor?: string },
) {
const t0 = Date.now();
const { stackName, containerName, actor } = options ?? {};
// Internal writes use the middleware default so they share a row key
// with user-initiated requests; otherwise the UI and monitors split
// between different node_id buckets.
const localNodeId = NodeRegistry.getInstance().getDefaultNodeId();
// Use the full resolution chain (node.compose_dir env default)
// Use the full resolution chain (node.compose_dir, env, default)
// so messages mentioning a per-node compose override get collapsed.
const sanitized = sanitizeNotificationMessage(message, {
composeDir: NodeRegistry.getInstance().getComposeDir(localNodeId),
});
const notification = this.dbService.addNotificationHistory(localNodeId, {
level,
category,
message: sanitized,
timestamp: Date.now(),
stack_name: stackName,
container_name: containerName,
actor_username: actor ?? null,
});
let notification: NotificationHistory;
try {
notification = this.dbService.addNotificationHistory(localNodeId, {
level,
category,
message: sanitized,
timestamp: Date.now(),
stack_name: stackName,
container_name: containerName,
actor_username: actor ?? null,
});
} catch (err) {
StackActivityMetricsService.getInstance().record(localNodeId, 'write', Date.now() - t0, false);
throw err;
}
StackActivityMetricsService.getInstance().record(localNodeId, 'write', Date.now() - t0, true);
// Separate [StackActivity:diag] namespace from the [Notify:diag] lines
// below so a single grep can pull every per-stack timeline write across
// route reads and dispatch writes.
if (isDebugEnabled()) {
console.log('[StackActivity:diag] write', {
category, stackName, nodeId: localNodeId, actor: actor ?? null, messageLen: sanitized.length,
});
}
// 2. Push to connected browser clients via WebSocket
this.broadcastToSubscribers(notification);
@@ -0,0 +1,111 @@
/**
* In-memory counters + latency samples for the per-stack activity timeline.
* Internal-only; never exported to any external system. Surfaced to admins
* via GET /api/stack-activity-metrics so operators can answer "why is the
* activity tab slow?" or "is the timeline dropping events?" without
* scrolling logs.
*
* State is process-local. A Sencho restart clears everything; persisting to
* SQLite would add write amplification to the hot dispatchAlert path for
* very little operator value. Each node tracks its own ops because the
* remote-node HTTP proxy (proxy/remoteNodeProxy.ts) short-circuits
* cross-node requests to the target's own router before this service sees
* them.
*/
export type StackActivityOp = 'read' | 'write';
interface StackActivityOpStats {
count: number;
successCount: number;
errorCount: number;
totalMs: number;
recentSamples: number[];
}
export interface StackActivitySnapshotEntry {
nodeId: number;
op: StackActivityOp;
count: number;
successCount: number;
errorCount: number;
avgMs: number;
p50Ms: number;
p95Ms: number;
}
export interface StackActivitySnapshot {
entries: StackActivitySnapshotEntry[];
}
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 StackActivityMetricsService {
private static instance: StackActivityMetricsService;
private readonly stats = new Map<string, StackActivityOpStats>();
public static getInstance(): StackActivityMetricsService {
if (!StackActivityMetricsService.instance) {
StackActivityMetricsService.instance = new StackActivityMetricsService();
}
return StackActivityMetricsService.instance;
}
public static resetForTests(): void {
this.instance = new StackActivityMetricsService();
}
private key(nodeId: number, op: StackActivityOp): string {
return `${nodeId}:${op}`;
}
public record(nodeId: number, op: StackActivityOp, durationMs: number, ok: boolean): void {
if (!Number.isFinite(durationMs) || durationMs < 0) return;
const k = this.key(nodeId, op);
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) {
s.recentSamples.shift();
}
}
public snapshot(): StackActivitySnapshot {
const entries: StackActivitySnapshotEntry[] = [];
for (const [key, s] of this.stats.entries()) {
const [nodeIdStr, op] = key.split(':');
const nodeId = Number(nodeIdStr);
if (!Number.isFinite(nodeId)) continue;
const sorted = [...s.recentSamples].sort((a, b) => a - b);
entries.push({
nodeId,
op: op as StackActivityOp,
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),
});
}
entries.sort((a, b) => a.nodeId - b.nodeId || a.op.localeCompare(b.op));
return { entries };
}
public size(): number {
return this.stats.size;
}
}