Files
sencho/backend/src/services/FileExplorerMetricsService.ts
T
Anso 9f2f13f35a feat(stack-files): in-process metrics and structured mutation logs (#1216)
* feat(stack-files): in-process metrics and structured mutation logs

Adds FileExplorerMetricsService, an in-memory counter and latency
histogram keyed by (nodeId, op) modelled on StackOpMetricsService.
record() is called once per file-route request from a small
recordFileOp helper that wraps the metric capture; rejection paths
that ran real filesystem work (overwrite confirms, write conflicts,
multer oversize) now record an error count and a warn log instead of
disappearing from the snapshot. recordUploadBytes tracks bytes that
actually persisted so a node taking many small uploads vs a few large
ones is visible in the dashboard.

Admin-only GET /api/file-explorer-metrics returns the snapshot in the
same shape as /api/stack-metrics so an operator chasing a slow node
has a single place to look. No external telemetry; everything is
process-local and resets on restart.

Mutation INFO lines now carry op, stack, path, and bytes/mode/
recursive/overwrite/toPath in the structured details so log scrapers
can pivot on the same identity the metric uses. The existing
developer_mode gate on logFileDiag is unchanged. A new
rejectFileMutation helper centralises the log+metric+response triple
on the three rejection sites (upload DIR_EXISTS, upload FILE_EXISTS,
write PRECONDITION_FAILED) so a future rejection cannot skip the
metric.

Tests cover the service in isolation (counts, p50/p95, ring buffer cap,
upload bytes tracking, snapshot sorting), the admin route auth and
shape, and the route layer end-to-end: a real upload surfaces in
/api/file-explorer-metrics, a FILE_EXISTS rejection bumps errorCount,
and the structured INFO line carries the expected fields.

* fix(stack-files): tighten download/upload latency tracking

Two metric-accuracy bugs caught in independent review:

Download metric was recorded as a success before result.stream.pipe(res)
ran. A mid-stream read failure or a client disconnect was not counted as
an error because the recorder fired at pipe time, not stream completion.
Now the recorder hangs off res.on('finish') for success and on both the
stream's error event and res.on('close') for failure, with a flag so a
normal completion (which emits both finish and close) does not produce
two recordings.

Upload latency was inconsistent across the success and failure branches.
The multer wrapper captured startedAt at route entry, but the async
handler created its own startedAt after multer had already buffered the
body. Successful uploads therefore reported only the post-multer time
and the multipart transfer/buffer cost vanished from the histogram. The
wrapper now stashes the route-entry timestamp on the request object and
the async handler reads it back, so every metric for a given upload
shares one window.

A new test pins the download recorder behaviour: a single successful
download must produce successCount=1, count=1, errorCount=0 in the
snapshot, which would have flagged the original double-fire path the
finish+close pair could have introduced.
2026-05-25 01:46:08 -04:00

149 lines
4.7 KiB
TypeScript

/**
* In-memory counters + latency samples for stack file explorer operations.
* Internal-only; never exported to any external system. Surfaced to admins via
* GET /api/file-explorer-metrics so operators can answer "why is the file
* editor slow on this node?" without scrolling logs.
*
* State is process-local. A Sencho restart clears everything; the alternative
* (persisting to SQLite) would add write amplification to every file op for
* very little operator value. Each node tracks its own ops. A request that
* targets a remote node is recorded by the remote Sencho, not the central.
*/
export type FileExplorerOp =
| 'list'
| 'read'
| 'download'
| 'permissionsRead'
| 'upload'
| 'write'
| 'delete'
| 'mkdir'
| 'rename'
| 'chmod';
interface FileExplorerOpStats {
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 FileExplorerSnapshotEntry {
nodeId: number;
op: FileExplorerOp;
count: number;
successCount: number;
errorCount: number;
avgMs: number;
p50Ms: number;
p95Ms: number;
}
export interface FileExplorerSnapshot {
entries: FileExplorerSnapshotEntry[];
uploadBytesByNode: Array<{ nodeId: number; totalBytes: 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 FileExplorerMetricsService {
private static instance: FileExplorerMetricsService;
private readonly stats = new Map<string, FileExplorerOpStats>();
private readonly uploadBytes = new Map<number, number>();
public static getInstance(): FileExplorerMetricsService {
if (!FileExplorerMetricsService.instance) {
FileExplorerMetricsService.instance = new FileExplorerMetricsService();
}
return FileExplorerMetricsService.instance;
}
public static resetForTests(): void {
this.instance = new FileExplorerMetricsService();
}
private key(nodeId: number, op: FileExplorerOp): string {
return `${nodeId}:${op}`;
}
/**
* Record one completed op. `ok=false` for the rejection path. Call once per
* request from the route layer regardless of success or failure.
*/
public record(nodeId: number, op: FileExplorerOp, 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) {
// Drop oldest. Array.shift is O(n) but n is bounded to MAX_SAMPLES and
// this path runs once per file op (low cadence).
s.recentSamples.shift();
}
}
/**
* Record bytes flowing through an upload. Tracked separately because the
* latency histogram alone hides whether a slow node is being asked to take
* many small uploads or a few large ones.
*/
public recordUploadBytes(nodeId: number, bytes: number): void {
if (!Number.isFinite(bytes) || bytes < 0) return;
this.uploadBytes.set(nodeId, (this.uploadBytes.get(nodeId) ?? 0) + bytes);
}
public snapshot(): FileExplorerSnapshot {
const entries: FileExplorerSnapshotEntry[] = [];
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 FileExplorerOp,
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));
const uploadBytesByNode: Array<{ nodeId: number; totalBytes: number }> = [];
for (const [nodeId, totalBytes] of this.uploadBytes.entries()) {
uploadBytesByNode.push({ nodeId, totalBytes });
}
uploadBytesByNode.sort((a, b) => a.nodeId - b.nodeId);
return { entries, uploadBytesByNode };
}
public size(): number {
return this.stats.size;
}
}