From b9c837c9c4d0f31c716ef2c5e37a522202c839a5 Mon Sep 17 00:00:00 2001 From: Nguyen Thanh Dat Date: Mon, 31 Aug 2026 10:46:32 +0700 Subject: [PATCH] fix(service): do not fail a Windows cold start that is still coming up On Windows, `ocx service repair` reported failure at its fixed 20s health deadline for a service that bound a few seconds later and then stayed healthy. The cold start does NTFS ACL hardening and previous-session journal recovery before the listener is announced, so 20s is not always enough, and the caller's fallback to a terminal failure is to start a second proxy against a port that is about to be taken. Windows now gets a 45s budget; the other platforms keep 20s. The wait also knocks once more after a short grace when the deadline passes, because the probe that ran last started before the deadline and a service binding during it was reported as dead. A caller that passed a zero budget still gets the single probe it asked for. The failure message prints the time actually waited. It printed the 20s constant whatever timeoutMs the caller passed. Refs #3009. --- src/service.ts | 38 +++++++++++++++++++++++++++++++--- tests/service.test.ts | 47 +++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 80 insertions(+), 5 deletions(-) diff --git a/src/service.ts b/src/service.ts index ab780711e8..6341b75881 100644 --- a/src/service.ts +++ b/src/service.ts @@ -660,6 +660,23 @@ export function installedServiceListenPort(): number { export const SERVICE_INSTALL_HEALTH_MS = 20_000; +/** + * Windows gets a longer budget because its cold start does more before the + * listener exists: NTFS ACL hardening and previous-session journal recovery + * both run first, and #3009 recorded a service that bound a few seconds past + * the 20s deadline and then stayed healthy. Reporting that as a terminal + * repair failure is worse than waiting: the caller's fallback is to start a + * second proxy against a port that is about to be taken. + */ +export const SERVICE_INSTALL_HEALTH_WINDOWS_MS = 45_000; + +/** The health budget for the platform this is running on. */ +export function serviceInstallHealthMs( + platform: NodeJS.Platform = process.platform, +): number { + return platform === "win32" ? SERVICE_INSTALL_HEALTH_WINDOWS_MS : SERVICE_INSTALL_HEALTH_MS; +} + /** * Whether a proxy actually answers on the port this install/start just produced. * @@ -690,12 +707,23 @@ export async function confirmServiceServing( const now = deps.now ?? Date.now; const sleep = deps.sleep ?? ((ms: number) => new Promise(r => setTimeout(r, ms))); const probe = deps.probe ?? (async (p, h) => !!(await proxyIdentityAt(p, { hostname: h }))); - const deadline = now() + (deps.timeoutMs ?? SERVICE_INSTALL_HEALTH_MS); + const deadline = now() + (deps.timeoutMs ?? serviceInstallHealthMs()); + let waited = false; for (;;) { if (await probe(port, hostname)) return { ok: true, port }; - if (now() >= deadline) return { ok: false, port }; + if (now() >= deadline) break; + await sleep(500); + waited = true; + } + // The probe that ran last started before the deadline, so a service that + // binds during it is reported as dead (#3009). Knock once more after a + // short grace before calling it a failure. A zero budget means the caller + // asked not to wait, so it gets the single probe it asked for. + if (waited) { await sleep(500); + if (await probe(port, hostname)) return { ok: true, port }; } + return { ok: false, port }; } /** @@ -711,14 +739,18 @@ async function reportServiceServing( verb: "installed" | "started" | "repaired", deps: Parameters[0] = {}, ): Promise { + const elapsed = deps.now ?? Date.now; + const startedAt = elapsed(); const serving = await confirmServiceServing(deps); if (serving.ok) { console.log(`✅ opencodex service ${verb} and serving on port ${serving.port}.`); return; } console.error( + // The elapsed time, not the constant: a caller that passes its own + // timeoutMs used to be told it had waited 20s whatever it waited. `⚠️ Service ${verb}, but no proxy answered on port ${serving.port} within ` - + `${Math.trunc(SERVICE_INSTALL_HEALTH_MS / 1000)}s.\n` + + `${Math.max(1, Math.round((elapsed() - startedAt) / 1000))}s.\n` + ` The manager registered the job; that is not the same as serving.\n` + ` Log: ${serviceLogPath()}\n` + ` Meanwhile: ocx start (serves in the foreground)`, diff --git a/tests/service.test.ts b/tests/service.test.ts index 4e9247e4b8..ea43fe0e79 100644 --- a/tests/service.test.ts +++ b/tests/service.test.ts @@ -7,7 +7,7 @@ import { pathToFileURL } from "node:url"; import * as serviceModule from "../src/service"; import { saveConfig } from "../src/config"; import { windowsEnvIndirectBatchValue } from "../src/lib/win-paths"; -import { assertServiceAuthEnvironment, assertServiceEnvironmentMatchesInstall, bakedServicePathsDiagnostic, confirmServiceServing, launchdListenPort, systemdListenPort, buildPlist, buildUnit, buildWindowsLauncherVbs, buildWindowsSchtasksCreateArgs, buildWindowsSchtasksCreateArgsForXml, buildWindowsServiceScript, buildWindowsTaskXml, deriveWindowsServiceDiagnostic, deriveWindowsServiceDiagnosticForCurrentUser, installFreshWindowsSchedulerSafely, installServiceSafely, launchctlLoadFailed, launchdJobMatchesPlist, normalizeServiceSubcommand, parseServiceArgs, parseServiceInstallState, planServiceCommand, prepareServiceInstall, probeServiceInstallation, readWindowsSchedulerXmlState, registerFreshWindowsSchedulerTask, removeNativeWindowsServiceForScheduler, repairService, resolveServiceListenPort, runLaunchctl, selectServiceSubcommand, serviceLogPath, serviceStartableFromTray, serviceStatusReport, serviceRetryCommand, serviceStatusSummary, stableLauncherEntry, systemdNeedsDaemonReload, systemdServiceInstallCleanupOps, uninstallSystemd, windowsListenPort, winswListenPort, startLaunchd, windowsTaskRegistrationHealthy } from "../src/service"; +import { assertServiceAuthEnvironment, assertServiceEnvironmentMatchesInstall, bakedServicePathsDiagnostic, buildPlist, buildUnit, buildWindowsLauncherVbs, buildWindowsSchtasksCreateArgs, buildWindowsSchtasksCreateArgsForXml, buildWindowsServiceScript, buildWindowsTaskXml, confirmServiceServing, deriveWindowsServiceDiagnostic, deriveWindowsServiceDiagnosticForCurrentUser, installFreshWindowsSchedulerSafely, installServiceSafely, launchctlLoadFailed, launchdJobMatchesPlist, launchdListenPort, normalizeServiceSubcommand, parseServiceArgs, parseServiceInstallState, planServiceCommand, prepareServiceInstall, probeServiceInstallation, readWindowsSchedulerXmlState, registerFreshWindowsSchedulerTask, removeNativeWindowsServiceForScheduler, repairService, resolveServiceListenPort, runLaunchctl, selectServiceSubcommand, SERVICE_INSTALL_HEALTH_MS, serviceInstallHealthMs, serviceLogPath, serviceRetryCommand, serviceStartableFromTray, serviceStatusReport, serviceStatusSummary, stableLauncherEntry, startLaunchd, systemdListenPort, systemdNeedsDaemonReload, systemdServiceInstallCleanupOps, uninstallSystemd, windowsListenPort, windowsTaskRegistrationHealthy, winswListenPort } from "../src/service"; import type { ServiceDiagnostic } from "../src/service"; import { definitionCarriesCredential, resolvedProxyEnv, writeServiceDefinitionFile } from "../src/service"; import { buildWinswXml } from "../src/lib/winsw"; @@ -3142,9 +3142,52 @@ describe("service serving confirmation", () => { now: () => 0, timeoutMs: 0, }); - expect(probes).toBe(1); + // At least once, which is what the name asks: a zero budget must not + // return without knocking. The exact count is not the contract — the + // deadline grace probe adds one when the caller did give it time. + expect(probes).toBeGreaterThanOrEqual(1); + }); + + // #3009: a Windows cold start does NTFS ACL hardening and journal recovery + // before the listener exists, so the service can bind seconds after the + // deadline and then stay healthy. `ocx service repair` reported that as a + // terminal failure with exit 1, and the caller's fallback is to start a + // second proxy against a port that is about to be taken. + test("accepts a service that binds during the grace after the deadline", async () => { + let now = 0; + let probes = 0; + const out = await confirmServiceServing({ + port: 10100, + // Answers only once the clock is past the deadline, which is the shape + // the report describes: healthy, just not within the budget. + probe: async () => { probes += 1; return now > 2_000; }, + sleep: async ms => { now += ms; }, + now: () => now, + timeoutMs: 2_000, + }); + expect(out).toEqual({ ok: true, port: 10100 }); + expect(probes).toBeGreaterThan(1); }); + test("still fails a service that never binds", async () => { + let now = 0; + const out = await confirmServiceServing({ + port: 10100, + probe: async () => false, + sleep: async ms => { now += ms; }, + now: () => now, + timeoutMs: 2_000, + }); + expect(out).toEqual({ ok: false, port: 10100 }); + }); + + // Windows is the platform the extra budget exists for; everything else keeps + // the original 20s so this cannot slow a healthy Linux install down. + test("gives Windows a longer cold-start budget than the other platforms", () => { + expect(serviceInstallHealthMs("win32")).toBeGreaterThan(serviceInstallHealthMs("linux")); + expect(serviceInstallHealthMs("linux")).toBe(SERVICE_INSTALL_HEALTH_MS); + expect(serviceInstallHealthMs("darwin")).toBe(SERVICE_INSTALL_HEALTH_MS); + }); // A service reinstall invalidates the pidfile, so resolving the target through // it (findLiveProxy) would report a serving service as dead. Ask the baked port. test("probes the port it was given rather than resolving one", async () => {