diff --git a/src/service.ts b/src/service.ts index 7733be7df6..84b7da3817 100644 --- a/src/service.ts +++ b/src/service.ts @@ -740,14 +740,22 @@ export async function reportServiceServing( deps: Parameters[0] = {}, ): Promise { const healthBudgetMs = deps.timeoutMs ?? serviceInstallHealthMs(); + // Timed here rather than reported from the budget. confirmServiceServing knocks once + // more after a grace sleep whenever it waited at all, so the real wait is the budget + // plus that grace — and printing the budget states a number the run did not spend. + // What the reader is deciding is whether the service was still coming up, which is a + // judgement about elapsed time (#3009). + const now = deps.now ?? Date.now; + const startedAt = now(); const serving = await confirmServiceServing({ ...deps, timeoutMs: healthBudgetMs }); + const waitedMs = Math.max(0, now() - startedAt); if (serving.ok) { console.log(`✅ opencodex service ${verb} and serving on port ${serving.port}.`); return; } console.error( - `⚠️ Service ${verb}, but no proxy answered on port ${serving.port} within ` - + `${Math.trunc(healthBudgetMs / 1000)}s.\n` + `⚠️ Service ${verb}, but no proxy answered on port ${serving.port} after ` + + `${Math.round(waitedMs / 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 f9b4e55cd5..f880ed3fb9 100644 --- a/tests/service.test.ts +++ b/tests/service.test.ts @@ -3320,7 +3320,13 @@ describe("service serving confirmation", () => { expect(serviceInstallHealthMs("darwin")).toBe(SERVICE_INSTALL_HEALTH_MS); }); - test("reports the effective Windows failure budget", async () => { + // The failure line reports what the run actually spent, not what it was allowed to. + // With the Windows budget the loop exits at 45s and the post-deadline grace knock + // adds its 500ms sleep, so the real wait is 45.5s. Reporting the budget printed 45s + // for a 45.5s wait -- a small gap here, but the same expression understates every + // future grace the loop grows, and the reader is using this number to judge whether + // the service was still coming up (#3009). + test("reports the wait it actually spent, grace knock included", async () => { const errors: string[] = []; const previousError = console.error; const previousExitCode = process.exitCode; @@ -3334,8 +3340,35 @@ describe("service serving confirmation", () => { now: () => now, timeoutMs: SERVICE_INSTALL_HEALTH_WINDOWS_MS, }); - expect(errors.join("\n")).toContain("within 45s"); - expect(errors.join("\n")).not.toContain("within 20s"); + expect(now).toBe(SERVICE_INSTALL_HEALTH_WINDOWS_MS + 500); + expect(errors.join("\n")).toContain("after 46s"); + expect(errors.join("\n")).not.toContain("45s"); + expect(errors.join("\n")).not.toContain("20s"); + } finally { + console.error = previousError; + process.exitCode = previousExitCode ?? 0; + } + }); + + // A caller that asked not to wait must not be told it waited: with a zero budget + // confirmServiceServing takes its single probe and skips the grace entirely, so the + // reported wait is 0 rather than the budget. + test("reports no wait when the caller asked not to wait", async () => { + const errors: string[] = []; + const previousError = console.error; + const previousExitCode = process.exitCode; + let now = 0; + console.error = (...values: unknown[]) => { errors.push(values.join(" ")); }; + try { + await reportServiceServing("started", { + port: 10100, + probe: async () => false, + sleep: async ms => { now += ms; }, + now: () => now, + timeoutMs: 0, + }); + expect(now).toBe(0); + expect(errors.join("\n")).toContain("after 0s"); } finally { console.error = previousError; process.exitCode = previousExitCode ?? 0;