diff --git a/backend/src/__tests__/fleet-prune-df-timeout.test.ts b/backend/src/__tests__/fleet-prune-df-timeout.test.ts new file mode 100644 index 00000000..04d8f381 --- /dev/null +++ b/backend/src/__tests__/fleet-prune-df-timeout.test.ts @@ -0,0 +1,100 @@ +/** + * F-6 regression: fleet routes that call estimateSystemReclaim on local + * nodes must also bound the slow `docker system df` call (8s) and surface + * a recognizable timeout message to the operator, matching the + * /api/system/prune/estimate behavior. + * + * Covers: + * - POST /api/fleet/labels/fleet-prune with dryRun: true + * - POST /api/fleet/prune/estimate + * + * Uses real timers because supertest dispatches lazily and the in-route + * `withTimeout` setTimeout cannot be advanced via vi.useFakeTimers from + * outside the request lifecycle. + */ +import { describe, it, expect, beforeAll, afterAll, afterEach, vi } from 'vitest'; +import request from 'supertest'; +import jwt from 'jsonwebtoken'; +import { setupTestDb, cleanupTestDb, TEST_USERNAME, TEST_JWT_SECRET } from './helpers/setupTestDb'; + +let tmpDir: string; +let app: import('express').Express; +let authHeader: string; +let DockerController: typeof import('../services/DockerController').default; +let FileSystemService: typeof import('../services/FileSystemService').FileSystemService; +let activeBulkActions: typeof import('../routes/labels').activeBulkActions; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ app } = await import('../index')); + ({ default: DockerController } = await import('../services/DockerController')); + ({ FileSystemService } = await import('../services/FileSystemService')); + ({ activeBulkActions } = await import('../routes/labels')); + // 10-minute expiry survives the file even with two ~8s timeout tests. + const token = jwt.sign({ username: TEST_USERNAME }, TEST_JWT_SECRET, { expiresIn: '10m' }); + authHeader = `Bearer ${token}`; +}); + +afterAll(() => cleanupTestDb(tmpDir)); + +afterEach(() => { + vi.restoreAllMocks(); + activeBulkActions.clear(); +}); + +function stubLocalEstimate(impl: () => Promise<{ reclaimableBytes: number }>) { + vi.spyOn(DockerController, 'getInstance').mockReturnValue({ + estimateSystemReclaim: vi.fn().mockImplementation(impl), + estimateManagedReclaim: vi.fn().mockResolvedValue({ reclaimableBytes: 0 }), + } as unknown as ReturnType); + vi.spyOn(FileSystemService.prototype, 'getStacks').mockResolvedValue([]); +} + +describe('Fleet prune routes bound docker df at 8s on local nodes (F-6)', () => { + it('POST /api/fleet/labels/fleet-prune dry-run surfaces a busy-daemon error on local timeout', async () => { + stubLocalEstimate(() => new Promise(() => { /* never resolves */ })); + + const t0 = Date.now(); + const res = await request(app) + .post('/api/fleet/labels/fleet-prune') + .set('Authorization', authHeader) + .send({ targets: ['volumes'], scope: 'all', dryRun: true }); + const elapsed = Date.now() - t0; + + expect(res.status).toBe(200); + const local = res.body.results[0]; + expect(local.reachable).toBe(true); + expect(local.targets[0].success).toBe(false); + expect(local.targets[0].error).toMatch(/Docker daemon is busy/); + expect(elapsed).toBeGreaterThanOrEqual(7_500); + expect(elapsed).toBeLessThan(15_000); + }, 20_000); + + it('POST /api/fleet/prune/estimate marks the local node unreachable with a busy-daemon error on timeout', async () => { + stubLocalEstimate(() => new Promise(() => { /* never resolves */ })); + + const res = await request(app) + .post('/api/fleet/prune/estimate') + .set('Authorization', authHeader) + .send({ targets: ['volumes'], scope: 'all' }); + + expect(res.status).toBe(200); + expect(Array.isArray(res.body.perNode)).toBe(true); + const local = res.body.perNode[0]; + expect(local.reachable).toBe(false); + expect(local.error).toMatch(/Docker daemon is busy/); + }, 20_000); + + it('fleet-prune dry-run succeeds normally when estimateSystemReclaim resolves quickly', async () => { + stubLocalEstimate(() => Promise.resolve({ reclaimableBytes: 256 })); + + const res = await request(app) + .post('/api/fleet/labels/fleet-prune') + .set('Authorization', authHeader) + .send({ targets: ['volumes'], scope: 'all', dryRun: true }); + + expect(res.status).toBe(200); + const local = res.body.results[0]; + expect(local.targets[0]).toMatchObject({ target: 'volumes', success: true, reclaimedBytes: 256, dryRun: true }); + }); +}); diff --git a/backend/src/__tests__/monitor-service.test.ts b/backend/src/__tests__/monitor-service.test.ts index aefd9fd9..edaa6a9f 100644 --- a/backend/src/__tests__/monitor-service.test.ts +++ b/backend/src/__tests__/monitor-service.test.ts @@ -10,7 +10,7 @@ const { mockGetGlobalSettings, mockGetNodes, mockGetStackAlerts, mockAddContaine mockCleanupOldMetrics, mockCleanupOldNotifications, mockCleanupOldAuditLogs, mockUpdateStackAlertLastFired, mockGetSystemState, mockSetSystemState, mockGetRunningContainers, mockGetAllContainers, mockGetContainerStatsStream, - mockGetContainerRestartCount, + mockGetContainerRestartCount, mockGetDiskUsage, mockDispatchAlert, mockCurrentLoad, mockMem, mockFsSize, mockExecAsync, @@ -32,6 +32,10 @@ const { mockGetGlobalSettings, mockGetNodes, mockGetStackAlerts, mockAddContaine mockGetAllContainers: vi.fn().mockResolvedValue([]), mockGetContainerStatsStream: vi.fn().mockResolvedValue('{}'), mockGetContainerRestartCount: vi.fn().mockResolvedValue(0), + mockGetDiskUsage: vi.fn().mockResolvedValue({ + reclaimableImages: 0, reclaimableContainers: 0, reclaimableVolumes: 0, reclaimableBuildCache: 0, + reclaimableImageCount: 0, reclaimableContainerCount: 0, reclaimableVolumeCount: 0, reclaimableBuildCacheCount: 0, + }), mockDispatchAlert: vi.fn().mockResolvedValue(undefined), mockCurrentLoad: vi.fn().mockResolvedValue({ currentLoad: 10 }), mockMem: vi.fn().mockResolvedValue({ used: 4e9, total: 16e9 }), @@ -66,6 +70,7 @@ vi.mock('../services/DockerController', () => ({ getAllContainers: mockGetAllContainers, getContainerStatsStream: mockGetContainerStatsStream, getContainerRestartCount: mockGetContainerRestartCount, + getDiskUsage: mockGetDiskUsage, }), }, })); @@ -92,6 +97,15 @@ vi.mock('../services/NotificationService', () => ({ }, })); +vi.mock('../services/NodeRegistry', () => ({ + NodeRegistry: { + getInstance: () => ({ + getDefaultNodeId: () => 1, + getNode: () => ({ id: 1, name: 'local-test', type: 'local' }), + }), + }, +})); + vi.mock('systeminformation', () => ({ default: { currentLoad: (...args: unknown[]) => mockCurrentLoad(...args), @@ -831,3 +845,232 @@ describe('MonitorService - parallel container processing', () => { expect(mockAddContainerMetric).toHaveBeenCalledTimes(containerCount); }); }); + +// ── Janitor cycle and circuit breaker (F-6) ──────────────────────────── + +describe('MonitorService - janitor cycle and circuit breaker', () => { + // Convenience: builds a never-settling promise used to simulate a hung df(). + function hangForever(): Promise { + return new Promise(() => { /* never resolves */ }); + } + + // Reclaimable payload large enough to cross a 0.5 GB janitor threshold. + const RECLAIMABLE_3GB = { + reclaimableImages: 3 * 1024 * 1024 * 1024, + reclaimableContainers: 0, + reclaimableVolumes: 0, + reclaimableBuildCache: 0, + reclaimableImageCount: 5, + reclaimableContainerCount: 0, + reclaimableVolumeCount: 0, + reclaimableBuildCacheCount: 0, + }; + + it('evaluate() does NOT call getDiskUsage (decoupling guardrail)', async () => { + // F-6 regression guard: the 30s monitor cycle must never call df(). + // If someone re-couples the janitor into evaluate(), this test fails. + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetNodes.mockReturnValue([]); + mockGetStackAlerts.mockReturnValue([]); + + const svc = MonitorService.getInstance(); + await (svc as any).evaluate(); + + expect(mockGetDiskUsage).not.toHaveBeenCalled(); + }); + + it('evaluate() completes promptly even when getDiskUsage would hang (F-6 regression)', async () => { + // If df() were still on the 30s cycle, hangForever would compound the + // cycle beyond its 25s threshold. Decoupled, evaluate() must return + // within a small wall-clock budget regardless. + mockGetDiskUsage.mockReturnValue(hangForever()); + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetNodes.mockReturnValue([]); + mockGetStackAlerts.mockReturnValue([]); + + const svc = MonitorService.getInstance(); + const t0 = Date.now(); + await (svc as any).evaluate(); + const elapsed = Date.now() - t0; + + expect(elapsed).toBeLessThan(2000); + expect(mockGetDiskUsage).not.toHaveBeenCalled(); + }); + + it('evaluateJanitor() honors isJanitorProcessing re-entrancy guard', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetDiskUsage.mockResolvedValue(RECLAIMABLE_3GB); + + const svc = MonitorService.getInstance(); + (svc as any).isJanitorProcessing = true; + + await (svc as any).evaluateJanitor(); + + // Second concurrent call must skip without touching settings or df. + expect(mockGetGlobalSettings).not.toHaveBeenCalled(); + expect(mockGetDiskUsage).not.toHaveBeenCalled(); + }); + + it('skips when docker_janitor_gb is unset, zero, or NaN', async () => { + const svc = MonitorService.getInstance(); + + mockGetGlobalSettings.mockReturnValue({}); + await (svc as any).evaluateJanitor(); + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0' }); + await (svc as any).evaluateJanitor(); + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: 'abc' }); + await (svc as any).evaluateJanitor(); + + expect(mockGetDiskUsage).not.toHaveBeenCalled(); + }); + + it('dispatches an alert when reclaimable exceeds the threshold', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetDiskUsage.mockResolvedValue(RECLAIMABLE_3GB); + mockGetSystemState.mockReturnValue('0'); // No prior alert; cooldown elapsed. + + const svc = MonitorService.getInstance(); + await (svc as any).evaluateJanitor(); + + expect(mockDispatchAlert).toHaveBeenCalledWith( + 'info', 'system', expect.stringContaining('3.0 GB'), { stackName: undefined }, + ); + }); + + it('does NOT alert when reclaimable is below MIN_RECLAIMABLE_GB even if threshold is aggressive', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.001' }); + mockGetDiskUsage.mockResolvedValue({ + ...RECLAIMABLE_3GB, + reclaimableImages: 50 * 1024 * 1024, // 50 MB, below the 100 MB floor + }); + mockGetSystemState.mockReturnValue('0'); + + const svc = MonitorService.getInstance(); + await (svc as any).evaluateJanitor(); + + expect(mockDispatchAlert).not.toHaveBeenCalled(); + }); + + it('opens the circuit breaker after JANITOR_BREAKER_THRESHOLD consecutive timeouts', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetDiskUsage.mockReturnValue(hangForever()); + const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + + const svc = MonitorService.getInstance(); + await (svc as any).evaluateJanitor(); + await (svc as any).evaluateJanitor(); + expect(warnSpy).not.toHaveBeenCalled(); // Threshold not yet reached. + await (svc as any).evaluateJanitor(); // Third timeout trips the breaker. + + const breakerLine = warnSpy.mock.calls.find( + (args) => typeof args[0] === 'string' && args[0].includes('circuit breaker opened'), + ); + expect(breakerLine).toBeDefined(); + expect((svc as any).janitorBreakerUntil).toBeGreaterThan(Date.now()); + // Counter resets on open so the cooldown is what gates the next attempt. + expect((svc as any).janitorConsecutiveTimeouts).toBe(0); + + warnSpy.mockRestore(); + }); + + it('respects the breaker cooldown; does not call getDiskUsage while open', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + + const svc = MonitorService.getInstance(); + (svc as any).janitorBreakerUntil = Date.now() + 60 * 60 * 1000; + + await (svc as any).evaluateJanitor(); + + expect(mockGetDiskUsage).not.toHaveBeenCalled(); + expect(mockGetGlobalSettings).not.toHaveBeenCalled(); + }); + + it('resets the timeout counter on a successful call after partial failures', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetDiskUsage + .mockReturnValueOnce(hangForever()) + .mockReturnValueOnce(hangForever()) + .mockResolvedValueOnce(RECLAIMABLE_3GB); + + const svc = MonitorService.getInstance(); + await (svc as any).evaluateJanitor(); + await (svc as any).evaluateJanitor(); + expect((svc as any).janitorConsecutiveTimeouts).toBe(2); + + const logSpy = vi.spyOn(console, 'log').mockImplementation(() => undefined); + await (svc as any).evaluateJanitor(); + + expect((svc as any).janitorConsecutiveTimeouts).toBe(0); + const recoveryLine = logSpy.mock.calls.find( + (args) => typeof args[0] === 'string' && args[0].includes('recovered'), + ); + expect(recoveryLine).toBeDefined(); + logSpy.mockRestore(); + }); + + it('logs recovery on the first successful call after a full breaker-open cooldown', async () => { + // After the breaker opens, the counter is zeroed; once the cooldown + // lapses, a successful call must still emit the recovered log so the + // operator observability story is symmetric with the partial-failure + // recovery path. + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + + const svc = MonitorService.getInstance(); + (svc as any).janitorBreakerUntil = Date.now() - 1; // cooldown just elapsed + (svc as any).janitorConsecutiveTimeouts = 0; // zeroed on open + mockGetDiskUsage.mockResolvedValue(RECLAIMABLE_3GB); + + const logSpy = vi.spyOn(console, 'log').mockImplementation(() => undefined); + await (svc as any).evaluateJanitor(); + + const recoveryLine = logSpy.mock.calls.find( + (args) => typeof args[0] === 'string' && args[0].includes('recovered'), + ); + expect(recoveryLine).toBeDefined(); + expect((svc as any).janitorBreakerUntil).toBe(0); + expect((svc as any).janitorConsecutiveTimeouts).toBe(0); + logSpy.mockRestore(); + }); + + it('does NOT advance the breaker counter on non-timeout errors', async () => { + mockGetGlobalSettings.mockReturnValue({ docker_janitor_gb: '0.5' }); + mockGetDiskUsage.mockRejectedValue(Object.assign(new Error('daemon unreachable'), { statusCode: 500 })); + const errSpy = vi.spyOn(console, 'error').mockImplementation(() => undefined); + + const svc = MonitorService.getInstance(); + await (svc as any).evaluateJanitor(); + await (svc as any).evaluateJanitor(); + await (svc as any).evaluateJanitor(); + await (svc as any).evaluateJanitor(); + + expect((svc as any).janitorConsecutiveTimeouts).toBe(0); + expect((svc as any).janitorBreakerUntil).toBe(0); + // The original support-grep line must still fire on every non-timeout error. + const janitorErrorLines = errSpy.mock.calls.filter( + (args) => typeof args[0] === 'string' && args[0].includes('Error checking docker janitor limits'), + ); + expect(janitorErrorLines.length).toBe(4); + + errSpy.mockRestore(); + }); + + it('stop() clears both intervals AND both deferred first-tick timeouts', () => { + // Without canceling the first-tick setTimeouts, stop() would let + // evaluate() / evaluateJanitor() fire on a service that the caller + // believes is dormant. The 5s and 45s windows are wider than typical + // graceful-shutdown budgets, so this matters. + const svc = MonitorService.getInstance(); + svc.start(); + expect((svc as any).intervalId).not.toBeNull(); + expect((svc as any).firstTickTimeoutId).not.toBeNull(); + expect((svc as any).janitorIntervalId).not.toBeNull(); + expect((svc as any).janitorFirstTickTimeoutId).not.toBeNull(); + + svc.stop(); + + expect((svc as any).intervalId).toBeNull(); + expect((svc as any).firstTickTimeoutId).toBeNull(); + expect((svc as any).janitorIntervalId).toBeNull(); + expect((svc as any).janitorFirstTickTimeoutId).toBeNull(); + }); +}); diff --git a/backend/src/__tests__/system-maintenance-prune.test.ts b/backend/src/__tests__/system-maintenance-prune.test.ts new file mode 100644 index 00000000..41ab77d3 --- /dev/null +++ b/backend/src/__tests__/system-maintenance-prune.test.ts @@ -0,0 +1,110 @@ +/** + * Route-level test for F-6: when `docker system df` is slow, the prune + * estimate endpoints must return 503 with code `docker_df_slow` instead + * of hanging the admin's tab. Mirrors the pattern from + * system-maintenance-self-protect.test.ts. + * + * Uses real timers because supertest dispatches lazily and vi.useFakeTimers + * does not compose cleanly with that pattern. Each timeout test waits the + * full 8s `withTimeout` budget, so two such tests add ~17s to the file. + */ +import { describe, it, expect, beforeAll, afterAll, afterEach, vi } from 'vitest'; +import request from 'supertest'; +import jwt from 'jsonwebtoken'; +import { setupTestDb, cleanupTestDb, TEST_USERNAME, TEST_JWT_SECRET } from './helpers/setupTestDb'; + +let tmpDir: string; +let app: import('express').Express; +let authHeader: string; +let DockerController: typeof import('../services/DockerController').default; +let FileSystemService: typeof import('../services/FileSystemService').FileSystemService; + +beforeAll(async () => { + tmpDir = await setupTestDb(); + ({ app } = await import('../index')); + ({ default: DockerController } = await import('../services/DockerController')); + ({ FileSystemService } = await import('../services/FileSystemService')); + // 10-minute expiry survives the full file even when two timeout tests + // burn ~8.5s each in real-timer mode. + const token = jwt.sign({ username: TEST_USERNAME }, TEST_JWT_SECRET, { expiresIn: '10m' }); + authHeader = `Bearer ${token}`; +}); + +afterAll(() => cleanupTestDb(tmpDir)); + +afterEach(() => { + vi.restoreAllMocks(); +}); + +function stubFsStacks() { + vi.spyOn(FileSystemService, 'getInstance').mockReturnValue({ + getStacks: vi.fn().mockResolvedValue([]), + } as unknown as ReturnType); +} + +function stubEstimate(impl: () => Promise<{ reclaimableBytes: number }>) { + vi.spyOn(DockerController, 'getInstance').mockReturnValue({ + estimateSystemReclaim: vi.fn().mockImplementation(impl), + } as unknown as ReturnType); +} + +describe('Prune estimate endpoints return 503 on slow docker df (F-6)', () => { + it('POST /api/system/prune/estimate returns 503 docker_df_slow when estimateSystemReclaim never settles', async () => { + stubFsStacks(); + stubEstimate(() => new Promise(() => { /* never resolves */ })); + + const t0 = Date.now(); + const res = await request(app) + .post('/api/system/prune/estimate') + .set('Authorization', authHeader) + .send({ target: 'volumes', scope: 'all' }); + const elapsed = Date.now() - t0; + + expect(res.status).toBe(503); + expect(res.body.code).toBe('docker_df_slow'); + expect(res.body.error).toMatch(/Docker daemon is busy/); + // Confirm the timeout actually fired (~8s), not an unrelated early + // 5xx that happened to look right. + expect(elapsed).toBeGreaterThanOrEqual(7_500); + expect(elapsed).toBeLessThan(15_000); + }, 20_000); + + it('POST /api/system/prune/system dry-run returns 503 docker_df_slow when estimateSystemReclaim never settles', async () => { + stubFsStacks(); + stubEstimate(() => new Promise(() => { /* never resolves */ })); + + const res = await request(app) + .post('/api/system/prune/system') + .set('Authorization', authHeader) + .send({ target: 'volumes', scope: 'all', dryRun: true }); + + expect(res.status).toBe(503); + expect(res.body.code).toBe('docker_df_slow'); + }, 20_000); + + it('estimate route succeeds normally when estimateSystemReclaim resolves quickly', async () => { + stubFsStacks(); + stubEstimate(() => Promise.resolve({ reclaimableBytes: 42 })); + + const res = await request(app) + .post('/api/system/prune/estimate') + .set('Authorization', authHeader) + .send({ target: 'volumes', scope: 'all' }); + + expect(res.status).toBe(200); + expect(res.body.reclaimableBytes).toBe(42); + }); + + it('estimate route returns 5xx (not 503 docker_df_slow) on unrelated daemon error', async () => { + stubFsStacks(); + stubEstimate(() => Promise.reject(new Error('daemon unreachable'))); + + const res = await request(app) + .post('/api/system/prune/estimate') + .set('Authorization', authHeader) + .send({ target: 'volumes', scope: 'all' }); + + expect(res.status).toBe(500); + expect(res.body.code).not.toBe('docker_df_slow'); + }); +}); diff --git a/backend/src/routes/fleet.ts b/backend/src/routes/fleet.ts index de69036d..9714f8f7 100644 --- a/backend/src/routes/fleet.ts +++ b/backend/src/routes/fleet.ts @@ -23,6 +23,11 @@ import { isValidStackName } from '../utils/validation'; import { isDebugEnabled } from '../utils/debug'; import { getErrorMessage } from '../utils/errors'; import { parseIntParam } from '../utils/parseIntParam'; +import { withTimeout, TimeoutError } from '../utils/withTimeout'; + +// Mirror the system-maintenance route timeout so fleet's local-node prune +// paths cap the slow `docker system df` call at the same 8s budget (F-6). +const FLEET_DF_TIMEOUT_MS = 8_000; import { POLICY_SEVERITIES } from '../utils/severity'; import { sanitizeForLog } from '../utils/safeLog'; import { formatNoTargetError } from '../utils/remoteTarget'; @@ -1197,9 +1202,17 @@ fleetRouter.post('/labels/fleet-prune', authMiddleware, async (req: Request, res for (const target of targets) { try { if (isDryRun) { + // estimateSystemReclaim hits `docker system df`; bound it + // so a slow local daemon doesn't hang the fleet admin tab + // (F-6). estimateManagedReclaim is fast (no df) and stays + // unwrapped. const estimate = scope === 'managed' ? await dockerController.estimateManagedReclaim(target, knownStacks) - : await dockerController.estimateSystemReclaim(target, knownStacks); + : await withTimeout( + dockerController.estimateSystemReclaim(target, knownStacks), + FLEET_DF_TIMEOUT_MS, + 'docker disk usage', + ); targetResults.push({ target, success: true, reclaimedBytes: estimate.reclaimableBytes, dryRun: true }); continue; } @@ -1209,7 +1222,10 @@ fleetRouter.post('/labels/fleet-prune', authMiddleware, async (req: Request, res targetResults.push({ target, success: true, reclaimedBytes: result.reclaimedBytes }); if (result.reclaimedBytes > 0 || result.success) anySuccess = true; } catch (err) { - targetResults.push({ target, success: false, reclaimedBytes: 0, error: getErrorMessage(err, 'Prune failed') }); + const error = err instanceof TimeoutError + ? 'Docker daemon is busy. Please try again in a moment.' + : getErrorMessage(err, 'Prune failed'); + targetResults.push({ target, success: false, reclaimedBytes: 0, error }); } } if (anySuccess && !isDryRun) invalidateNodeCaches(node.id); @@ -1370,16 +1386,24 @@ fleetRouter.post('/prune/estimate', authMiddleware, async (req: Request, res: Re const dockerController = DockerController.getInstance(node.id); let nodeBytes = 0; for (const target of targets) { + // estimateSystemReclaim hits `docker system df`; bound it so a + // slow local daemon doesn't hang the fleet estimate (F-6). const result = scope === 'managed' ? await dockerController.estimateManagedReclaim(target, knownStacks) - : await dockerController.estimateSystemReclaim(target, knownStacks); + : await withTimeout( + dockerController.estimateSystemReclaim(target, knownStacks), + FLEET_DF_TIMEOUT_MS, + 'docker disk usage', + ); nodeBytes += result.reclaimableBytes; } return { nodeId: node.id, nodeName: node.name, reclaimableBytes: nodeBytes, reachable: true }; } catch (err) { + const error = err instanceof TimeoutError + ? 'Docker daemon is busy. Please try again in a moment.' + : getErrorMessage(err, 'Failed to estimate locally'); return { - nodeId: node.id, nodeName: node.name, reclaimableBytes: 0, reachable: false, - error: getErrorMessage(err, 'Failed to estimate locally'), + nodeId: node.id, nodeName: node.name, reclaimableBytes: 0, reachable: false, error, }; } } diff --git a/backend/src/routes/systemMaintenance.ts b/backend/src/routes/systemMaintenance.ts index c4b0d26e..e12c7cbe 100644 --- a/backend/src/routes/systemMaintenance.ts +++ b/backend/src/routes/systemMaintenance.ts @@ -8,6 +8,20 @@ import { isValidDockerResourceId, isValidCidr, isValidIPv4 } from '../utils/vali import { isDebugEnabled } from '../utils/debug'; import { getErrorMessage } from '../utils/errors'; import { sanitizeForLog } from '../utils/safeLog'; +import { withTimeout, TimeoutError } from '../utils/withTimeout'; + +// `docker system df` (the call backing estimateSystemReclaim) can take 30+ +// seconds on Docker Desktop with many volumes; 8s matches the MonitorService +// janitor timeout so the daemon never has more than ~16s of concurrent +// pressure from Sencho's own paths even when prune and janitor collide. +const PRUNE_ESTIMATE_TIMEOUT_MS = 8_000; + +function respondDfSlow(res: Response): Response { + return res.status(503).json({ + error: 'Docker daemon is busy. Please try again in a moment.', + code: 'docker_df_slow', + }); +} export const systemMaintenanceRouter = Router(); @@ -95,9 +109,15 @@ systemMaintenanceRouter.post('/prune/system', async (req: Request, res: Response knownStacks, ); } else { - estimate = await dockerController.estimateSystemReclaim( - target as 'containers' | 'images' | 'networks' | 'volumes', - knownStacks, + // estimateSystemReclaim calls `docker system df`; bound it so a slow + // daemon doesn't hang the admin's tab (F-6). + estimate = await withTimeout( + dockerController.estimateSystemReclaim( + target as 'containers' | 'images' | 'networks' | 'volumes', + knownStacks, + ), + PRUNE_ESTIMATE_TIMEOUT_MS, + 'docker disk usage', ); } res.json({ message: 'Dry run', success: true, dryRun: true, reclaimedBytes: estimate.reclaimableBytes }); @@ -122,6 +142,10 @@ systemMaintenanceRouter.post('/prune/system', async (req: Request, res: Response } res.json({ message: 'Prune completed', ...result }); } catch (error: unknown) { + if (error instanceof TimeoutError) { + console.warn('System prune: docker disk usage timed out'); + return respondDfSlow(res); + } console.error('System prune error:', error); res.status(500).json({ error: 'System prune failed' }); } @@ -150,13 +174,23 @@ systemMaintenanceRouter.post('/prune/estimate', async (req: Request, res: Respon knownStacks, ); } else { - result = await dockerController.estimateSystemReclaim( - target as 'containers' | 'images' | 'networks' | 'volumes', - knownStacks, + // estimateSystemReclaim calls `docker system df`; bound it so a slow + // daemon doesn't hang the admin's tab (F-6). + result = await withTimeout( + dockerController.estimateSystemReclaim( + target as 'containers' | 'images' | 'networks' | 'volumes', + knownStacks, + ), + PRUNE_ESTIMATE_TIMEOUT_MS, + 'docker disk usage', ); } res.json({ reclaimableBytes: result.reclaimableBytes }); } catch (error: unknown) { + if (error instanceof TimeoutError) { + console.warn('Prune estimate: docker disk usage timed out'); + return respondDfSlow(res); + } console.error('Prune estimate error:', error); res.status(500).json({ error: 'Failed to estimate reclaimable bytes' }); } diff --git a/backend/src/services/MonitorService.ts b/backend/src/services/MonitorService.ts index 3a336917..bb6d87d3 100644 --- a/backend/src/services/MonitorService.ts +++ b/backend/src/services/MonitorService.ts @@ -7,6 +7,7 @@ import { NotificationService } from './NotificationService'; import { isValidVersion, getSenchoVersion } from './CapabilityRegistry'; import { getLatestVersion } from '../utils/version-check'; import { isDebugEnabled } from '../utils/debug'; +import { withTimeout, TimeoutError } from '../utils/withTimeout'; const getMetricDetails = (metric: string): { name: string, unit: string } => { switch (metric) { @@ -60,25 +61,17 @@ const HOST_ALERT_KEYS = { const STATS_TIMEOUT_MS = 10_000; const FLOAT_EQ_EPSILON = 0.01; -class TimeoutError extends Error { - constructor(label: string, ms: number) { - super(`Timeout: ${label} after ${ms}ms`); - this.name = 'TimeoutError'; - } -} - -function withTimeout(promise: Promise, ms: number, label: string): Promise { - // Note: JavaScript Promise.race does not cancel the losing promise. - // A timed-out Docker API or systeminformation call continues in the - // background until it resolves or the process exits. True cancellation - // requires AbortController plumbing through DockerController and - // systeminformation, which is a structural limitation of the codebase. - let timer: NodeJS.Timeout | undefined; - const timeout = new Promise((_, reject) => { - timer = setTimeout(() => reject(new TimeoutError(label, ms)), ms); - }); - return Promise.race([promise, timeout]).finally(() => clearTimeout(timer)); -} +// Janitor cadence and circuit-breaker. The disk-usage call (`docker system df`) +// can take 30+ seconds on Docker Desktop Windows when the daemon has many +// volumes; running it on the 30s evaluate cycle compounded with stats fan-out +// produced 140s+ stalls (F-6). Decoupling onto a slow cadence + tight timeout +// keeps the monitor cycle bounded and prevents the cycle from re-entering on +// a sick daemon. +const JANITOR_INTERVAL_MS = 15 * 60 * 1000; +const JANITOR_TIMEOUT_MS = 8_000; +const JANITOR_BREAKER_THRESHOLD = 3; +const JANITOR_BREAKER_COOLDOWN_MS = 60 * 60 * 1000; +const JANITOR_FIRST_TICK_DELAY_MS = 45_000; // Cap on simultaneous Docker socket requests when fanning out per-container // work. Mirrors the implicit safety profile of updateGlobalDockerNetwork in @@ -117,7 +110,19 @@ async function runWithConcurrency( export class MonitorService { private static instance: MonitorService; private intervalId: NodeJS.Timeout | null = null; + private firstTickTimeoutId: NodeJS.Timeout | null = null; + private janitorIntervalId: NodeJS.Timeout | null = null; + private janitorFirstTickTimeoutId: NodeJS.Timeout | null = null; private isProcessing = false; + private isJanitorProcessing = false; + + // Circuit-breaker state for the janitor disk-usage check. When + // getDiskUsage() times out JANITOR_BREAKER_THRESHOLD times in a row the + // breaker opens for JANITOR_BREAKER_COOLDOWN_MS so a sick daemon stops + // pinning Dockerode sockets every cycle. Counter resets on success or + // when the cooldown elapses. + private janitorConsecutiveTimeouts = 0; + private janitorBreakerUntil = 0; // Track the duration a specific stack alert rule has been in breach state // key: rule_id, value: AlertState @@ -155,23 +160,43 @@ export class MonitorService { public start() { if (this.intervalId) return; - if (isDebugEnabled()) console.log('[Monitor:diag] Starting evaluation loop (30s interval)'); + if (isDebugEnabled()) console.log('[Monitor:diag] Starting evaluation loop (30s interval) + janitor loop (15m interval)'); - // Run every 30 seconds + // 30s monitor cycle: host stats, container stats, version check. + // Does NOT include the janitor disk-usage check (F-6); that runs on + // its own slow cadence so a hung df() cannot compound the cycle. this.intervalId = setInterval(() => { this.evaluate(); }, 30000); + this.firstTickTimeoutId = setTimeout(() => this.evaluate(), 5000); - // Run an initial evaluation slightly after boot - setTimeout(() => this.evaluate(), 5000); + // 15m janitor cycle: disk-usage check with tight timeout + breaker. + // First tick is deferred past the initial monitor tick's stats + // fan-out so the two don't share daemon head-of-line latency. + this.janitorIntervalId = setInterval(() => { + this.evaluateJanitor(); + }, JANITOR_INTERVAL_MS); + this.janitorFirstTickTimeoutId = setTimeout(() => this.evaluateJanitor(), JANITOR_FIRST_TICK_DELAY_MS); } public stop() { if (this.intervalId) { clearInterval(this.intervalId); this.intervalId = null; - if (isDebugEnabled()) console.log('[Monitor:diag] Evaluation loop stopped'); } + if (this.firstTickTimeoutId) { + clearTimeout(this.firstTickTimeoutId); + this.firstTickTimeoutId = null; + } + if (this.janitorIntervalId) { + clearInterval(this.janitorIntervalId); + this.janitorIntervalId = null; + } + if (this.janitorFirstTickTimeoutId) { + clearTimeout(this.janitorFirstTickTimeoutId); + this.janitorFirstTickTimeoutId = null; + } + if (isDebugEnabled()) console.log('[Monitor:diag] Evaluation + janitor loops stopped'); } private async evaluate() { @@ -241,49 +266,114 @@ export class MonitorService { // DockerEventService: event-driven, causal, distinguishes // intentional stops from real crashes, detects OOM kills. - // 3. Docker Janitor Check - try { - const janitorLimitGb = parseFloat(settings['docker_janitor_gb']); - if (!isNaN(janitorLimitGb) && janitorLimitGb > 0) { - // Use the Docker Engine API directly via dockerode. The previous - // shell-out parsed `docker system df --format "{{json .}}"` and - // walked the human-readable "1.196GB" Reclaimable strings with - // a regex; the API returns raw byte counts and saves a fork - // every monitor tick (default 30 s). - const usage = await withTimeout( - DockerController.getInstance().getDiskUsage(), - STATS_TIMEOUT_MS, - 'docker disk usage', - ); - const totalReclaimableBytes = - usage.reclaimableImages + - usage.reclaimableContainers + - usage.reclaimableVolumes + - usage.reclaimableBuildCache; - - const reclaimGb = totalReclaimableBytes / (1024 * 1024 * 1024); - const JANITOR_COOLDOWN_MS = 24 * 60 * 60 * 1000; // 24 hours - // Sanity floor: never alert on near-empty hosts even if the user - // configured an aggressive threshold like 0.001 GB. 100 MB is the - // smallest waste worth interrupting an operator over. - const MIN_RECLAIMABLE_GB = 0.1; - - if (reclaimGb >= janitorLimitGb && reclaimGb >= MIN_RECLAIMABLE_GB) { - const registry = NodeRegistry.getInstance(); - const localNode = registry.getNode(registry.getDefaultNodeId()); - const nodeLabel = localNode?.name ?? 'this node'; - await this.dispatchWithCooldown(HOST_ALERT_KEYS.janitor, JANITOR_COOLDOWN_MS, 'info', 'system', - `Node "${nodeLabel}" has accumulated ${reclaimGb.toFixed(1)} GB of unused Docker data. Consider using the Janitor tool.`); - } - } - } catch (e) { - console.error('Error checking docker janitor limits', e); - } + // 3. (Decoupled) Docker janitor disk-usage check runs on its own + // slow cadence in evaluateJanitor(); see start() and F-6. // 4. Sencho version update check (runs once per VERSION_CHECK_INTERVAL_MS) await this.checkSenchoVersion(); } + /** + * Slow-cadence janitor disk-usage check, decoupled from the 30s monitor + * cycle (F-6). A hung `docker system df` would otherwise compound with + * the per-container stats fan-out and produce 140s+ stalls. + * + * Failure handling: + * - TimeoutError increments a counter; at JANITOR_BREAKER_THRESHOLD the + * breaker opens for JANITOR_BREAKER_COOLDOWN_MS, after which the + * counter resets and the next tick attempts again. + * - Other errors (daemon unreachable, parse errors) are logged but do + * not advance the breaker, because they are not the failure mode the + * breaker exists to mitigate. + * - Re-entrancy is guarded; this matters because the 8s timeout still + * may leave the previous in-flight `df()` resolving in the background. + */ + private async evaluateJanitor(): Promise { + if (this.isJanitorProcessing) return; + + if (Date.now() < this.janitorBreakerUntil) { + if (isDebugEnabled()) { + const remainingMin = Math.round((this.janitorBreakerUntil - Date.now()) / 60000); + console.debug(`[Monitor:diag] Janitor breaker open; next attempt in ~${remainingMin}m`); + } + return; + } + + this.isJanitorProcessing = true; + try { + const db = DatabaseService.getInstance(); + const settings = db.getGlobalSettings(); + const janitorLimitGb = parseFloat(settings['docker_janitor_gb']); + if (isNaN(janitorLimitGb) || janitorLimitGb <= 0) return; + + let usage: Awaited>; + try { + usage = await withTimeout( + DockerController.getInstance().getDiskUsage(), + JANITOR_TIMEOUT_MS, + 'docker disk usage', + ); + } catch (e) { + if (e instanceof TimeoutError) { + this.janitorConsecutiveTimeouts += 1; + if (this.janitorConsecutiveTimeouts >= JANITOR_BREAKER_THRESHOLD) { + this.janitorBreakerUntil = Date.now() + JANITOR_BREAKER_COOLDOWN_MS; + const cooldownMin = Math.round(JANITOR_BREAKER_COOLDOWN_MS / 60000); + console.warn( + `[Monitor] Janitor disk-usage check circuit breaker opened after ${this.janitorConsecutiveTimeouts} consecutive timeouts (next attempt in ${cooldownMin}m)`, + ); + this.janitorConsecutiveTimeouts = 0; + } else if (isDebugEnabled()) { + console.debug(`[Monitor:diag] Janitor disk-usage timeout ${this.janitorConsecutiveTimeouts}/${JANITOR_BREAKER_THRESHOLD}`); + } + return; + } + console.error('Error checking docker janitor limits', e); + return; + } + + // Recovery covers both partial-failure recovery (counter > 0, + // breaker still closed) and post-cooldown recovery (counter + // zeroed on open, breaker now elapsed). janitorBreakerUntil + // remains set to its past timestamp until the next success + // clears it; that flag is what distinguishes "always healthy" + // from "was sick, now recovered" once the cooldown has passed. + if (this.janitorConsecutiveTimeouts > 0 || this.janitorBreakerUntil > 0) { + console.log('[Monitor] Janitor disk-usage check recovered'); + this.janitorConsecutiveTimeouts = 0; + this.janitorBreakerUntil = 0; + } + + const totalReclaimableBytes = + usage.reclaimableImages + + usage.reclaimableContainers + + usage.reclaimableVolumes + + usage.reclaimableBuildCache; + + const reclaimGb = totalReclaimableBytes / (1024 * 1024 * 1024); + const JANITOR_COOLDOWN_MS = 24 * 60 * 60 * 1000; // 24h between repeat alerts + // Sanity floor: never alert on near-empty hosts even if the user + // configured an aggressive threshold like 0.001 GB. 100 MB is the + // smallest waste worth interrupting an operator over. + const MIN_RECLAIMABLE_GB = 0.1; + + if (reclaimGb >= janitorLimitGb && reclaimGb >= MIN_RECLAIMABLE_GB) { + const registry = NodeRegistry.getInstance(); + const localNode = registry.getNode(registry.getDefaultNodeId()); + const nodeLabel = localNode?.name ?? 'this node'; + await this.dispatchWithCooldown( + HOST_ALERT_KEYS.janitor, + JANITOR_COOLDOWN_MS, + 'info', + 'system', + `Node "${nodeLabel}" has accumulated ${reclaimGb.toFixed(1)} GB of unused Docker data. Consider using the Janitor tool.`, + ); + } + } finally { + this.isJanitorProcessing = false; + } + } + /** * Check GitHub/Docker Hub for a newer Sencho release and dispatch a * one-shot notification. Uses getLatestVersion() which wraps CacheService diff --git a/backend/src/utils/withTimeout.ts b/backend/src/utils/withTimeout.ts new file mode 100644 index 00000000..8797ab63 --- /dev/null +++ b/backend/src/utils/withTimeout.ts @@ -0,0 +1,27 @@ +/** + * Bounded-wait wrapper for promises that may never settle. + * + * Promise.race does not cancel the losing promise. A timed-out Docker API or + * systeminformation call continues running in the background until it + * resolves or the process exits. True cancellation would require + * AbortController plumbing through every caller (DockerController, dockerode, + * systeminformation), which is a structural limitation of the codebase. + * + * The trade-off is acceptable for monitor cycles and admin request handlers: + * the caller gets bounded latency, and the orphan promise carries no + * observable side effects once the timeout fires. + */ +export class TimeoutError extends Error { + constructor(label: string, ms: number) { + super(`Timeout: ${label} after ${ms}ms`); + this.name = 'TimeoutError'; + } +} + +export function withTimeout(promise: Promise, ms: number, label: string): Promise { + let timer: NodeJS.Timeout | undefined; + const timeout = new Promise((_, reject) => { + timer = setTimeout(() => reject(new TimeoutError(label, ms)), ms); + }); + return Promise.race([promise, timeout]).finally(() => clearTimeout(timer)); +}