Skip to content

test(runtime-host): fix flaky startup failure test via native fake timers - #3859

Open
Bryandero98 wants to merge 1 commit into
apache:mainfrom
Bryandero98:test/fix-flaky-startup-shutdown-deadline-test
Open

test(runtime-host): fix flaky startup failure test via native fake timers#3859
Bryandero98 wants to merge 1 commit into
apache:mainfrom
Bryandero98:test/fix-flaky-startup-shutdown-deadline-test

Conversation

@Bryandero98

Copy link
Copy Markdown

Summary

Fixes #3840.

"startup failure preserves its cause when shutdown reaches the active deadline" (host-kernel.test.ts) raced a real 100ms shutdownGraceMs deadline against real I/O that #closeResources() must perform before it ever calls composition.close() - registration writes, listener admission close, storage-root identity re-validation. On a loaded runner that pre-close bookkeeping alone can exceed 100ms, so #assertShutdownCanContinue() aborts the shutdown sequence before composition.close() is ever invoked. closeEntered then never resolves, and the test fails with "composition close did not begin" - a false negative; the kernel is behaving exactly as designed (fail-stop on a missed shutdown deadline).

Fix: enable node:test's built-in mock timers (t.mock.timers, already used in this package - see gitoxide-helper-invocation-internal.test.ts) right before starting the kernel, await the real, un-timed signal that close() was actually entered, then deterministically tick(100) the deadline forward. This reproduces the intended scenario - close() genuinely stuck when shutdownGraceMs elapses - without racing wall-clock jitter, and without touching kernel production code (host-kernel.ts is unmodified).

I considered two other approaches first and rejected both: stubbing the I/O layer (writeHostRegistration/listener setup aren't injectable without adding new seams to production code, and it wouldn't structurally remove the race, only shrink it) and deferring context.requestDrain() until "prep" finishes (the kernel has no way to know that from outside, and it would change what the test actually exercises - startup failure, not post-startup drain).

Verification

  • Reproduced the reported failure locally on the unmodified test (Error: composition close did not begin, ~1.1s) before making any change.
  • After the fix: 50/50 consecutive runs passing, average 1989ms/run, no run within 3x of the 10s safety-net timeout.
  • Full host-kernel.test.ts suite: 60 passed / 5 skipped, one unrelated pre-existing failure (answers an admitted bootstrap with draining after shutdown commits, a Windows named-pipe EPIPE) confirmed via git stash to fail identically without this change - a local Windows-environment issue, not something this PR introduces.
  • npm run lint, npm run format:check, npm run build, npm run typecheck all clean.

Root cause

See Summary above - two timers were sharing one budget: incidental real setup I/O common to every shutdown, and the deliberately-stuck close() this test simulates. Under CI load the former could consume the whole 100ms before the latter was ever reached.

AI use

  • No generative tool made a substantive contribution
  • Generative tooling made a substantive contribution

Tool(s) and scope: Claude (Anthropic, Claude Code) diagnosed the root cause by tracing the kernel's shutdown sequence, designed and implemented the fake-timer fix, and ran the verification above, under a human contributor's step-by-step review and approval at each stage (diagnosis, design, and implementation were each checkpointed before proceeding). Generated-by trailer added to the commit.

Checklist

  • Tests cover the change and fail without it (verified via git stash against the unmodified test)
  • Lint, format, typecheck and the affected suites pass locally

Does this PR entail a change in behavior?

  • Yes
  • No - test-only change; kernel production code is untouched

@Astro-Han Astro-Han left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I reviewed this head and found no blocking issues.

Fixes flaky startup-failure deadline test with fake timers isolating deadline from I/O jitter; no product code change.

No P0-P3. Note: exact head currently has no hosted checks — needs CI green before merge.

简体中文该头无阻断,待 CI。

Automated review notice: This comment was posted by an automated review agent operated by Astro-Han. It is not an independent human review and does not replace one.

@M4n5ter
M4n5ter force-pushed the test/fix-flaky-startup-shutdown-deadline-test branch 2 times, most recently from 91964e0 to e84191f Compare August 26, 2026 09:57
@github-actions github-actions Bot added the effort/S Under 100 readable lines label Aug 27, 2026

@Astro-Han Astro-Han left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Heads-up before you spend more time on this: #3844 landed a few minutes ago as another fix for #3840, and this branch now conflicts with main. That is my miss — I merged it without noticing this PR was open against the same issue. I do not want to just close this one, because your diagnosis finds something #3844 does not fix.

I read host-kernel.ts:844-905 to compare the two, and I think there are two distinct failure modes here, not one:

Mode A — what #3844 fixes. withTimeout(closeEntered, 1_000, …) starts counting after RuntimeHostKernel.start() is called but not awaited, so the whole startup chain — storage-root resolution, owner acquisition, listener setup, composition factory, requestDrain(), the recover throw — runs inside that one-second window. On a loaded runner that chain alone can exceed 1s while shutdown itself stays well inside its 100ms grace. The 1053ms/1080ms failures reported on the issue fit this shape exactly, and widening the budget genuinely fixes it.

Mode B — what you found, and what #3844 does not touch. #closeResources() calls #assertShutdownCanContinue() four times before it ever reaches this.#composition?.close() — after #publishRegistration(), after the bounded operation/handshake drain, after await operationDrain, and after await this.#compositionStartup. The deadline timer is armed at shutdownGraceMs, which this test sets to 100ms. If that pre-close bookkeeping — and #publishRegistration() is a filesystem write — exceeds 100ms, #terminationRequired is already set and the next assert throws, so close() is never invoked and markCloseEntered() never runs. closeEntered then never resolves at all, and a 5s budget fails with the same composition close did not begin message that a 1s budget did, just five seconds later.

So #3844 is a correct fix for A and a no-op for B. Your t.mock.timers approach covers both: awaiting the real close signal and then deterministically ticking the deadline forward reproduces the intended scenario — close() genuinely in progress when the grace elapses — regardless of how loaded the machine is. That is the stronger fix and I would like it in.

Could you rebase onto main? The conflict should be mechanical: #3844 only widened the two withTimeout budgets you are replacing anyway, so taking your version of that block and dropping the budget-widening comment should resolve it. If you would rather keep the 5s budgets as belt-and-braces alongside the fake timers, that is fine, but say so in the body so the next reader knows the widening is deliberate redundancy and not a leftover.

One thing I want you to address when you rebase, since I could not settle it from the diff alone: t.mock.timers replaces the timer functions process-wide for the test, and #closeResources() also depends on waitForBoundedCompletion(operationDrain, SHUTDOWN_OPERATION_GRACE_MS) and waitForTransportClose(handshaking, SHUTDOWN_HANDSHAKE_GRACE_MS). Please confirm those two bounded waits still complete via their underlying promises rather than via a timer that will now never fire on its own — and if they do rely on the timer, that the single tick(100) is enough to release them. A hang there would trade an intermittent failure for an intermittent hang, which is worse.

AI use: Claude Code (Opus) read #closeResources and #armShutdownDeadline in packages/runtime-host/src/server/host-kernel.ts and derived the two failure modes above from the placement of the #assertShutdownCanContinue() calls relative to composition.close(). Neither mode was reproduced on a loaded runner. The reviewer of record reviewed and accepted this reasoning.

简体中文

先说明情况:#3844 几分钟前已合并,同样是修 #3840,这个分支现在与 main 冲突了。这是我的疏忽——合并时没注意到本 PR 针对同一 issue。但我不想直接关掉它,因为你的诊断发现了 #3844 没有修到的东西。

我读了 host-kernel.ts:844-905 对比两者,认为这里其实有两种不同的失败模式

模式 A —— #3844 修的。 withTimeout(closeEntered, 1_000, …)RuntimeHostKernel.start() 被调用(但未 await)之后开始计时,因此整条启动链——存储根解析、owner 获取、listener 建立、composition 工厂、requestDrain()recover 抛错——都在这一秒窗口内。高负载 runner 上仅这条链就可能超过 1s,而 shutdown 本身仍稳稳在 100ms 宽限内。issue 中报告的 1053ms/1080ms 正符合这个形状,放宽预算确实能修。

模式 B —— 你发现的,#3844 完全没碰。 #closeResources() 在真正走到 this.#composition?.close() 之前调用了四次 #assertShutdownCanContinue()#publishRegistration() 之后、有界的 operation/handshake drain 之后、await operationDrain 之后、await this.#compositionStartup 之后。deadline 定时器按 shutdownGraceMs 布防,本测试设为 100ms。若这些前置记账——而 #publishRegistration() 是一次文件写——超过 100ms,#terminationRequired 已置位,下一个断言就抛出,于是 close() 根本不会被调用,markCloseEntered() 也不会执行。此时 closeEntered 永远不 resolve,5s 预算会以与 1s 预算完全相同的 composition close did not begin 失败,只是晚五秒。

所以 #3844 对 A 是正确修复,对 B 是空操作。你的 t.mock.timers 方案两者都覆盖:先等真实的 close 信号,再确定性地把 deadline 推进,无论机器多忙都能复现真正想测的场景——宽限到期时 close() 确实正在进行中。这是更强的修法,我希望它进来。

能否 rebase 到 main?冲突应该是机械的:#3844 只是放宽了你本来就要替换掉的那两处 withTimeout 预算,取你的版本并去掉那段放宽预算的注释即可。若你想在 fake timer 之外保留 5s 预算作为双保险也可以,但请在正文里说明,让后来者知道这份冗余是刻意的而非残留。

rebase 时请顺带回答一个我从 diff 里定不下来的问题:t.mock.timers 会在该测试内进程级替换定时器函数,而 #closeResources() 还依赖 waitForBoundedCompletion(operationDrain, SHUTDOWN_OPERATION_GRACE_MS)waitForTransportClose(handshaking, SHUTDOWN_HANDSHAKE_GRACE_MS)。请确认这两处有界等待仍靠底层 promise 完成,而不是靠一个现在再也不会自行触发的定时器;如果确实依赖定时器,请确认单次 tick(100) 足以释放它们。那里若挂住,就是把间歇性失败换成了间歇性挂起,更糟。

