Skip to content

Commit efc0055

Browse files
authored
fix: cache lifecycle can lose or leak state on build failure (#94)
* fix: cache lifecycle can lose or leak state on build failure Four reliability gaps in the move-based caching and retained-workspace locking, all variants of the same root cause: a cleanup step that only runs on the success path, or a staleness check with no liveness signal. - runLocalBuild() called afterLocalBuild() (which moves a localCacheMode=move-directory cache back to the cache root) only when setup/build returned normally. A thrown error skipped it entirely, so a cache already moved out of the cache root by beforeLocalBuild() was lost with no surviving copy anywhere. Now wrapped in try/finally, with the afterLocalBuild call itself guarded so a cache-save failure can't mask the original build error. - Orchestrator.runWithProvider() released a retained-workspace lock only in the success path. IsWorkspaceLocked() has no TTL, so a build that threw before reaching that line leaked the lock permanently, shrinking the retained-workspace pool by one on every crash. Now also released in the failure path (idempotent, so this is safe regardless of whether the success path already ran). - The background-save lock (.game-ci-cache-save.lock) was only checked reactively, when a later save/restore happened to target the same cache key. A process killed mid-save left its lock in place indefinitely for any cache key a run doesn't revisit. LocalCacheService.sweepStaleLocks() proactively sweeps every cache-key directory under the cache root at the start of a build, treating a lock as stale when its recorded PID is no longer alive. - ChildWorkspaceService.cleanStaleWorkspaces() existed and was tested but was never wired into plugin-lifecycle.ts, so cached child workspaces accumulated forever. Wired into afterLocalBuild, reusing the existing cacheRetentionDays setting rather than adding a new one. * chore: rebuild plugins/unity dist to include the runLocalBuild try/finally fix CI's dist-drift check caught this - src/unity-builder/index.ts was updated but dist/unity-builder/index.js wasn't rebuilt to match. * fix: harden cache cleanup and middleware validation
1 parent 6fd266c commit efc0055

10 files changed

Lines changed: 523 additions & 109 deletions

File tree

plugins/orchestrator/src/model/orchestrator/orchestrator.ts

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -397,6 +397,27 @@ class Orchestrator {
397397

398398
return new OrchestratorResult(buildParameters, output, true, true, false);
399399
} catch (error: any) {
400+
// Release first: logging/status reporting below may itself throw, and no
401+
// secondary failure should be able to strand a retained-workspace lock.
402+
if (
403+
BuildParameters.shouldUseRetainedWorkspaceMode(Orchestrator.buildParameters) &&
404+
Orchestrator.lockedWorkspace
405+
) {
406+
try {
407+
await SharedWorkspaceLocking.ReleaseWorkspace(
408+
Orchestrator.lockedWorkspace,
409+
Orchestrator.buildParameters.buildGuid,
410+
Orchestrator.buildParameters,
411+
);
412+
} catch (releaseError: any) {
413+
OrchestratorLogger.log(
414+
`Failed to release workspace lock for ${Orchestrator.lockedWorkspace} after build failure: ${OrchestratorLogger.stringifyError(releaseError)}`,
415+
);
416+
} finally {
417+
Orchestrator.lockedWorkspace = ``;
418+
}
419+
}
420+
400421
OrchestratorLogger.log(OrchestratorLogger.stringifyError(error));
401422
await GitHub.updateGitHubCheck(
402423
Orchestrator.buildParameters.buildGuid,
@@ -405,6 +426,7 @@ class Orchestrator {
405426
`completed`,
406427
);
407428
if (!Orchestrator.buildParameters.isCliMode) core.endGroup();
429+
408430
await OrchestratorError.handleException(
409431
error,
410432
Orchestrator.buildParameters,

plugins/orchestrator/src/model/orchestrator/services/cache/local-cache-service.test.ts

Lines changed: 106 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -368,6 +368,112 @@ describe('LocalCacheService', () => {
368368
});
369369
});
370370

371+
describe('sweepStaleLocks', () => {
372+
it('should return 0 when cache root does not exist', () => {
373+
(mockFs.existsSync as vi.Mock).mockReturnValue(false);
374+
expect(LocalCacheService.sweepStaleLocks('/cache')).toBe(0);
375+
});
376+
377+
it('should remove a lock whose owning PID is no longer alive', () => {
378+
(mockFs.existsSync as vi.Mock).mockReturnValue(true);
379+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
380+
(mockFs.readFileSync as vi.Mock).mockReturnValue('99999');
381+
(mockFs.unlinkSync as vi.Mock).mockReturnValue(undefined);
382+
383+
const killSpy = vi.spyOn(process, 'kill').mockImplementation(() => {
384+
throw Object.assign(new Error('ESRCH'), { code: 'ESRCH' });
385+
});
386+
387+
try {
388+
const removed = LocalCacheService.sweepStaleLocks('/cache');
389+
390+
expect(removed).toBe(1);
391+
expect(mockFs.unlinkSync).toHaveBeenCalledWith(
392+
path.join('/cache', 'key1', '.game-ci-cache-save.lock'),
393+
);
394+
} finally {
395+
killSpy.mockRestore();
396+
}
397+
});
398+
399+
it('should leave a lock in place when the owning PID is still alive', () => {
400+
(mockFs.existsSync as vi.Mock).mockReturnValue(true);
401+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
402+
(mockFs.readFileSync as vi.Mock).mockReturnValue(String(process.pid));
403+
(mockFs.unlinkSync as vi.Mock).mockReturnValue(undefined);
404+
405+
const killSpy = vi.spyOn(process, 'kill').mockImplementation(() => true as any);
406+
407+
try {
408+
const removed = LocalCacheService.sweepStaleLocks('/cache');
409+
410+
expect(removed).toBe(0);
411+
expect(mockFs.unlinkSync).not.toHaveBeenCalled();
412+
} finally {
413+
killSpy.mockRestore();
414+
}
415+
});
416+
417+
it('should leave a fresh pending lock in place while the child PID is being written', () => {
418+
(mockFs.existsSync as vi.Mock).mockReturnValue(true);
419+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
420+
(mockFs.readFileSync as vi.Mock).mockReturnValue('pending');
421+
(mockFs.statSync as vi.Mock).mockReturnValue({ mtimeMs: Date.now() });
422+
(mockFs.unlinkSync as vi.Mock).mockReturnValue(undefined);
423+
424+
const removed = LocalCacheService.sweepStaleLocks('/cache');
425+
426+
expect(removed).toBe(0);
427+
expect(mockFs.unlinkSync).not.toHaveBeenCalled();
428+
});
429+
430+
it('should remove an incomplete lock after the background-save timeout', () => {
431+
(mockFs.existsSync as vi.Mock).mockReturnValue(true);
432+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
433+
(mockFs.readFileSync as vi.Mock).mockReturnValue('pending');
434+
(mockFs.statSync as vi.Mock).mockReturnValue({ mtimeMs: Date.now() - 300_001 });
435+
(mockFs.unlinkSync as vi.Mock).mockReturnValue(undefined);
436+
437+
const removed = LocalCacheService.sweepStaleLocks('/cache');
438+
439+
expect(removed).toBe(1);
440+
expect(mockFs.unlinkSync).toHaveBeenCalledWith(
441+
path.join('/cache', 'key1', '.game-ci-cache-save.lock'),
442+
);
443+
});
444+
445+
it('should preserve a lock when the PID check fails with EPERM', () => {
446+
(mockFs.existsSync as vi.Mock).mockReturnValue(true);
447+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
448+
(mockFs.readFileSync as vi.Mock).mockReturnValue('12345');
449+
450+
const killSpy = vi.spyOn(process, 'kill').mockImplementation(() => {
451+
throw Object.assign(new Error('EPERM'), { code: 'EPERM' });
452+
});
453+
454+
try {
455+
const removed = LocalCacheService.sweepStaleLocks('/cache');
456+
457+
expect(removed).toBe(0);
458+
expect(mockFs.unlinkSync).not.toHaveBeenCalled();
459+
} finally {
460+
killSpy.mockRestore();
461+
}
462+
});
463+
464+
it('should skip cache-key directories with no lock file', () => {
465+
(mockFs.existsSync as vi.Mock).mockImplementation(
466+
(candidate: string) => !String(candidate).endsWith('.lock'),
467+
);
468+
(mockFs.readdirSync as vi.Mock).mockReturnValue([{ name: 'key1', isDirectory: () => true }]);
469+
470+
const removed = LocalCacheService.sweepStaleLocks('/cache');
471+
472+
expect(removed).toBe(0);
473+
expect(mockFs.unlinkSync).not.toHaveBeenCalled();
474+
});
475+
});
476+
371477
describe('garbageCollect', () => {
372478
it('should skip when cache root does not exist', async () => {
373479
(mockFs.existsSync as vi.Mock).mockReturnValue(false);

plugins/orchestrator/src/model/orchestrator/services/cache/local-cache-service.ts

Lines changed: 83 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,7 @@ export interface LocalCacheSaveOptions {
4949

5050
/** Marker file written during background cache saves, contains the PID. */
5151
const BACKGROUND_LOCK_FILE = '.game-ci-cache-save.lock';
52+
const BACKGROUND_LOCK_GRACE_MS = 300_000;
5253

5354
export class LocalCacheService {
5455
/**
@@ -935,6 +936,80 @@ export class LocalCacheService {
935936
}
936937
}
937938

939+
/**
940+
* Proactively sweep orphaned background-save lock files across every cache-key
941+
* directory under cacheRoot. A lock is orphaned when its recorded PID is no
942+
* longer alive, or when an incomplete/unparseable lock is older than the
943+
* background-save timeout. Fresh incomplete locks are preserved because the
944+
* writer briefly stores "pending" before replacing it with the child PID.
945+
*
946+
* waitForBackgroundLock() only self-heals reactively -- it checks a lock file
947+
* when a later save/restore call happens to target that exact cache key. A
948+
* background save killed mid-copy (runner crash, OOM kill) under a cache key
949+
* this run never touches would otherwise leave its lock in place indefinitely,
950+
* since nothing else in the process would ever look at it again. Call this once
951+
* at the start of a build (before any restore) to catch that case too.
952+
*
953+
* Returns the number of stale locks removed.
954+
*/
955+
static sweepStaleLocks(cacheRoot: string): number {
956+
if (!fs.existsSync(cacheRoot)) return 0;
957+
958+
let cacheKeyDirs: string[];
959+
try {
960+
cacheKeyDirs = fs
961+
.readdirSync(cacheRoot, { withFileTypes: true })
962+
.filter((entry) => entry.isDirectory())
963+
.map((entry) => entry.name);
964+
} catch (error: any) {
965+
OrchestratorLogger.logWarning(
966+
`[LocalCache] Failed to scan ${cacheRoot} for stale locks: ${error.message}`,
967+
);
968+
969+
return 0;
970+
}
971+
972+
let swept = 0;
973+
for (const cacheKeyDir of cacheKeyDirs) {
974+
const lockPath = path.join(cacheRoot, cacheKeyDir, BACKGROUND_LOCK_FILE);
975+
if (!fs.existsSync(lockPath)) continue;
976+
977+
try {
978+
const lockContents = fs.readFileSync(lockPath, 'utf8').trim();
979+
const pid = /^\d+$/.test(lockContents) ? Number(lockContents) : 0;
980+
if (pid > 0) {
981+
try {
982+
process.kill(pid, 0); // Signal 0 = existence check
983+
// Owning process is still alive -- a save is genuinely in progress.
984+
continue;
985+
} catch (error: any) {
986+
if (error?.code !== 'ESRCH') {
987+
// EPERM means the process exists but is owned by another user;
988+
// unknown errors are likewise not proof that the lock is stale.
989+
continue;
990+
}
991+
}
992+
} else if (Date.now() - fs.statSync(lockPath).mtimeMs < BACKGROUND_LOCK_GRACE_MS) {
993+
continue;
994+
}
995+
996+
fs.unlinkSync(lockPath);
997+
swept++;
998+
OrchestratorLogger.log(`[LocalCache] Swept stale background-save lock: ${lockPath}`);
999+
} catch (error: any) {
1000+
OrchestratorLogger.logWarning(
1001+
`[LocalCache] Failed to sweep lock ${lockPath}: ${error.message}`,
1002+
);
1003+
}
1004+
}
1005+
1006+
if (swept > 0) {
1007+
OrchestratorLogger.log(`[LocalCache] Stale lock sweep complete: ${swept} lock(s) removed`);
1008+
}
1009+
1010+
return swept;
1011+
}
1012+
9381013
/**
9391014
* Wait for a background cache save lock to be released.
9401015
* Polls the lock file for up to 5 minutes.
@@ -951,11 +1026,17 @@ export class LocalCacheService {
9511026
while (fs.existsSync(lockPath) && Date.now() - start < timeoutMs) {
9521027
// Check if the PID is still alive
9531028
try {
954-
const pid = Number.parseInt(fs.readFileSync(lockPath, 'utf8').trim(), 10);
1029+
const lockContents = fs.readFileSync(lockPath, 'utf8').trim();
1030+
const pid = /^\d+$/.test(lockContents) ? Number(lockContents) : 0;
9551031
if (pid > 0) {
9561032
try {
9571033
process.kill(pid, 0); // Signal 0 = existence check
958-
} catch {
1034+
} catch (error: any) {
1035+
if (error?.code !== 'ESRCH') {
1036+
// Lack of permission is evidence that the process exists, not
1037+
// that the lock is stale. Keep waiting in that case.
1038+
continue;
1039+
}
9591040
// Process is gone, remove stale lock
9601041
OrchestratorLogger.log(
9611042
'[LocalCache] Background save process exited, removing stale lock',

plugins/orchestrator/src/model/orchestrator/services/hooks/middleware-service.test.ts

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -419,5 +419,60 @@ after:
419419
expect(result[1].name).toBe('medium');
420420
expect(result[2].name).toBe('high');
421421
});
422+
423+
it.each([
424+
['command middleware on a container phase', 'command', '[pre-build]', 'cannot use phase'],
425+
['container middleware on a command phase', 'container', '[build]', 'cannot use phase'],
426+
[
427+
'middleware spanning incompatible phase kinds',
428+
'command',
429+
'[build, post-build]',
430+
'cannot use phase',
431+
],
432+
])('should reject %s', (_description, type, phases, expectedMessage) => {
433+
const yaml = `
434+
name: invalid-phase
435+
type: ${type}
436+
trigger:
437+
phase: ${phases}
438+
before: echo "test"
439+
`;
440+
441+
expect(() => MiddlewareService.getMiddleware(yaml)).toThrow(expectedMessage);
442+
});
443+
444+
it('should reject allowFailure on command middleware', () => {
445+
const yaml = `
446+
name: invalid-allow-failure
447+
type: command
448+
allowFailure: true
449+
trigger:
450+
phase: [build]
451+
before: echo "test"
452+
`;
453+
454+
expect(() => MiddlewareService.getMiddleware(yaml)).toThrow(
455+
'allowFailure, which is supported only for container middleware',
456+
);
457+
});
458+
459+
it('should reject middleware with no phase or commands', () => {
460+
expect(() =>
461+
MiddlewareService.getMiddleware(`
462+
name: missing-phase
463+
type: command
464+
before: echo "test"
465+
`),
466+
).toThrow('must declare at least one trigger phase');
467+
468+
expect(() =>
469+
MiddlewareService.getMiddleware(`
470+
name: missing-commands
471+
type: command
472+
trigger:
473+
phase: [build]
474+
`),
475+
).toThrow('must declare before and/or after commands');
476+
});
422477
});
423478
});

plugins/orchestrator/src/model/orchestrator/services/hooks/middleware-service.ts

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,10 @@ export class MiddlewareService {
3535
// Load file-based definitions from game-ci/middleware/
3636
middleware.push(...MiddlewareService.getMiddlewareFromFiles());
3737

38+
for (const definition of middleware) {
39+
MiddlewareService.validateMiddleware(definition);
40+
}
41+
3842
// Sort by priority (lower = earlier)
3943
middleware.sort((a, b) => (a.priority ?? 100) - (b.priority ?? 100));
4044

@@ -43,6 +47,51 @@ export class MiddlewareService {
4347
return middleware;
4448
}
4549

50+
/**
51+
* Reject configurations that cannot be represented by the underlying hook
52+
* systems. Command hooks are wired only to setup/build; container hooks are
53+
* wired only to pre-build/post-build.
54+
*/
55+
private static validateMiddleware(middleware: Middleware): void {
56+
const commandPhases = new Set(['setup', 'build']);
57+
const containerPhases = new Set(['pre-build', 'post-build']);
58+
const phasesForType =
59+
middleware.type === 'command'
60+
? commandPhases
61+
: middleware.type === 'container'
62+
? containerPhases
63+
: undefined;
64+
65+
if (!phasesForType) {
66+
throw new Error(
67+
`Middleware "${middleware.name}" has unsupported type "${middleware.type}"; expected "command" or "container"`,
68+
);
69+
}
70+
71+
if (!middleware.trigger.phase.length) {
72+
throw new Error(`Middleware "${middleware.name}" must declare at least one trigger phase`);
73+
}
74+
75+
const incompatiblePhases = middleware.trigger.phase.filter(
76+
(phase) => !phasesForType.has(phase),
77+
);
78+
if (incompatiblePhases.length > 0) {
79+
throw new Error(
80+
`Middleware "${middleware.name}" of type "${middleware.type}" cannot use phase(s): ${incompatiblePhases.join(', ')}`,
81+
);
82+
}
83+
84+
if (!middleware.before && !middleware.after) {
85+
throw new Error(`Middleware "${middleware.name}" must declare before and/or after commands`);
86+
}
87+
88+
if (middleware.type === 'command' && middleware.allowFailure) {
89+
throw new Error(
90+
`Middleware "${middleware.name}" sets allowFailure, which is supported only for container middleware`,
91+
);
92+
}
93+
}
94+
4695
/**
4796
* Resolve middleware to CommandHooks for a given phase and timing.
4897
* Filters by trigger conditions and converts to hooks.

0 commit comments

Comments
 (0)