diff --git a/backend/src/__tests__/file-explorer-metrics-route.test.ts b/backend/src/__tests__/file-explorer-metrics-route.test.ts new file mode 100644 index 00000000..19bf2808 --- /dev/null +++ b/backend/src/__tests__/file-explorer-metrics-route.test.ts @@ -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 }, + ]); + }); +}); diff --git a/backend/src/__tests__/file-explorer-metrics-service.test.ts b/backend/src/__tests__/file-explorer-metrics-service.test.ts new file mode 100644 index 00000000..8c085b9f --- /dev/null +++ b/backend/src/__tests__/file-explorer-metrics-service.test.ts @@ -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', + ]); + }); +}); diff --git a/backend/src/__tests__/stack-files-routes.test.ts b/backend/src/__tests__/stack-files-routes.test.ts index fab1e93a..e5460bfc 100644 --- a/backend/src/__tests__/stack-files-routes.test.ts +++ b/backend/src/__tests__/stack-files-routes.test.ts @@ -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; + // 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((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 ───────────────────────────────────────────── diff --git a/backend/src/index.ts b/backend/src/index.ts index 2eddd417..b08642f1 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -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 }); diff --git a/backend/src/routes/fileExplorerMetrics.ts b/backend/src/routes/fileExplorerMetrics.ts new file mode 100644 index 00000000..68c53e78 --- /dev/null +++ b/backend/src/routes/fileExplorerMetrics.ts @@ -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()); +}); diff --git a/backend/src/routes/stacks.ts b/backend/src/routes/stacks.ts index a8b3ccf5..c6fe7497 100644 --- a/backend/src/routes/stacks.ts +++ b/backend/src/routes/stacks.ts @@ -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): 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; + }, +): 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'); } }); diff --git a/backend/src/services/FileExplorerMetricsService.ts b/backend/src/services/FileExplorerMetricsService.ts new file mode 100644 index 00000000..5a632f6d --- /dev/null +++ b/backend/src/services/FileExplorerMetricsService.ts @@ -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(); + private readonly uploadBytes = new Map(); + + 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; + } +}