fix(service): report the wait that was actually spent, not the budget

[ntdatt812]

Follow-up to #3134, which named this as the one piece of #3039 it deliberately did not carry, and said it deserved its own resolution. This is that.

The gap

reportServiceServing prints the budget it allowed:

+ `${Math.trunc(healthBudgetMs / 1000)}s.\n`

while confirmServiceServing knocks once more after a 500ms grace sleep whenever it waited at all:

if (waited) {
  await sleep(500);
  if (await probe(port, hostname)) return { ok: true, port };
}

So a Windows run that gives up spends 45.5s and reports within 45s.

Half a second is not the point. The expression is wrong rather than the number: it states a figure the run did not spend, and it understates every future grace the loop grows. What the reader is deciding is whether the service was merely still coming up — which is a question about elapsed time, and #3009 is the report of exactly that misjudgement being made.

The change

The wait is timed in reportServiceServing, through the same injected now the deps already carry:

const now = deps.now ?? Date.now;
const startedAt = now();
const serving = await confirmServiceServing({ ...deps, timeoutMs: healthBudgetMs });
const waitedMs = Math.max(0, now() - startedAt);

confirmServiceServing's return shape and contract are untouched, so its existing tests — including the zero-budget single-probe assertion #3104 was right to restore — are untouched too. Nine lines, one file.

Math.round rather than Math.trunc: truncating 45.5s back to 45 would reintroduce the understatement this fixes.

Tests

test	pins
reports the wait it actually spent, grace knock included	the fake clock reaches SERVICE_INSTALL_HEALTH_WINDOWS_MS + 500, the line says after 46s, and no longer says 45s
reports no wait when the caller asked not to wait	a zero budget takes its single probe, skips the grace, and reports after 0s

The second one exists because "report the elapsed time" has an obvious wrong version — reporting the budget when nothing was waited — and the zero-budget path is where that shows.

Reverting to the budget expression fails both.

Verification

bun test tests/service.test.ts   ->  183 pass, 3 skip, 6 fail

Those six fail identically on a clean dev checkout on this host (Windows) — service listen-port bake ×2, service install auth preflight ×2, service lifecycle cleanup ordering ×2. Compared by test name rather than by count, and none is touched by this diff.

Thank you for splitting this out instead of closing #3039 over it.

Review readiness checklist

This PR stays in draft until every box below is ticked. Tick all four boxes once the requirements are met:

• All CI tests are green on my local testing.

• I pushed my PR to the latest dev commit.

• I resolved all correct Codex and CodeRabbit findings.

• My PR is ready for review.

Summary by CodeRabbit

• Bug Fixes
  • Service availability failure messages now report the actual time spent waiting for confirmation.
  • Updated wording clarifies that the check failed after the reported duration.
  • Zero-second wait scenarios now display an accurate 0-second duration.

[github-actions]

✅ Deterministic PR hygiene checks passed.

[github-actions]

✅ READY

• all PR quality gates passed; the review readiness checklist is complete.

Review readiness checklist

• ✅ All CI tests are green on my local testing.
• ✅ I pushed my PR to the latest dev commit.
• ✅ I resolved all correct Codex and CodeRabbit findings.
• ✅ My PR is ready for review.

✅ 4/4 boxes ticked.

This pull request is already Ready for Review.
The review-ready label marks this PR as ready; review automation runs independently.
Maintainers: @lidge-jun @Ingwannu

[coderabbitai]

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info

⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: ASSERTIVE

Plan: Team

Run ID: db35cdfc-c6d3-43c6-9122-591d698922ac

📥 Commits

Reviewing files that changed from the base of the PR and between b14b741 and dda9e80.

📒 Files selected for processing (2)

• src/service.ts
• tests/service.test.ts

Included review availability: Your plan provides up to 10 included reviews per hour; 9 remain after this review.

---

📝 Walkthrough

Walkthrough

