mirror of
https://github.com/Studio-Saelix/sencho.git
synced 2026-08-09 18:32:52 +00:00
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.
This commit is contained in:
@@ -0,0 +1,68 @@
|
||||
/**
|
||||
* Integration tests for GET /api/file-explorer-metrics. Admin-only endpoint
|
||||
* surfacing the in-process snapshot from FileExplorerMetricsService.
|
||||
*/
|
||||
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 { FileExplorerMetricsService } = await import('../services/FileExplorerMetricsService');
|
||||
FileExplorerMetricsService.resetForTests();
|
||||
});
|
||||
|
||||
describe('GET /api/file-explorer-metrics', () => {
|
||||
it('returns 401 without an auth cookie', async () => {
|
||||
const res = await request(app).get('/api/file-explorer-metrics');
|
||||
expect(res.status).toBe(401);
|
||||
});
|
||||
|
||||
it('returns an empty snapshot on a fresh process', async () => {
|
||||
const res = await request(app).get('/api/file-explorer-metrics').set('Cookie', authCookie);
|
||||
expect(res.status).toBe(200);
|
||||
expect(res.body).toEqual({ entries: [], uploadBytesByNode: [] });
|
||||
});
|
||||
|
||||
it('returns recorded entries and upload bytes with the expected shape', async () => {
|
||||
const { FileExplorerMetricsService } = await import('../services/FileExplorerMetricsService');
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.record(1, 'upload', 100, true);
|
||||
svc.record(1, 'upload', 200, false);
|
||||
svc.record(2, 'read', 50, true);
|
||||
svc.recordUploadBytes(1, 1024);
|
||||
svc.recordUploadBytes(2, 2048);
|
||||
|
||||
const res = await request(app).get('/api/file-explorer-metrics').set('Cookie', authCookie);
|
||||
expect(res.status).toBe(200);
|
||||
expect(res.body.entries).toHaveLength(2);
|
||||
expect(res.body.entries[0]).toMatchObject({
|
||||
nodeId: 1,
|
||||
op: 'upload',
|
||||
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');
|
||||
expect(res.body.uploadBytesByNode).toEqual([
|
||||
{ nodeId: 1, totalBytes: 1024 },
|
||||
{ nodeId: 2, totalBytes: 2048 },
|
||||
]);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,100 @@
|
||||
import { describe, it, expect, beforeEach } from 'vitest';
|
||||
import { FileExplorerMetricsService } from '../services/FileExplorerMetricsService';
|
||||
|
||||
beforeEach(() => {
|
||||
FileExplorerMetricsService.resetForTests();
|
||||
});
|
||||
|
||||
describe('FileExplorerMetricsService', () => {
|
||||
it('aggregates count, success, error, and avg/p50/p95 latency per (nodeId, op)', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.record(1, 'upload', 10, true);
|
||||
svc.record(1, 'upload', 30, true);
|
||||
svc.record(1, 'upload', 50, false);
|
||||
svc.record(1, 'read', 5, true);
|
||||
svc.record(2, 'upload', 1000, true);
|
||||
|
||||
const { entries } = svc.snapshot();
|
||||
const node1Upload = entries.find(e => e.nodeId === 1 && e.op === 'upload')!;
|
||||
expect(node1Upload.count).toBe(3);
|
||||
expect(node1Upload.successCount).toBe(2);
|
||||
expect(node1Upload.errorCount).toBe(1);
|
||||
expect(node1Upload.avgMs).toBe(30);
|
||||
// percentile() floors (n-1) * p, so with sorted = [10, 30, 50]: p50 = sorted[1] = 30
|
||||
// and p95 = sorted[floor((3-1)*0.95)] = sorted[1] = 30. The shared pattern with
|
||||
// StackOpMetricsService accepts this off-by-floor; the histogram is for
|
||||
// operator triage, not statistical reporting.
|
||||
expect(node1Upload.p50Ms).toBe(30);
|
||||
expect(node1Upload.p95Ms).toBe(30);
|
||||
|
||||
const node1Read = entries.find(e => e.nodeId === 1 && e.op === 'read')!;
|
||||
expect(node1Read.count).toBe(1);
|
||||
expect(node1Read.successCount).toBe(1);
|
||||
expect(node1Read.errorCount).toBe(0);
|
||||
|
||||
const node2Upload = entries.find(e => e.nodeId === 2 && e.op === 'upload')!;
|
||||
expect(node2Upload.count).toBe(1);
|
||||
expect(node2Upload.avgMs).toBe(1000);
|
||||
});
|
||||
|
||||
it('rejects negative or non-finite latency without growing the ring buffer', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.record(1, 'upload', -1, true);
|
||||
svc.record(1, 'upload', NaN, true);
|
||||
svc.record(1, 'upload', Infinity, true);
|
||||
expect(svc.size()).toBe(0);
|
||||
expect(svc.snapshot().entries).toEqual([]);
|
||||
});
|
||||
|
||||
it('caps the ring buffer at 1000 samples (older samples dropped on overflow)', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
// Record 1050 ops with increasing latencies. p95 should reflect the recent
|
||||
// window, not the dropped low values from the very start.
|
||||
for (let i = 0; i < 1050; i++) {
|
||||
svc.record(1, 'upload', i, true);
|
||||
}
|
||||
const entry = svc.snapshot().entries.find(e => e.nodeId === 1 && e.op === 'upload')!;
|
||||
expect(entry.count).toBe(1050);
|
||||
// The ring buffer dropped the first 50, so p50 ≈ 524 (middle of 50..1049)
|
||||
// and p95 ≈ 1001 (95th percentile of the same window). Use a relaxed
|
||||
// tolerance because percentile() floors the index.
|
||||
expect(entry.p50Ms).toBeGreaterThan(520);
|
||||
expect(entry.p50Ms).toBeLessThan(560);
|
||||
expect(entry.p95Ms).toBeGreaterThan(990);
|
||||
});
|
||||
|
||||
it('tracks upload bytes per node and sorts the snapshot by nodeId', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.recordUploadBytes(2, 1024);
|
||||
svc.recordUploadBytes(1, 512);
|
||||
svc.recordUploadBytes(2, 256);
|
||||
|
||||
const { uploadBytesByNode } = svc.snapshot();
|
||||
expect(uploadBytesByNode).toEqual([
|
||||
{ nodeId: 1, totalBytes: 512 },
|
||||
{ nodeId: 2, totalBytes: 1280 },
|
||||
]);
|
||||
});
|
||||
|
||||
it('ignores negative or non-finite upload byte counts', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.recordUploadBytes(1, -100);
|
||||
svc.recordUploadBytes(1, NaN);
|
||||
svc.recordUploadBytes(1, Infinity);
|
||||
expect(svc.snapshot().uploadBytesByNode).toEqual([]);
|
||||
});
|
||||
|
||||
it('snapshot entries sort by nodeId ascending then op alphabetically', () => {
|
||||
const svc = FileExplorerMetricsService.getInstance();
|
||||
svc.record(2, 'upload', 1, true);
|
||||
svc.record(1, 'write', 1, true);
|
||||
svc.record(1, 'read', 1, true);
|
||||
|
||||
const { entries } = svc.snapshot();
|
||||
expect(entries.map(e => `${e.nodeId}:${e.op}`)).toEqual([
|
||||
'1:read',
|
||||
'1:write',
|
||||
'2:upload',
|
||||
]);
|
||||
});
|
||||
});
|
||||
@@ -126,6 +126,81 @@ describe('GET /api/stacks/:stackName/files', () => {
|
||||
DatabaseService.getInstance().updateGlobalSetting('developer_mode', '0');
|
||||
});
|
||||
|
||||
it('emits a structured INFO line on a successful mutation (op/stack/path/bytes)', async () => {
|
||||
const logSpy = vi.spyOn(console, 'log').mockImplementation(() => undefined);
|
||||
|
||||
await request(app)
|
||||
.post(`/api/stacks/${STACK}/files/upload`)
|
||||
.set('Cookie', adminCookie)
|
||||
.attach('file', Buffer.from('observability payload'), 'observability-info.txt');
|
||||
|
||||
const mutateCall = logSpy.mock.calls.find(
|
||||
([prefix, details]) =>
|
||||
typeof prefix === 'string' &&
|
||||
prefix.includes('[Files] mutate') &&
|
||||
details &&
|
||||
typeof details === 'object' &&
|
||||
(details as { op?: unknown }).op === 'upload',
|
||||
);
|
||||
expect(mutateCall).toBeDefined();
|
||||
const details = mutateCall![1] as Record<string, unknown>;
|
||||
// sanitizeForLog coerces every value to a string before it lands in the log
|
||||
// payload, so bytes/mode/etc. arrive as their string representation. Operators
|
||||
// and log scrapers still see the right number; the test reflects that shape.
|
||||
expect(details.stack).toBe(STACK);
|
||||
expect(details.path).toBe('observability-info.txt');
|
||||
expect(typeof details.bytes).toBe('string');
|
||||
expect(Number(details.bytes)).toBeGreaterThan(0);
|
||||
|
||||
logSpy.mockRestore();
|
||||
});
|
||||
|
||||
it('records an error metric when an upload is rejected with FILE_EXISTS (overwrite confirm path)', async () => {
|
||||
const { FileExplorerMetricsService } = await import('../services/FileExplorerMetricsService');
|
||||
FileExplorerMetricsService.resetForTests();
|
||||
|
||||
// Seed an existing file so the second upload hits the FILE_EXISTS branch.
|
||||
await fs.writeFile(path.join(stacksDir, STACK, 'observability-conflict.txt'), 'pre-existing');
|
||||
const res = await request(app)
|
||||
.post(`/api/stacks/${STACK}/files/upload`)
|
||||
.set('Cookie', adminCookie)
|
||||
.attach('file', Buffer.from('replacement'), 'observability-conflict.txt');
|
||||
expect(res.status).toBe(409);
|
||||
expect(res.body.code).toBe('FILE_EXISTS');
|
||||
|
||||
const metricsRes = await request(app)
|
||||
.get('/api/file-explorer-metrics')
|
||||
.set('Cookie', adminCookie);
|
||||
const uploadEntry = (metricsRes.body.entries as Array<{ op: string; errorCount: number }>).find(
|
||||
e => e.op === 'upload',
|
||||
);
|
||||
expect(uploadEntry).toBeDefined();
|
||||
expect(uploadEntry!.errorCount).toBeGreaterThanOrEqual(1);
|
||||
});
|
||||
|
||||
it('records a metric on the upload route that surfaces in /api/file-explorer-metrics', async () => {
|
||||
const { FileExplorerMetricsService } = await import('../services/FileExplorerMetricsService');
|
||||
FileExplorerMetricsService.resetForTests();
|
||||
|
||||
await request(app)
|
||||
.post(`/api/stacks/${STACK}/files/upload`)
|
||||
.set('Cookie', adminCookie)
|
||||
.attach('file', Buffer.from('metrics payload'), 'observability-metrics.txt');
|
||||
|
||||
const metricsRes = await request(app)
|
||||
.get('/api/file-explorer-metrics')
|
||||
.set('Cookie', adminCookie);
|
||||
expect(metricsRes.status).toBe(200);
|
||||
const uploadEntry = (metricsRes.body.entries as Array<{ op: string; successCount: number }>).find(
|
||||
e => e.op === 'upload',
|
||||
);
|
||||
expect(uploadEntry).toBeDefined();
|
||||
expect(uploadEntry!.successCount).toBeGreaterThanOrEqual(1);
|
||||
const bytesEntry = (metricsRes.body.uploadBytesByNode as Array<{ totalBytes: number }>)[0];
|
||||
expect(bytesEntry).toBeDefined();
|
||||
expect(bytesEntry.totalBytes).toBeGreaterThan(0);
|
||||
});
|
||||
|
||||
it('returns 400 for an invalid stack name containing path traversal', async () => {
|
||||
const res = await request(app)
|
||||
.get('/api/stacks/../evil/files')
|
||||
@@ -314,6 +389,35 @@ describe('GET /api/stacks/:stackName/files/download', () => {
|
||||
expect(res.headers['content-disposition']).toMatch(/attachment/);
|
||||
expect(res.text).toContain('services');
|
||||
});
|
||||
|
||||
it('records the download metric exactly once per successful response', async () => {
|
||||
// The metric recorder is wired to both res.on("finish") and
|
||||
// res.on("close"), guarded by a flag so a single completion does not
|
||||
// double-fire. A regression that drops the flag would push successCount
|
||||
// to 2 for one download.
|
||||
const { FileExplorerMetricsService } = await import('../services/FileExplorerMetricsService');
|
||||
FileExplorerMetricsService.resetForTests();
|
||||
|
||||
const res = await request(app)
|
||||
.get(`/api/stacks/${STACK}/files/download`)
|
||||
.query({ path: 'compose.yaml' })
|
||||
.set('Cookie', adminCookie);
|
||||
expect(res.status).toBe(200);
|
||||
|
||||
// Allow the res.on('close') tail event to fire after the test's await.
|
||||
await new Promise<void>((r) => setTimeout(r, 50));
|
||||
|
||||
const metricsRes = await request(app)
|
||||
.get('/api/file-explorer-metrics')
|
||||
.set('Cookie', adminCookie);
|
||||
const downloadEntry = (metricsRes.body.entries as Array<{ op: string; count: number; successCount: number; errorCount: number }>).find(
|
||||
e => e.op === 'download',
|
||||
);
|
||||
expect(downloadEntry).toBeDefined();
|
||||
expect(downloadEntry!.count).toBe(1);
|
||||
expect(downloadEntry!.successCount).toBe(1);
|
||||
expect(downloadEntry!.errorCount).toBe(0);
|
||||
});
|
||||
});
|
||||
|
||||
// ── POST /:stackName/files/upload ─────────────────────────────────────────────
|
||||
|
||||
@@ -50,6 +50,7 @@ import { nodesRouter } from './routes/nodes';
|
||||
import { stacksRouter } from './routes/stacks';
|
||||
import { stackActivityRouter } from './routes/stackActivity';
|
||||
import { stackMetricsRouter } from './routes/stackMetrics';
|
||||
import { fileExplorerMetricsRouter } from './routes/fileExplorerMetrics';
|
||||
import { secretsRouter } from './routes/secrets';
|
||||
|
||||
// Suppress [DEP0060] DeprecationWarning emitted by http-proxy@1.18.1 which calls
|
||||
@@ -143,6 +144,7 @@ app.use('/api/nodes', nodesRouter);
|
||||
app.use('/api/stacks', stackActivityRouter);
|
||||
app.use('/api/stacks', stacksRouter);
|
||||
app.use('/api/stack-metrics', stackMetricsRouter);
|
||||
app.use('/api/file-explorer-metrics', fileExplorerMetricsRouter);
|
||||
|
||||
const { server, wss, pilotTunnelWss } = createServer(app);
|
||||
attachUpgrade(server, { wss, pilotTunnelWss });
|
||||
|
||||
@@ -0,0 +1,20 @@
|
||||
import { Router, type Request, type Response } from 'express';
|
||||
import { requireAdmin } from '../middleware/tierGates';
|
||||
import { FileExplorerMetricsService } from '../services/FileExplorerMetricsService';
|
||||
|
||||
export const fileExplorerMetricsRouter = Router();
|
||||
|
||||
/**
|
||||
* Admin-only snapshot of in-process stack file explorer metrics. No external
|
||||
* export: this endpoint exists so an operator debugging "why is the file
|
||||
* editor slow on this node?" can pull per-(nodeId, op) counts and latencies
|
||||
* without scrolling logs.
|
||||
*
|
||||
* Mounted at /api/file-explorer-metrics after the global authGate, so it
|
||||
* inherits the standard session/Bearer auth surface like every other authed
|
||||
* route.
|
||||
*/
|
||||
fileExplorerMetricsRouter.get('/', (req: Request, res: Response): void => {
|
||||
if (!requireAdmin(req, res)) return;
|
||||
res.json(FileExplorerMetricsService.getInstance().snapshot());
|
||||
});
|
||||
+227
-22
@@ -16,6 +16,7 @@ import { requirePaid, requireAdmin, effectiveTier } from '../middleware/tierGate
|
||||
import { NotificationService, type NotificationCategory } from '../services/NotificationService';
|
||||
import { StackOpLockService, type StackOpAction } from '../services/StackOpLockService';
|
||||
import { StackOpMetricsService, type StackOpAction as StackMetricAction } from '../services/StackOpMetricsService';
|
||||
import { FileExplorerMetricsService, type FileExplorerOp } from '../services/FileExplorerMetricsService';
|
||||
import { isValidGitSourcePath, isValidStackName, isValidServiceName, isPathWithinBase, isValidRelativeStackPath } from '../utils/validation';
|
||||
import { getErrorMessage } from '../utils/errors';
|
||||
import { isDebugEnabled } from '../utils/debug';
|
||||
@@ -1371,6 +1372,46 @@ function logFileDiag(message: string, details: Record<string, unknown>): void {
|
||||
console.debug(`[Files:diag] ${message}`, cleaned);
|
||||
}
|
||||
|
||||
/**
|
||||
* Records one file-explorer op into the in-process metrics service. Always
|
||||
* called once per request from the route layer, regardless of success or
|
||||
* failure, so the counts in the `/api/file-explorer-metrics` snapshot stay
|
||||
* in step with the INFO log line emitted in the same handler.
|
||||
*/
|
||||
function recordFileOp(nodeId: number, op: FileExplorerOp, startedAt: number, ok: boolean): void {
|
||||
FileExplorerMetricsService.getInstance().record(nodeId, op, Date.now() - startedAt, ok);
|
||||
}
|
||||
|
||||
/**
|
||||
* Emits the warn log, records the metric, and sends the JSON response for a
|
||||
* mutation rejected with a known error code (e.g. DIR_EXISTS, FILE_EXISTS,
|
||||
* PRECONDITION_FAILED). Centralizes the three-step shape so a future rejection
|
||||
* site cannot skip the metric and drift from the log.
|
||||
*/
|
||||
function rejectFileMutation(
|
||||
req: Request,
|
||||
res: Response,
|
||||
args: {
|
||||
op: FileExplorerOp;
|
||||
stack: string;
|
||||
path: string;
|
||||
startedAt: number;
|
||||
status: number;
|
||||
code: string;
|
||||
body: Record<string, unknown>;
|
||||
},
|
||||
): Response {
|
||||
logFileOperation('warn', 'mutate rejected', {
|
||||
nodeId: req.nodeId,
|
||||
op: args.op,
|
||||
stack: args.stack,
|
||||
path: args.path,
|
||||
errorCode: args.code,
|
||||
});
|
||||
recordFileOp(req.nodeId, args.op, args.startedAt, false);
|
||||
return res.status(args.status).json({ ...args.body, code: args.code });
|
||||
}
|
||||
|
||||
function isSafeUploadFilename(rawName: string): boolean {
|
||||
if (!rawName || rawName === '.' || rawName === '..') return false;
|
||||
if (rawName.includes('\0') || rawName.includes('/') || rawName.includes('\\')) return false;
|
||||
@@ -1405,9 +1446,11 @@ stacksRouter.get('/:stackName/files', async (req: Request, res: Response) => {
|
||||
truncated: result.truncated,
|
||||
elapsedMs: Date.now() - startedAt,
|
||||
});
|
||||
recordFileOp(req.nodeId, 'list', startedAt, true);
|
||||
return res.json(result.entries);
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'list failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
recordFileOp(req.nodeId, 'list', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to list directory');
|
||||
}
|
||||
});
|
||||
@@ -1438,9 +1481,11 @@ stacksRouter.get('/:stackName/files/content', async (req: Request, res: Response
|
||||
size: result.size,
|
||||
elapsedMs: Date.now() - startedAt,
|
||||
});
|
||||
recordFileOp(req.nodeId, 'read', startedAt, true);
|
||||
return res.json(result);
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'read failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
recordFileOp(req.nodeId, 'read', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to read file');
|
||||
}
|
||||
});
|
||||
@@ -1462,29 +1507,69 @@ stacksRouter.get('/:stackName/files/download', async (req: Request, res: Respons
|
||||
const encodedFilename = encodeURIComponent(result.filename);
|
||||
const safeFilename = result.filename.replace(/[\\"]/g, '');
|
||||
res.setHeader('Content-Disposition', `attachment; filename="${safeFilename}"; filename*=UTF-8''${encodedFilename}`);
|
||||
// Stream-success and stream-failure both have to flow through a single
|
||||
// recorder so a mid-stream read error or a client disconnect doesn't get
|
||||
// counted as a successful download. The flag protects against
|
||||
// double-firing when both `finish` and `close` fire after a normal
|
||||
// completion.
|
||||
let downloadRecorded = false;
|
||||
const recordDownloadOnce = (ok: boolean): void => {
|
||||
if (downloadRecorded) return;
|
||||
downloadRecorded = true;
|
||||
recordFileOp(req.nodeId, 'download', startedAt, ok);
|
||||
};
|
||||
result.stream.on('error', (streamErr) => {
|
||||
console.error('[files] stream error:', sanitizeForLog(getErrorMessage(streamErr, 'unknown')));
|
||||
if (!res.headersSent) res.status(500).end();
|
||||
else res.destroy();
|
||||
recordDownloadOnce(false);
|
||||
});
|
||||
res.on('finish', () => recordDownloadOnce(true));
|
||||
res.on('close', () => recordDownloadOnce(false));
|
||||
req.on('close', () => result.stream.destroy());
|
||||
logFileDiag('download stream opened', { stackName, relPath, nodeId: req.nodeId, size: result.size, elapsedMs: Date.now() - startedAt });
|
||||
result.stream.pipe(res);
|
||||
return;
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'download failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
recordFileOp(req.nodeId, 'download', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to download file');
|
||||
}
|
||||
});
|
||||
|
||||
type UploadStartedReq = Request & { _fileUploadStartedAt?: number };
|
||||
|
||||
stacksRouter.post(
|
||||
'/:stackName/files/upload',
|
||||
(req: Request, res: Response, next: NextFunction) => {
|
||||
// Capture the time the upload entered the route so every downstream
|
||||
// metric reports the same latency window: the body-transfer +
|
||||
// parser-buffer time on success, plus the multer rejection branches
|
||||
// below. Reading a fresh Date.now() after multer would hide the
|
||||
// multipart upload's network and buffering cost from the histogram.
|
||||
const startedAt = Date.now();
|
||||
(req as UploadStartedReq)._fileUploadStartedAt = startedAt;
|
||||
upload.single('file')(req, res, (err) => {
|
||||
if (err && (err as multer.MulterError).code === 'LIMIT_FILE_SIZE') {
|
||||
logFileOperation('warn', 'mutate rejected', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'upload',
|
||||
stack: req.params.stackName,
|
||||
errorCode: 'TOO_LARGE',
|
||||
});
|
||||
recordFileOp(req.nodeId, 'upload', startedAt, false);
|
||||
return res.status(413).json({ error: 'File exceeds 25 MB limit', code: 'TOO_LARGE' });
|
||||
}
|
||||
if (err) return res.status(500).json({ error: 'Upload failed' });
|
||||
if (err) {
|
||||
logFileOperation('warn', 'upload failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'upload',
|
||||
stack: req.params.stackName,
|
||||
errorCode: 'MULTER_ERROR',
|
||||
});
|
||||
recordFileOp(req.nodeId, 'upload', startedAt, false);
|
||||
return res.status(500).json({ error: 'Upload failed' });
|
||||
}
|
||||
next();
|
||||
});
|
||||
},
|
||||
@@ -1504,30 +1589,66 @@ stacksRouter.post(
|
||||
}
|
||||
const targetRelPath = relPath ? `${relPath}/${originalName}` : originalName;
|
||||
const overwrite = String(req.query.overwrite) === '1';
|
||||
const startedAt = Date.now();
|
||||
// The multer wrapper stashed the route-entry timestamp on the request so
|
||||
// the success path and the rejection paths share one window. Fall back to
|
||||
// Date.now() defensively in case the wrapper was bypassed in a test.
|
||||
const startedAt = (req as UploadStartedReq)._fileUploadStartedAt ?? Date.now();
|
||||
logFileDiag('upload start', { stackName, relPath: targetRelPath, nodeId: req.nodeId, size: req.file.size, overwrite });
|
||||
try {
|
||||
const existing = await FileSystemService.getInstance(req.nodeId).pathKind(stackName, targetRelPath);
|
||||
if (existing === 'directory') {
|
||||
// A directory can never be replaced by an upload; surface a distinct code
|
||||
// so the UI does not offer a useless "Replace" button.
|
||||
return res.status(409).json({
|
||||
error: `A folder named ${originalName} already exists in this folder. Rename the upload or remove the folder first.`,
|
||||
return rejectFileMutation(req, res, {
|
||||
op: 'upload',
|
||||
stack: stackName,
|
||||
path: targetRelPath,
|
||||
startedAt,
|
||||
status: 409,
|
||||
code: 'DIR_EXISTS',
|
||||
body: {
|
||||
error: `A folder named ${originalName} already exists in this folder. Rename the upload or remove the folder first.`,
|
||||
},
|
||||
});
|
||||
}
|
||||
if (existing === 'file' && !overwrite) {
|
||||
return res.status(409).json({
|
||||
error: `${originalName} already exists in this folder. Confirm to replace.`,
|
||||
// Real FS work ran (pathKind) and the operator was rejected; surface
|
||||
// the conflict in metrics so a node with a hot overwrite-confirm
|
||||
// pattern shows up in the snapshot rather than disappearing.
|
||||
return rejectFileMutation(req, res, {
|
||||
op: 'upload',
|
||||
stack: stackName,
|
||||
path: targetRelPath,
|
||||
startedAt,
|
||||
status: 409,
|
||||
code: 'FILE_EXISTS',
|
||||
body: {
|
||||
error: `${originalName} already exists in this folder. Confirm to replace.`,
|
||||
},
|
||||
});
|
||||
}
|
||||
await FileSystemService.getInstance(req.nodeId).writeStackFileBuffer(stackName, targetRelPath, req.file.buffer);
|
||||
logFileOperation('info', 'upload complete', { nodeId: req.nodeId, size: req.file.size, overwrite });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'upload',
|
||||
stack: stackName,
|
||||
path: targetRelPath,
|
||||
bytes: req.file.size,
|
||||
overwrite,
|
||||
});
|
||||
logFileDiag('upload timing', { stackName, relPath: targetRelPath, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'upload', startedAt, true);
|
||||
FileExplorerMetricsService.getInstance().recordUploadBytes(req.nodeId, req.file.size);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'upload failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'upload failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'upload',
|
||||
stack: stackName,
|
||||
path: targetRelPath,
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'upload', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to upload file', { notFoundMessage: 'Target directory not found' });
|
||||
}
|
||||
},
|
||||
@@ -1558,20 +1679,44 @@ stacksRouter.put('/:stackName/files/content', async (req: Request, res: Response
|
||||
if (!result.ok) {
|
||||
// Stale ETag: surface the current content + mtime so the client can
|
||||
// show a "file changed elsewhere" diff and let the user reconcile.
|
||||
// Real FS work ran (the if-unchanged stat compare); record the
|
||||
// attempted-and-rejected write so operators chasing concurrent-edit
|
||||
// patterns can see them in the snapshot.
|
||||
res.setHeader('ETag', stackFileEtag(result.currentMtimeMs));
|
||||
return res.status(412).json({
|
||||
error: 'File has been modified since you last read it. Reload to see the current version.',
|
||||
return rejectFileMutation(req, res, {
|
||||
op: 'write',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
startedAt,
|
||||
status: 412,
|
||||
code: 'PRECONDITION_FAILED',
|
||||
currentMtimeMs: result.currentMtimeMs,
|
||||
currentContent: result.currentContent,
|
||||
body: {
|
||||
error: 'File has been modified since you last read it. Reload to see the current version.',
|
||||
currentMtimeMs: result.currentMtimeMs,
|
||||
currentContent: result.currentContent,
|
||||
},
|
||||
});
|
||||
}
|
||||
res.setHeader('ETag', stackFileEtag(result.mtimeMs));
|
||||
logFileOperation('info', 'write complete', { nodeId: req.nodeId });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'write',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
bytes: Buffer.byteLength(content, 'utf-8'),
|
||||
});
|
||||
logFileDiag('write timing', { stackName, relPath, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'write', startedAt, true);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'write failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'write failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'write',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'write', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to write file');
|
||||
}
|
||||
});
|
||||
@@ -1589,11 +1734,26 @@ stacksRouter.delete('/:stackName/files', async (req: Request, res: Response) =>
|
||||
logFileDiag('delete start', { stackName, relPath, recursive, nodeId: req.nodeId });
|
||||
try {
|
||||
await FileSystemService.getInstance(req.nodeId).deleteStackPath(stackName, relPath, recursive);
|
||||
logFileOperation('info', 'delete complete', { nodeId: req.nodeId, recursive });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'delete',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
recursive,
|
||||
});
|
||||
logFileDiag('delete timing', { stackName, relPath, recursive, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'delete', startedAt, true);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'delete failed', { nodeId: req.nodeId, recursive, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'delete failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'delete',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
recursive,
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'delete', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to delete path');
|
||||
}
|
||||
});
|
||||
@@ -1610,11 +1770,24 @@ stacksRouter.post('/:stackName/files/folder', async (req: Request, res: Response
|
||||
logFileDiag('mkdir start', { stackName, relPath, nodeId: req.nodeId });
|
||||
try {
|
||||
await FileSystemService.getInstance(req.nodeId).mkdirStackPath(stackName, relPath);
|
||||
logFileOperation('info', 'mkdir complete', { nodeId: req.nodeId });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'mkdir',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
});
|
||||
logFileDiag('mkdir timing', { stackName, relPath, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'mkdir', startedAt, true);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'mkdir failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'mkdir failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'mkdir',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'mkdir', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to create folder');
|
||||
}
|
||||
});
|
||||
@@ -1639,11 +1812,26 @@ stacksRouter.patch('/:stackName/files/rename', async (req: Request, res: Respons
|
||||
logFileDiag('rename start', { stackName, from, to, nodeId: req.nodeId });
|
||||
try {
|
||||
await FileSystemService.getInstance(req.nodeId).renameStackPath(stackName, from, to);
|
||||
logFileOperation('info', 'rename complete', { nodeId: req.nodeId });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'rename',
|
||||
stack: stackName,
|
||||
path: from,
|
||||
toPath: to,
|
||||
});
|
||||
logFileDiag('rename timing', { stackName, from, to, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'rename', startedAt, true);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'rename failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'rename failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'rename',
|
||||
stack: stackName,
|
||||
path: from,
|
||||
toPath: to,
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'rename', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to rename');
|
||||
}
|
||||
});
|
||||
@@ -1661,9 +1849,11 @@ stacksRouter.get('/:stackName/files/permissions', async (req: Request, res: Resp
|
||||
try {
|
||||
const result = await FileSystemService.getInstance(req.nodeId).getStackEntryMode(stackName, relPath);
|
||||
logFileDiag('permissions read complete', { stackName, relPath, nodeId: req.nodeId, mode: result.octal, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'permissionsRead', startedAt, true);
|
||||
return res.json(result);
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'permissions read failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
recordFileOp(req.nodeId, 'permissionsRead', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to read permissions');
|
||||
}
|
||||
});
|
||||
@@ -1684,11 +1874,26 @@ stacksRouter.put('/:stackName/files/permissions', async (req: Request, res: Resp
|
||||
logFileDiag('chmod start', { stackName, relPath, nodeId: req.nodeId, mode });
|
||||
try {
|
||||
await FileSystemService.getInstance(req.nodeId).chmodStackPath(stackName, relPath, mode);
|
||||
logFileOperation('info', 'chmod complete', { nodeId: req.nodeId, mode });
|
||||
logFileOperation('info', 'mutate', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'chmod',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
mode: mode.toString(8).padStart(3, '0'),
|
||||
});
|
||||
logFileDiag('chmod timing', { stackName, relPath, nodeId: req.nodeId, elapsedMs: Date.now() - startedAt });
|
||||
recordFileOp(req.nodeId, 'chmod', startedAt, true);
|
||||
return res.status(204).send();
|
||||
} catch (err: unknown) {
|
||||
logFileOperation('warn', 'chmod failed', { nodeId: req.nodeId, errorCode: fsErrorCode(err) });
|
||||
logFileOperation('warn', 'chmod failed', {
|
||||
nodeId: req.nodeId,
|
||||
op: 'chmod',
|
||||
stack: stackName,
|
||||
path: relPath,
|
||||
mode: mode.toString(8).padStart(3, '0'),
|
||||
errorCode: fsErrorCode(err),
|
||||
});
|
||||
recordFileOp(req.nodeId, 'chmod', startedAt, false);
|
||||
return sendFsError(res, err, 'Failed to set permissions');
|
||||
}
|
||||
});
|
||||
|
||||
@@ -0,0 +1,148 @@
|
||||
/**
|
||||
* 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;
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user