@Bryandero98

Copy link
Copy Markdown
Author

Rebased onto main. The conflict was mechanical as expected: took the t.mock.timers block, kept the two withTimeout wrappers around closeEntered/startupFailure as deliberate redundancy rather than dropping them, with a comment (host-kernel.test.ts:1478-1484) explaining they no longer tolerate real jitter and exist only to fail fast with a named error if the kernel regresses.

Bounded waits, confirmed: waitForBoundedCompletion(operationDrain, SHUTDOWN_OPERATION_GRACE_MS) and waitForTransportClose(handshaking, SHUTDOWN_HANDSHAKE_GRACE_MS) (host-kernel.ts:880-883) each race the real task promise against an internal setTimeout. t.mock.timers.enable({ apis: ['setTimeout'] }) does patch that internal setTimeout too (it's the bare global, not a node:timers import). In this test neither grace timer needs to fire: operationDrain resolves through #waitForOperations() with zero active operations, and handshaking is empty (waitForTransportClose short-circuits at transports.length === 0 before creating a timer, host-kernel.ts:959) since no client ever connects. Both resolve via their real promise path before the single tick(100) runs. Ran the test 20 consecutive times after the rebase — 20/20 pass, ~7s each. tsc --noEmit clean.

One thing worth flagging for whoever edits this test next: since the mock patches setTimeout process-wide, a future variant of this test that leaves a pending operation or handshaking transport at shutdown time would need its own explicit tick(1000) for those grace periods — today's scenario doesn't hit that path, so it's not a problem now, just a latent trap.

Can't push the rebased branch yet: it now carries main's own unrelated .github/workflows/ci.yml updates (from commits between our old base and current main), and GitHub blocks the push without a workflow-scoped token. Sorting that out on our end; will push as soon as it's resolved.

@Bryandero98

Copy link
Copy Markdown
Author

Status update: the rebase and fix described above are complete and verified locally (20/20 test runs passing, tsc --noEmit clean), but I can't push the branch update yet - it now carries main's own unrelated .github/workflows/ci.yml changes (from commits between our old base and current main), and pushing requires a workflow-scoped token, which the one I'm using doesn't have. Sorting that out on our end.

Since "Allow edits from maintainers" is enabled on this PR, a maintainer with the right token scope could pull Bryandero98:test/fix-flaky-startup-shutdown-deadline-test and push the rebase directly if that's faster than waiting on us. Otherwise we'll push as soon as the token is sorted - just flagging so this isn't mistaken for stalled work.

@Bryandero98
Bryandero98 force-pushed the test/fix-flaky-startup-shutdown-deadline-test branch from e84191f to 0dc0074 Compare August 27, 2026 05:43
…mers (apache#3840)

The "startup failure preserves its cause when shutdown reaches the
active deadline" test in host-kernel.test.ts raced a real 100ms
shutdownGraceMs deadline against real I/O that #closeResources() must
perform before it ever calls composition.close() (registration writes,
listener admission close, storage-root identity re-validation). On a
loaded runner that pre-close bookkeeping alone can exceed 100ms,
causing #assertShutdownCanContinue() to abort the shutdown sequence
before composition.close() is ever invoked. closeEntered then never
resolves, and the test fails with "composition close did not begin" -
a false negative, since the kernel is behaving exactly as designed.

Fix: enable node:test's built-in mock timers (already used elsewhere
in this package, see gitoxide-helper-invocation-internal.test.ts) right
before starting the kernel, await the real, un-timed signal that
close() was actually entered, and only then deterministically tick the
100ms deadline forward. This reproduces the intended scenario - close()
genuinely stuck when shutdownGraceMs elapses - without racing real
wall-clock jitter, and without touching any kernel production code.

apache#3844 fixed the same reported flakiness by widening the two
withTimeout budgets this replaces, but that only tolerates a slow
startup chain before close() is invoked - it does not touch the
scenario above, where close() is invoked but assertShutdownCanContinue
aborts before it can return. Rebased onto main after apache#3844 merged;
kept its widened 5s budgets wrapping closeEntered/startupFailure as
deliberate redundancy, not a leftover - fake timers remove the jitter
they were tolerating, so they now exist only to fail fast with a named
error if this test ever regresses, instead of the generic message from
the outer 10_000ms test timeout.

Verified: 20/20 consecutive runs passing after the rebase, tsc --noEmit
clean.

Generated-by: Claude (Anthropic, Claude Code)
@Bryandero98
Bryandero98 force-pushed the test/fix-flaky-startup-shutdown-deadline-test branch from 0dc0074 to 8d9b9d9 Compare August 27, 2026 05:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

effort/S Under 100 readable lines

Projects

None yet

Development

Successfully merging this pull request may close these issues.

test(runtime-host): flaky 'startup failure preserves its cause when shutdown reaches the active deadline'

2 participants