reportServiceServing now reports the actual elapsed wait around confirmServiceServing, including its grace probe. Tests verify grace-inclusive timing and the zero-timeout case.

Changes

Service wait reporting

Layer / File(s)	Summary
Measure and report elapsed wait src/service.ts	At lines 743–758, reportServiceServing captures a timestamp before confirmServiceServing, calculates elapsed milliseconds afterward, and reports rounded seconds using “after Xs” instead of the configured budget using “within Xs”.
Validate measured wait messages tests/service.test.ts	At lines 3323–3371, tests verify that the failure message includes the grace-inclusive elapsed wait and that a zero timeout reports “after 0s”.

Estimated code review effort: 2 (Simple) | ~10 minutes

Merge Risk: ⚪ Minimal · up to dda9e

This localized change corrects the reported service-wait duration without changing health checks, connectivity, permissions, deployment behavior, or persisted state. No actionable merge-blocking risk remains at the current head beyond normal checks and review.

Suggested reviewers: ingwannu

🚥 Pre-merge checks | ✅ 5

✅ Passed checks (5 passed)

Check name	Status	Explanation
Docstring Coverage	✅ Passed	Docstring coverage is 100.00% which is sufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 1 functions across 2 files.
Linked Issues check	✅ Passed	Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check	✅ Passed	Check skipped because no linked issues were found for this pull request.
Description Check	✅ Passed	Check skipped - CodeRabbit’s high-level summary is enabled.
Title check	✅ Passed	The title clearly and concisely states the main change: reporting the actual service wait time instead of the configured budget. It matches the changes in src/service.ts and tests/service.test.ts.

✨ Finishing Touches

🧪 Generate unit tests (beta)

• Create PR with unit tests

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands.}

[Ingwannu]

Reviewed exact head dda9e80. The two-file production/test change is correct and narrowly scoped: reportServiceServing measures the same injected clock around confirmServiceServing, clamps backward-clock results at zero, reports the real elapsed wait, and keeps the zero-budget single-probe path honest. The focused regressions cover both the 45.5s Windows path and zero wait. I found no source-code blocker in this patch.

Final approval is blocked only by exact-head CI and base drift. Linux shard 3/4 failed at tests/server-auth.test.ts:2289 on the unrelated websocket-refresh fixture. This branch is four commits behind current dev, which now contains #3139 (c8c8dc338) specifically fixing that startup-prime race. Please rebase this unchanged service patch onto current dev and rerun the complete exact-head matrix. If the range-diff remains equivalent and CI is green, this is an approval candidate; no additional service behavior change is requested.

[ntdatt812]

The red on this PR is dev's, not this branch's.

macos, test 3/4 and the ci rollup all fail on the same assertion:

(fail) server local API auth > websocket passthrough refreshes pool auth for each response.create turn
  tests/server-auth.test.ts:2289

The same test fails on dev itself, in the same macos job, on run
33477777613
at 58be3c5bb — the run that follows b14b741dc, which was green. This PR
touches one function in src/service.ts (reportServiceServing) and nothing
under src/server/ or src/codex/.

Two notes in case they save someone time, one of them a correction:

The diff is a substitution, not an extra element. GitHub redacts the tokens
to ***, which makes it read like a length mismatch. It is not: both arrays
have two entries and only seenAuth[0] differs — expected
Bearer old-access-token, got Bearer new-access-token. So the credential was
already rotated before the first turn was served, which is exactly the shape
#3139 describes.

#3139 does not appear to have closed it. That commit moved Date.now and
the fetch stub above startServer so the startup pool-quota prime would run
inside the fixture's controlled world. The failure survives that on dev.

I could not reproduce it locally (Windows, bun 1.3.14): the test passes on dev
as-is, and still passes with a deliberate 400 ms delay inserted after
startServer to let the prime win the race, so whatever fires on the runners
does not fire here. OPENCODEX_DEBUG_QUOTA=1 produced no prime output on this
host either. I am not claiming a root cause on that evidence — only that the
failure predates this branch and is reproducible on dev.

One thing worth checking if you are still on it: the fixture stamps
updateAccountQuota("pool-a", …) before Date.now is faked, so updatedAt
carries real time while the prime's staleness test reads the fake clock
(Date.now() - q.updatedAt >= POOL_CACHE_TTL, auth-api.ts:1334). With the fake
clock ~4 months ahead of real time, that comparison is always stale. Moving the
clock above saveCodexAccountCredential/updateAccountQuota would make it 0.
I could not confirm this is the live path on my host, so treat it as a lead
rather than a diagnosis.

Happy to rebase this PR once dev is green if that is easier than reading
around the noise.

[lidge-jun]

리뷰 · 우선순위 52 / 80

설명

이 PR은 #3134가 의도적으로 남긴 #3039 조각을 닫습니다. reportServiceServing 이 실제로 기다린 시간이 아니라 health budget을 출력하던 문구 오류를 고칩니다. Windows에서 confirm 루프가 45초 예산 뒤 500ms grace knock까지 합쳐 45.5초를 쓰고도 within 45s 라고 말하면, 운영자는 "아직 기동 중인가, 이미 예산을 다 썼는가"를 잘못 판단합니다. 그 오판이 #3009로 보고된 장면입니다.

지금 HEAD src/service.ts 738행 근처 reportServiceServing 은 healthBudgetMs 를 받아 confirmServiceServing 에 넘긴 뒤, 실패 메시지에 Math.trunc(healthBudgetMs / 1000) 을 붙입니다. confirmServiceServing 은 한 번이라도 기다렸으면 500ms를 더 자고 probe합니다. 예산과 실측이 어긋나는 구조입니다. 패치는 deps.now ?? Date.now 로 시작 시각을 찍고, confirm이 끝난 뒤 waitedMs 를 재어 Math.round(waitedMs / 1000) 으로 출력합니다. confirm의 반환 shape와 zero-budget 단일 probe 계약(#3104가 복구한 것)은 건드리지 않습니다.

파일은 src/service.ts 와 tests/service.test.ts 뿐이고 +46/−5, MERGEABLE, 베이스 dev 입니다. types.ts/config.ts 분할과 무관합니다. remote hub·계정 핀·Claude admission 같은 열차보다 우선순위는 낮지만, 서비스 설치/복구 메시지의 정직성은 운영 도구로서 맞습니다.

점수는 52입니다. 관측 가능성 수정이고 기능/보안 구멍은 아닙니다. #3158이 언급한 launcher 플래크와도 직접 같지는 않습니다(그쪽은 start 거절/#3144 축).

라인 src/service.ts reportServiceServing - budget 대신 waitedMs를 찍습니다. 성공 경로 문구까지 바꾸는지 실패 라인만인지 diff에서 확인하십시오
경로 tests/service.test.ts - injected now 로 45.5초 → "46s" 또는 "46" 반올림이 잠기는지 보세요
경로 #3009 - 사용자 오판 보고와 연결됩니다. Closes/Fixes 참조를 명확히 하십시오
경로 #3134 - 이 조각을 남긴 선행입니다. 중복 구현이 없어야 합니다
경로 Windows grace 500ms - 앞으로 grace가 늘어도 elapsed 보고면 표현이 따라갑니다

메인테이너의 판단이 필요한 지점

• #3009를 이 PR로 닫을지, 메시지 수정만 하고 이슈는 별 검증 후 닫을지
• 성공 메시지에도 elapsed를 넣을지(본문은 실패 라인을 중심으로 설명)

너의 추천
작은 독립 패치로 머지해도 됩니다. #3168/#3166/#3148 같은 높은 점수 항목 뒤에 두십시오. 라벨은 바꾸지 않습니다.

이 댓글은 grok-bot이 작성했습니다