Skip to content

Commit 4c1f9f3

Browse files
committed
fix(update): stop a slow progress write from erasing the install outcome
The state file is a temp file plus rename, so the last rename wins. Progress writes were fire-and-forget, and the installer's terminal state=done line bypasses the write throttle just as the child exits — so on the ordinary success path that write could land after the outcome, restoring active and dropping lastSuccess. The next launch read that as an abandoned install and recorded a failure for a version that had installed cleanly, which parks the version at two attempts. Progress writes now run on one chain, new ones stop once the outcome is settled, and the finalizer drains the chain before writing. Removing the drain fails the new test. Also from review: the CDN reject cases named the field they expect instead of matching any non-empty message, the lock-ordering test now reaches the prompt before asserting no lock was taken (it previously asserted before the first await, so it held wherever the acquisition sat), and two lint nits this branch introduced.
1 parent e486a10 commit 4c1f9f3

4 files changed

Lines changed: 97 additions & 20 deletions

File tree

apps/pythinker-code/src/cli/update/preflight.ts

Lines changed: 25 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -841,6 +841,15 @@ async function startBackgroundInstall(
841841
let ready = false;
842842
let settled = false;
843843
let pendingOutcome: { succeeded: boolean; reason: string } | undefined;
844+
// Progress writes are fire-and-forget, and the state file is written as a
845+
// temp file plus rename — so the last rename wins. The installer's terminal
846+
// `state=done` line bypasses the throttle and writes just as the child
847+
// exits, so without ordering that write can land *after* the outcome write
848+
// and restore `active` while dropping `lastSuccess`. The next launch reads
849+
// that as an abandoned install and records a failure for a version that
850+
// installed cleanly. One chain keeps the writes ordered and gives `finish`
851+
// something to drain.
852+
let progressWrites: Promise<void> = Promise.resolve();
844853

845854
const finish = async (succeeded: boolean, reason: string): Promise<void> => {
846855
if (!ready) {
@@ -849,6 +858,9 @@ async function startBackgroundInstall(
849858
}
850859
if (settled) return;
851860
settled = true;
861+
// `settled` already stops new progress writes; drain the ones in flight so
862+
// none of them renames over the outcome below.
863+
await progressWrites;
852864
const attempts = failureAttemptsFor(startedState, target, 'install') + 1;
853865
const stderrTail = readStderrTail();
854866
const message = stderrTail === undefined ? reason : `${reason}: ${stderrTail}`;
@@ -917,6 +929,9 @@ async function startBackgroundInstall(
917929
});
918930
let lastProgressWriteAt = 0;
919931
const recordInstallerProgress = (update: UpdateInstallProgress): void => {
932+
// Once the outcome is being written, progress is history: writing it would
933+
// undo the terminal record.
934+
if (settled) return;
920935
// Terminal states always persist; intermediate ones at most every 2s.
921936
const terminal = update.state === 'done' || update.state === 'failed';
922937
if (
@@ -936,14 +951,17 @@ async function startBackgroundInstall(
936951
progress: update,
937952
},
938953
};
939-
writeUpdateInstallState(nextState).catch((error) => {
940-
// A progress write is best-effort; it must never reject the spawn path.
941-
logUpdateWarn(logger, 'could not record installer progress', {
942-
targetVersion: target.version,
943-
source,
944-
error: formatErrorMessage(error),
954+
progressWrites = progressWrites
955+
.then(() => writeUpdateInstallState(nextState))
956+
.catch((error) => {
957+
// A progress write is best-effort; it must never reject the spawn path
958+
// and must not break the chain for the writes queued behind it.
959+
logUpdateWarn(logger, 'could not record installer progress', {
960+
targetVersion: target.version,
961+
source,
962+
error: formatErrorMessage(error),
963+
});
945964
});
946-
});
947965
};
948966
const readStderrTail = captureStderrTail(child, recordInstallerProgress);
949967
child.once('error', (error) => { void finish(false, formatErrorMessage(error)); });

apps/pythinker-code/test/cli/update/cdn.test.ts

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -173,18 +173,18 @@ describe('fetchUpdateManifest', () => {
173173
// so reading it after a bad manifest would report an unverifiable target as
174174
// verified. Every one of these must reject and leave the cached answer alone.
175175
const rejectCases: ReadonlyArray<readonly [string, Route, RegExp]> = [
176-
['latest.json is missing (HTTP 404)', { status: 404 }, /HTTP 404/],
177-
['latest.json fetch throws', new Error('network down'), /network down/],
178-
['body is not valid JSON', { body: 'not json {' }, /JSON/i],
176+
['latest.json is missing (HTTP 404)', { status: 404 }, /HTTP 404/u],
177+
['latest.json fetch throws', new Error('network down'), /network down/u],
178+
['body is not valid JSON', { body: 'not json {' }, /JSON/iu],
179179
[
180180
'version is not semver',
181181
{ body: JSON.stringify({ version: 'nope', publishedAt: '2026-06-12T00:00:00.000Z' }) },
182-
/invalid semver/,
182+
/invalid semver/u,
183183
],
184184
[
185185
'publishedAt is unparseable',
186186
{ body: JSON.stringify({ version: '2.0.0', publishedAt: 'garbage' }) },
187-
/invalid timestamp/,
187+
/invalid timestamp/u,
188188
],
189189
[
190190
'a batch percent is out of range',
@@ -195,7 +195,9 @@ describe('fetchUpdateManifest', () => {
195195
rollout: [{ percent: 150, delaySeconds: 0 }],
196196
}),
197197
},
198-
/./,
198+
// Name the field: `/./` matched any non-empty message, so a JSON.parse
199+
// failure would have satisfied it just as well as the schema rejection.
200+
/percent/u,
199201
],
200202
[
201203
'a batch delay is negative',
@@ -206,7 +208,7 @@ describe('fetchUpdateManifest', () => {
206208
rollout: [{ percent: 100, delaySeconds: -1 }],
207209
}),
208210
},
209-
/./,
211+
/delaySeconds/u,
210212
],
211213
];
212214

@@ -229,7 +231,7 @@ describe('fetchUpdateManifest', () => {
229231
}) as unknown as typeof fetch;
230232

231233
const result = fetchUpdateManifest(f);
232-
const expectation = expect(result).rejects.toThrow(/aborted/);
234+
const expectation = expect(result).rejects.toThrow(/aborted/u);
233235
await vi.advanceTimersByTimeAsync(3_000);
234236

235237
await expectation;

apps/pythinker-code/test/cli/update/preflight.test.ts

Lines changed: 60 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -388,6 +388,14 @@ function progressActiveStates(): unknown[] {
388388
.filter((state) => state !== undefined && state !== null && state.active?.progress !== undefined);
389389
}
390390

391+
/** The terminal success records written by the finalizer, in order. */
392+
function successOutcomeStates(): unknown[] {
393+
return mocks.writeUpdateInstallState.mock.calls
394+
.map((call) => call[0])
395+
.filter((state) => state !== undefined && state !== null
396+
&& state.active === null && state.lastSuccess !== undefined && state.lastSuccess !== null);
397+
}
398+
391399
async function flushBackgroundInstall(): Promise<void> {
392400
await new Promise<void>((resolve) => {
393401
setImmediate(resolve);
@@ -961,6 +969,13 @@ describe('runUpdatePreflight', () => {
961969

962970
const running = runUpdatePreflight('0.4.0', options);
963971

972+
// Let the flow actually reach the prompt first. Asserting straight after the
973+
// call was vacuous: nothing had run past the first await, so "no lock yet"
974+
// held wherever the acquisition sat, and the ordering claim in the test name
975+
// went unchecked.
976+
await vi.waitFor(() => {
977+
expect(mocks.promptForInstallChoice).toHaveBeenCalled();
978+
});
964979
expect(mocks.tryAcquireUpdateInstallLock).not.toHaveBeenCalled();
965980
resolvePrompt?.('install');
966981
await expect(running).resolves.toBe('exit');
@@ -1178,7 +1193,7 @@ describe('runUpdatePreflight', () => {
11781193
await expect(runUpdatePreflight('0.5.0', options)).resolves.toBe('continue');
11791194

11801195
expect(mocks.spawn).toHaveBeenCalledWith(
1181-
expect.stringMatching(/^npm(\.cmd)?$/),
1196+
expect.stringMatching(/^npm(\.cmd)?$/u),
11821197
['install', '-g', '@pythoughts/pythinker-code@0.6.0'],
11831198
{ detached: true, windowsHide: false, stdio: ['ignore', 'ignore', 'pipe'] },
11841199
);
@@ -2099,6 +2114,50 @@ describe('runUpdatePreflight', () => {
20992114
}));
21002115
});
21012116

2117+
/**
2118+
* The state file is written as a temp file plus rename, so the last rename
2119+
* wins. The installer's terminal `state=done` line writes just as the child
2120+
* exits, so an unawaited progress write can rename over the outcome —
2121+
* restoring `active` and dropping `lastSuccess`. The next launch reads that
2122+
* as an abandoned install and records a failure for a version that
2123+
* installed cleanly, which at two attempts parks it for good.
2124+
*/
2125+
it('never lets a slow progress write rename over the install outcome', async () => {
2126+
mocks.readUpdateCache.mockResolvedValue(cacheWith('0.5.0'));
2127+
mocks.readUpdateInstallState.mockResolvedValue(installState());
2128+
mocks.refreshUpdateCache.mockResolvedValue(cacheWith('0.5.0'));
2129+
mocks.detectInstallSource.mockResolvedValue('npm-global');
2130+
// Hold the progress write open; every other write settles at once.
2131+
let releaseProgressWrite: (() => void) | undefined;
2132+
mocks.writeUpdateInstallState.mockImplementation(
2133+
(state: { active?: { progress?: unknown } | null }) => (
2134+
state.active?.progress === undefined
2135+
? Promise.resolve()
2136+
: new Promise<void>((resolve) => { releaseProgressWrite = resolve; })
2137+
),
2138+
);
2139+
mockSpawnExitWithStderr(0, 'progress: state=done transferred=55795679\n');
2140+
const { options } = captureOutput();
2141+
2142+
await expect(runUpdatePreflight('0.4.0', options)).resolves.toBe('continue');
2143+
await flushBackgroundInstall();
2144+
2145+
// The progress write is still in flight, so the outcome must not be out yet.
2146+
expect(progressActiveStates()).toHaveLength(1);
2147+
expect(successOutcomeStates()).toEqual([]);
2148+
2149+
releaseProgressWrite?.();
2150+
await flushBackgroundInstall();
2151+
await flushBackgroundInstall();
2152+
2153+
expect(successOutcomeStates()).toHaveLength(1);
2154+
// The outcome is the last thing written, so it survives on disk.
2155+
expect(mocks.writeUpdateInstallState.mock.calls.at(-1)?.[0]).toMatchObject({
2156+
active: null,
2157+
lastSuccess: expect.objectContaining({ version: '0.5.0' }),
2158+
});
2159+
});
2160+
21022161
it('keeps progress lines out of the failure tail and ordinary stderr lines in it', async () => {
21032162
mocks.readUpdateCache.mockResolvedValue(cacheWith('0.5.0'));
21042163
mocks.readUpdateInstallState.mockResolvedValue(installState());

apps/pythinker-code/test/tui/pythinker-tui-startup.test.ts

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2022,8 +2022,7 @@ describe('footer update status poll', () => {
20222022
*/
20232023
it('dispatches availability and then live progress into the status row', async () => {
20242024
const home = mkdtempSync(join(tmpdir(), 'pk-footer-update-'));
2025-
const previousHome = process.env['PYTHINKER_CODE_HOME'];
2026-
process.env['PYTHINKER_CODE_HOME'] = home;
2025+
vi.stubEnv('PYTHINKER_CODE_HOME', home);
20272026
const updates = join(home, 'updates');
20282027
mkdirSync(updates, { recursive: true });
20292028
const manifest = {
@@ -2089,8 +2088,7 @@ describe('footer update status poll', () => {
20892088
} finally {
20902089
driver.stopUpdateStatusPolling();
20912090
driver.state.footer.dispose();
2092-
if (previousHome === undefined) delete process.env['PYTHINKER_CODE_HOME'];
2093-
else process.env['PYTHINKER_CODE_HOME'] = previousHome;
2091+
vi.unstubAllEnvs();
20942092
rmSync(home, { recursive: true, force: true });
20952093
}
20962094
}, 30_000);

0 commit comments

Comments
 (0)