fix(monitor): decouple janitor disk-usage check from 30s cycle (F-6) (#1164)

* fix(monitor): decouple janitor disk-usage check from 30s cycle (F-6)

`docker system df` (called by the MonitorService janitor check) can take
30+ seconds on Docker Desktop with many volumes. Running it on the 30s
evaluate cycle compounded with the per-container stats fan-out and pushed
the cycle to 140s+, blocking subsequent monitoring work.

This change:

- Moves the janitor disk-usage check into its own 15-minute cycle with
  a tight 8s timeout. A circuit breaker opens after 3 consecutive
  timeouts (60-minute cooldown) so a sick daemon stops pinning Dockerode
  sockets every tick. The first janitor tick is deferred 45 seconds past
  boot to avoid head-of-line collision with the initial monitor cycle's
  stats fan-out.
- Adds a paired 8s `withTimeout` wrap to the admin prune-estimate routes
  (`/api/system/prune/estimate` and the dry-run path of
  `/api/system/prune/system`) so a slow df does not hang the admin tab.
  Both routes respond 503 with code `docker_df_slow` on timeout.
- Factors `withTimeout` and `TimeoutError` into `utils/withTimeout.ts`
  so the route layer does not have to import from a service module.
- Adds 10 unit tests covering the decoupling guardrail, breaker
  open/close, cooldown, threshold gate, the 100 MB reclaimable floor,
  re-entrancy, recovery logging, non-timeout error handling, and the
  full timer-cleanup contract of `stop()`.
- Adds 4 integration tests for the prune routes covering the 503
  timeout response, the success path, and the non-timeout 5xx path.

* fix(fleet,monitor): extend F-6 timeout to fleet prune routes; close breaker-recovery log gap

Codex audit findings on PR #1164:

Major. The fleet routes that fan out prune-estimate work on local nodes
(`POST /api/fleet/labels/fleet-prune` dry-run path and
`POST /api/fleet/prune/estimate`) called `estimateSystemReclaim` without
a timeout, so a slow local Docker daemon could still hang the fleet
admin tab even though the system-maintenance routes were already
bounded. Wrap both call sites with the shared `withTimeout(..., 8s)`
and surface a "Docker daemon is busy" message via the per-target and
per-node error channels the routes already used for other failures.
The destructive (non-dry-run) prune path stays unwrapped because it
calls `pruneSystem` / `pruneManagedOnly`, not `df`.

Minor. The janitor circuit breaker zeroed `janitorConsecutiveTimeouts`
when it opened, so a successful call after a full breaker-open cooldown
slipped past the `if (counter > 0)` recovery-log branch and never
emitted `[Monitor] Janitor disk-usage check recovered`. The operator
observability signal was missing exactly when it mattered most.
Extend the predicate to also trip on `janitorBreakerUntil > 0` (which
stays set to its past timestamp after cooldown until the next success
clears it), so recovery logs symmetrically for both partial-failure
and post-breaker recovery paths. Added a dedicated test.

Three new integration tests cover the fleet routes (timeout, success,
and the estimate endpoint's per-node unreachable shape).
This commit is contained in:
Anso
2026-05-23 00:04:05 -04:00
committed by GitHub
parent da3e7adc30
commit a51547a158
7 changed files with 702 additions and 74 deletions
@@ -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<typeof DockerController.getInstance>);
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 });
});
});
+244 -1
View File
@@ -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<never> {
return new Promise<never>(() => { /* 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();
});
});
@@ -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<typeof FileSystemService.getInstance>);
}
function stubEstimate(impl: () => Promise<{ reclaimableBytes: number }>) {
vi.spyOn(DockerController, 'getInstance').mockReturnValue({
estimateSystemReclaim: vi.fn().mockImplementation(impl),
} as unknown as ReturnType<typeof DockerController.getInstance>);
}
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');
});
});