Skip to content

fix(cli): use quartz clock in waitForTaskIdle for immediate first poll#25648

Merged
mafredri merged 1 commit into
mainfrom
fix/DEVEX-381
May 25, 2026
Merged

fix(cli): use quartz clock in waitForTaskIdle for immediate first poll#25648
mafredri merged 1 commit into
mainfrom
fix/DEVEX-381

Conversation

@mafredri

@mafredri mafredri commented May 25, 2026

Copy link
Copy Markdown
Member

waitForTaskIdle used time.NewTicker(5s) which delays the first poll by 5 seconds. On slow CI (Windows), this causes context deadline exceeded because the polling budget is too tight.

Two changes:

  1. Use r.clock.NewTicker (quartz) with time.Nanosecond initial interval and Reset(5s) for immediate first poll. Tests inject a mock clock via clitest.NewWithClock for deterministic control.
  2. Rewrite WaitsForWorkingAppState test with quartz traps (NewTicker + TickerReset) for deterministic synchronization instead of racing goroutines. Fix PausedDuringWaitForReady sync point.
Root cause proof

Added fmt.Fprintf instrumentation to waitForTaskIdle logging: function entry time, each ticker fire with elapsed time, task.Status, task.CurrentState (nil or not, .State, .Message), which switch branch was taken, and context cancellation with total poll count.

Normal case (ran go test -v -count=1 -run Test_TaskSend/WaitsForWorkingAppState ./cli/):

[DEBUG] ticker created (5s interval), entering poll loop (elapsed=46.4µs)
[DEBUG] poll #1: ticker fired (elapsed=5.000962288s)
[DEBUG] poll #1: task.Status="active", CurrentState==nil:false, CurrentState.State="idle"
[DEBUG] poll #1: branch=active, state=idle, RETURNING NIL (success)

Poll #1 fires at 5s, sees idle (the test patched to idle before the first tick), returns. Test passes in 5.92s.

Failure reproduction (modified test to use testutil.WaitShort (10s) context and delayed the idle patch by 6s via time.AfterFunc, then ran the same command):

[DEBUG] ticker created (5s interval), entering poll loop (elapsed=98.829µs)
[DEBUG] poll #1: ticker fired (elapsed=5.00054867s)
[DEBUG] poll #1: task.Status="active", CurrentState==nil:false, CurrentState.State="working"
[DEBUG] poll #1: branch=active, state=working, still working, continuing
[DEBUG] context done (elapsed=9.956793257s, polls=1), err=context deadline exceeded

Poll #1 fires at 5s, sees "working" (idle patch delayed). Poll #2 would fire at 10s, but context expires at 9.96s. Only 1 poll occurred; the function never observed "idle".

This matches the CI failure: 26.14s runtime with a 25s context, context deadline exceeded.

dlv confirmation (ran dlv test ./cli/ -- -test.v -test.run Test_TaskSend/WaitsForWorkingAppState, breakpoint at task_send.go:175): breakpoint hit once (hits goroutine(2758):1 total:1), confirming one poll per 5s tick.

Closes https://linear.app/codercom/issue/DEVEX-381

🤖 This PR was created with the help of Coder Agents, and will be reviewed by a human. 🏂🏻

@mafredri mafredri changed the title fix(cli): make waitForTaskIdle poll interval injectable and poll immediately fix(cli): use quartz clock in waitForTaskIdle for immediate first poll May 25, 2026
waitForTaskIdle used time.NewTicker(5s) which delays the first poll
by 5 seconds. Debugger tracing proved the failure mechanism: on slow
CI (Windows), the first poll at 5s sees "working" (idle patch has not
landed due to goroutine scheduling), needs poll #2 at 10s, but the
25s context expires before it fires.

Two changes:

1. Use r.clock.NewTicker (quartz) with time.Nanosecond initial
   interval and Reset(5s) for immediate first poll. Tests inject a
   mock clock via clitest.NewWithClock for deterministic control.
2. Rewrite WaitsForWorkingAppState test with quartz traps
   (NewTicker + TickerReset) for deterministic synchronization
   instead of racing goroutines. Fix PausedDuringWaitForReady
   sync point.

Closes https://linear.app/codercom/issue/DEVEX-381
@mafredri mafredri marked this pull request as ready for review May 25, 2026 15:00
@mafredri mafredri merged commit 7958ad6 into main May 25, 2026
31 checks passed
@mafredri mafredri deleted the fix/DEVEX-381 branch May 25, 2026 16:14
@github-actions github-actions Bot locked and limited conversation to collaborators May 25, 2026
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants