Files
coder/cli/task_send_test.go
T
Jake Howell 0c3c65d85b fix: stabilize latest workspace app status ordering (DEVEX-381) (#27041)
> 🤖 This PR was written by Coder Agents on behalf of Jake Howell.

Closes
[DEVEX-381](https://linear.app/codercom/issue/DEVEX-381/flake-test-tasksendwaitsforworkingappstate).
Follow-up to #25648 and #25858, which addressed a different symptom of
the same test.

## Symptom

```
task_send_test.go:348: context expired while waiting for trap: context deadline exceeded
--- FAIL: Test_TaskSend/WaitsForWorkingAppState (26.02s)
```

Windows-only, on `test-go-pg (windows-2022)`. Reported four times since
#25648 landed (2026-06-02, 2026-06-10, 2026-07-01).

## Root cause

The test:

1. `setupCLITaskTest` inserts `workspace_app_status(state=idle)` at the
end of setup.
2. `WaitsForWorkingAppState` then inserts
`workspace_app_status(state=working)` before starting the CLI.
3. Both are persisted via `dbtime.Now()`, which rounds to microseconds.
Windows `time.Now()` resolution is coarser than that (often ~1 ms or
worse), so back-to-back calls frequently round to the same microsecond.
4. `GetLatestWorkspaceAppStatusesByWorkspaceIDs` has no tiebreaker:

   ```sql
   ORDER BY workspace_id, created_at DESC
   ```

Its sibling `GetLatestWorkspaceAppStatusByAppID` already uses `ORDER BY
created_at DESC, id DESC` for exactly this reason. When the two rows
collide, Postgres picks either.
5. On the failing runs, the query returned the `idle` row.
`waitForTaskIdle` saw idle on the first poll, returned nil, `TaskSend`
proceeded, and the CLI completed successfully in ~5 s.
6. But the test was blocked at `resetTrap.MustWait(ctx)` waiting for a
**second** `ticker.Reset` that never happened. `WaitLong = 25s` elapsed,
line 348 failed.

CI log confirms the sequence: only one `Ticker.Reset(5s)` is caught,
then `Ticker.Stop([]) call, matched 0 traps` (from `defer
ticker.Stop()`), then the trap wait times out.

This is the same class of flake Spike documented in #15923 and #21332
("Windows in particular doesn't have high-resolution timers"), just
hidden behind a SQL `ORDER BY`.

## Fix

Two changes:

1. **`coderd/database/queries/workspaceapps.sql`**: add an `id DESC`
tiebreaker to `GetLatestWorkspaceAppStatusesByWorkspaceIDs`, matching
`GetLatestWorkspaceAppStatusByAppID`. Makes the query deterministic when
`created_at` collides.
2. **`cli/task_test.go` / `cli/task_send_test.go`**: add a
`withoutInitialAppStatus()` option to `setupCLITaskTest` and use it from
`WaitsForWorkingAppState`. The test now inserts a single `working` row,
so the collision cannot happen in the first place. Belt-and-braces with
change 1.

Comments in both places reference DEVEX-381 and #21332 so the next agent
doesn't have to re-derive this.

## Verification

- `go test ./cli -run 'Test_TaskSend' -count=1`: all 12 subtests pass,
`WaitsForWorkingAppState` completes in ~5.6 s (was ~16 s previously due
to a longer poll loop).
- Stress: 20 sequential runs of `WaitsForWorkingAppState` on Linux,
race-enabled binary, all pass in ~5.5 s each.
- `go test ./coderd -run 'AppStatus|Task' -count=1` passes.
- `go vet ./coderd/database/... ./cli/...` clean.
- `make lint/emdash` clean.
- `gofmt` clean.

Not reproducible on Linux (real time between the two patches is orders
of magnitude larger than microsecond); the Windows path is fixed by
making the ordering deterministic and by not creating the collision in
the first place.

<details>
<summary>Implementation plan & decision log</summary>

### Investigation

1. Pulled the failing job log for run `28483879823/job/84428355669`.
2. Traced the mock-clock trap sequence: one `NewTicker` and exactly one
`Ticker.Reset(5s)` were caught, then `Ticker.Stop([]) call, matched 0
traps` fires (the `defer ticker.Stop()` on `waitForTaskIdle` return).
This proves `waitForTaskIdle` returned after a single poll, not that the
trap machinery hung.
3. The command exited with `<nil>` (`clitest.go:299: command "coder task
send" exited with error: <nil>`) and a `POST /send` completed in 5.4 s.
So the CLI succeeded; the test's own trap wait is what timed out.
4. The only `waitForTaskIdle` return-nil paths are `Active +
CurrentState.State in {Idle, Complete, Failed}` and `Active +
CurrentState == nil past 30s grace`. First observation of nil cannot be
past 30s. So `TaskByID` must have returned `State == Idle`.
5. Traced `TaskByID` → `taskGet` → `workspaceData` →
`GetLatestWorkspaceAppStatusesByWorkspaceIDs`. Found the missing
tiebreaker; the sibling query one line above
(`GetLatestWorkspaceAppStatusByAppID`) already had it.
6. Confirmed the two `PATCH /app-status` calls in the Windows log
happened at `00:26:13.077` and `00:26:13.093`, well within Windows timer
resolution.
7. Confirmed `dbtime.Now()` rounds to microseconds; Windows `time.Now()`
doesn't have that precision, so `Round(time.Microsecond)` on two calls
close together frequently produces equal values.

### Prior art from Spike

- #15923: loosened `HeartbeatPeriod * 9/10` to `3/4` for Windows.
- #21332: switched `assert.After` to `assert.NotBefore` because
timestamps can equal on Windows.

Both explicitly cite "Windows doesn't always have high-resolution timers
available."

### Considered alternatives

- **Only fix the test.** Works today but leaves the SQL query
non-deterministic; another test that relies on
`GetLatestWorkspaceAppStatusesByWorkspaceIDs` could hit the same
collision.
- **Only fix the SQL query.** Would give a stable answer but not
necessarily the *right* one. If both patches share a `created_at`, `id
DESC` picks whichever UUID sorted higher, still random with respect to
insertion order.
- **Make `dbtime.Now()` monotonic per process.** Cleanest at the source,
but affects every timestamp in the database and has broader implications
than a targeted flake fix.

Going with both the query fix (defense in depth, matches existing
pattern) and the test fix (eliminates the collision at the source) is
the smallest change that closes the flake and hardens the query.

### Rejected commit-message scopes

Changes touch both `cli/` and `coderd/database/`, so per AGENTS.md the
scope is omitted for the cross-cutting commit and PR title.

</details>
2026-07-14 11:48:31 +10:00

445 lines
16 KiB
Go

package cli_test
import (
"encoding/json"
"net/http"
"strings"
"testing"
"time"
"github.com/google/uuid"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
agentapisdk "github.com/coder/agentapi-sdk-go"
"github.com/coder/coder/v2/agent"
"github.com/coder/coder/v2/agent/agenttest"
"github.com/coder/coder/v2/cli/clitest"
"github.com/coder/coder/v2/coderd/coderdtest"
"github.com/coder/coder/v2/coderd/httpapi"
"github.com/coder/coder/v2/codersdk"
"github.com/coder/coder/v2/codersdk/agentsdk"
"github.com/coder/coder/v2/testutil"
"github.com/coder/coder/v2/testutil/expecter"
"github.com/coder/quartz"
)
func Test_TaskSend(t *testing.T) {
t.Parallel()
t.Run("ByTaskName_WithArgument", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "carry on with the task", "you got it"))
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", setup.task.Name, "carry on with the task")
inv.Stdout = &stdout
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
err := inv.WithContext(ctx).Run()
require.NoError(t, err)
})
t.Run("ByTaskID_WithArgument", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "carry on with the task", "you got it"))
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", setup.task.ID.String(), "carry on with the task")
inv.Stdout = &stdout
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
err := inv.WithContext(ctx).Run()
require.NoError(t, err)
})
t.Run("ByTaskName_WithStdin", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "carry on with the task", "you got it"))
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", setup.task.Name, "--stdin")
inv.Stdout = &stdout
inv.Stdin = strings.NewReader("carry on with the task")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
err := inv.WithContext(ctx).Run()
require.NoError(t, err)
})
t.Run("TaskNotFound_ByName", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitLong)
client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerDaemon: true})
owner := coderdtest.CreateFirstUser(t, client)
userClient, _ := coderdtest.CreateAnotherUser(t, client, owner.OrganizationID)
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", "doesnotexist", "some task input")
inv.Stdout = &stdout
clitest.SetupConfig(t, userClient, root)
err := inv.WithContext(ctx).Run()
require.Error(t, err)
require.ErrorContains(t, err, httpapi.ResourceNotFoundResponse.Message)
})
t.Run("TaskNotFound_ByID", func(t *testing.T) {
t.Parallel()
ctx := testutil.Context(t, testutil.WaitLong)
client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerDaemon: true})
owner := coderdtest.CreateFirstUser(t, client)
userClient, _ := coderdtest.CreateAnotherUser(t, client, owner.OrganizationID)
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", uuid.Nil.String(), "some task input")
inv.Stdout = &stdout
clitest.SetupConfig(t, userClient, root)
err := inv.WithContext(ctx).Run()
require.Error(t, err)
require.ErrorContains(t, err, httpapi.ResourceNotFoundResponse.Message)
})
t.Run("SendError", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendErr(assert.AnError))
var stdout strings.Builder
inv, root := clitest.New(t, "task", "send", setup.task.Name, "some task input")
inv.Stdout = &stdout
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
err := inv.WithContext(ctx).Run()
require.ErrorContains(t, err, assert.AnError.Error())
})
t.Run("WaitsForInitializingTask", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "some task input", "some task response"))
// Close the first agent, pause, then resume the task so the
// workspace is started but no agent is connected.
// This puts the task in "initializing" state.
require.NoError(t, setup.agent.Close())
pauseTask(setupCtx, t, setup.userClient, setup.task)
resumeTask(setupCtx, t, setup.userClient, setup.task)
// When: We attempt to send input to the initializing task.
inv, root := clitest.New(t, "task", "send", setup.task.Name, "some task input")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
inv = inv.WithContext(ctx)
// Use a pty so we can wait for the command to produce build
// output, confirming it has entered the initializing code
// path before we connect the agent.
stdout := expecter.NewAttachedToInvocation(t, inv)
w := clitest.StartWithWaiter(t, inv)
// Wait for the command to observe the initializing state and
// start watching the workspace build. This ensures the command
// has entered the waiting code path.
stdout.ExpectMatch(ctx, "Queued")
// Connect a new agent so the task can transition to active.
agentClient := agentsdk.New(setup.userClient.URL, agentsdk.WithFixedToken(setup.agentToken))
setup.agent = agenttest.New(t, setup.userClient.URL, setup.agentToken, func(o *agent.Options) {
o.Client = agentClient
})
coderdtest.NewWorkspaceAgentWaiter(t, setup.userClient, setup.task.WorkspaceID.UUID).
WaitFor(coderdtest.AgentsReady)
// Report the task app as idle so waitForTaskIdle can proceed.
require.NoError(t, agentClient.PatchAppStatus(ctx, agentsdk.PatchAppStatus{
AppSlug: "task-sidebar",
State: codersdk.WorkspaceAppStatusStateIdle,
Message: "ready",
}))
// Then: The command should complete successfully.
require.NoError(t, w.Wait())
updated, err := setup.userClient.TaskByIdentifier(ctx, setup.task.Name)
require.NoError(t, err)
require.Equal(t, codersdk.TaskStatusActive, updated.Status)
})
t.Run("ResumesPausedTask", func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "some task input", "some task response"))
// Close the first agent before pausing so it does not conflict
// with the agent we reconnect after the workspace is resumed.
require.NoError(t, setup.agent.Close())
pauseTask(setupCtx, t, setup.userClient, setup.task)
// When: We attempt to send input to the paused task.
inv, root := clitest.New(t, "task", "send", setup.task.Name, "some task input")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
inv = inv.WithContext(ctx)
// Use a pty so we can wait for the command to produce build
// output, confirming it has entered the paused code path and
// triggered a resume before we connect the agent.
stdout := expecter.NewAttachedToInvocation(t, inv)
w := clitest.StartWithWaiter(t, inv)
// Wait for the command to observe the paused state, trigger
// a resume, and start watching the workspace build.
stdout.ExpectMatch(ctx, "Queued")
// Connect a new agent so the task can transition to active.
agentClient := agentsdk.New(setup.userClient.URL, agentsdk.WithFixedToken(setup.agentToken))
setup.agent = agenttest.New(t, setup.userClient.URL, setup.agentToken, func(o *agent.Options) {
o.Client = agentClient
})
coderdtest.NewWorkspaceAgentWaiter(t, setup.userClient, setup.task.WorkspaceID.UUID).
WaitFor(coderdtest.AgentsReady)
// Report the task app as idle so waitForTaskIdle can proceed.
require.NoError(t, agentClient.PatchAppStatus(ctx, agentsdk.PatchAppStatus{
AppSlug: "task-sidebar",
State: codersdk.WorkspaceAppStatusStateIdle,
Message: "ready",
}))
// Then: The command should complete successfully.
require.NoError(t, w.Wait())
updated, err := setup.userClient.TaskByIdentifier(ctx, setup.task.Name)
require.NoError(t, err)
require.Equal(t, codersdk.TaskStatusActive, updated.Status)
})
t.Run("PausedDuringWaitForReady", func(t *testing.T) {
t.Parallel()
// Given: An initializing task (workspace running, no agent
// connected). Close the agent, pause, then resume so the
// workspace is started but no agent is connected. The
// command enters waitForTaskIdle directly (initializing
// path), where we verify it handles an external pause.
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, nil)
require.NoError(t, setup.agent.Close())
pauseTask(setupCtx, t, setup.userClient, setup.task)
resumeTask(setupCtx, t, setup.userClient, setup.task)
// Set up mock clock and traps before starting the command.
mClock := quartz.NewMock(t)
tickTrap := mClock.Trap().NewTicker("task_send", "poll")
resetTrap := mClock.Trap().TickerReset("task_send", "poll")
// When: We attempt to send input to the initializing task.
inv, root := clitest.NewWithClock(t, mClock, "task", "send", setup.task.Name, "some task input")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
inv = inv.WithContext(ctx)
stdout := expecter.NewAttachedToInvocation(t, inv)
w := clitest.StartWithWaiter(t, inv)
// Wait for the command to enter the build-watching phase
// of waitForTaskIdle.
stdout.ExpectMatch(ctx, "Waiting for task to become idle")
// Wait for ticker creation and release it.
tickCall := tickTrap.MustWait(ctx)
tickCall.MustRelease(ctx)
tickTrap.Close()
// Fire the first poll. The goroutine calls ticker.Reset
// which the trap catches, freezing the goroutine BEFORE
// client.TaskByID runs. Release it so the first poll
// sees 'initializing' and continues.
mClock.Advance(time.Nanosecond).MustWait(ctx)
resetCall := resetTrap.MustWait(ctx)
resetCall.MustRelease(ctx)
// Fire the second poll. The goroutine is again frozen at
// ticker.Reset by the trap.
mClock.Advance(5 * time.Second).MustWait(ctx)
resetCall = resetTrap.MustWait(ctx)
// While the goroutine is frozen (before client.TaskByID),
// pause the task. The stop build completes, so the DB has
// (stop, succeeded) = 'paused'.
pauseTask(ctx, t, setup.userClient, setup.task)
// Release the trap. The goroutine unfreezes and
// client.TaskByID deterministically sees 'paused'.
resetCall.MustRelease(ctx)
resetTrap.Close()
// Then: The command should fail because the task was paused.
err := w.Wait()
require.Error(t, err)
require.ErrorContains(t, err, "was paused while waiting for it to become idle")
})
t.Run("WaitsForWorkingAppState", func(t *testing.T) {
t.Parallel()
// Given: An active task whose app is in "working" state.
// Skip the default idle status to avoid a timestamp collision.
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "some task input", "some task response"), withoutInitialAppStatus())
// Move the app into "working" state before running the command.
agentClient := agentsdk.New(setup.userClient.URL, agentsdk.WithFixedToken(setup.agentToken))
require.NoError(t, agentClient.PatchAppStatus(setupCtx, agentsdk.PatchAppStatus{
AppSlug: "task-sidebar",
State: codersdk.WorkspaceAppStatusStateWorking,
Message: "busy",
}))
// Set up mock clock and traps before starting the command.
mClock := quartz.NewMock(t)
tickTrap := mClock.Trap().NewTicker("task_send", "poll")
resetTrap := mClock.Trap().TickerReset("task_send", "poll")
// When: We send input while the app is working.
inv, root := clitest.NewWithClock(t, mClock, "task", "send", setup.task.Name, "some task input")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
inv = inv.WithContext(ctx)
w := clitest.StartWithWaiter(t, inv)
// Wait for ticker creation and release it.
tickCall := tickTrap.MustWait(ctx)
tickCall.MustRelease(ctx)
tickTrap.Close()
// Fire the first poll. The goroutine calls ticker.Reset
// which the trap catches, freezing the goroutine BEFORE
// client.TaskByID runs. Release it so the first poll
// sees "working" and continues.
mClock.Advance(time.Nanosecond).MustWait(ctx)
resetCall := resetTrap.MustWait(ctx)
resetCall.MustRelease(ctx)
// Fire the second poll. The goroutine is again frozen
// at ticker.Reset by the trap.
mClock.Advance(5 * time.Second).MustWait(ctx)
resetCall = resetTrap.MustWait(ctx)
// While the goroutine is frozen (before client.TaskByID),
// transition the app to idle.
require.NoError(t, agentClient.PatchAppStatus(ctx, agentsdk.PatchAppStatus{
AppSlug: "task-sidebar",
State: codersdk.WorkspaceAppStatusStateIdle,
Message: "ready",
}))
// Release the trap. The goroutine unfreezes and
// client.TaskByID deterministically sees "idle".
resetCall.MustRelease(ctx)
resetTrap.Close()
// Then: The command should complete successfully.
require.NoError(t, w.Wait())
})
t.Run("SendToNonIdleAppState", func(t *testing.T) {
t.Parallel()
for _, appState := range []codersdk.WorkspaceAppStatusState{
codersdk.WorkspaceAppStatusStateComplete,
codersdk.WorkspaceAppStatusStateFailure,
} {
t.Run(string(appState), func(t *testing.T) {
t.Parallel()
setupCtx := testutil.Context(t, testutil.WaitLong)
setup := setupCLITaskTest(setupCtx, t, fakeAgentAPITaskSendOK(t, "some input", "some response"))
agentClient := agentsdk.New(setup.userClient.URL, agentsdk.WithFixedToken(setup.agentToken))
require.NoError(t, agentClient.PatchAppStatus(setupCtx, agentsdk.PatchAppStatus{
AppSlug: "task-sidebar",
State: appState,
Message: "done",
}))
inv, root := clitest.New(t, "task", "send", setup.task.Name, "some input")
clitest.SetupConfig(t, setup.userClient, root)
ctx := testutil.Context(t, testutil.WaitLong)
err := inv.WithContext(ctx).Run()
require.NoError(t, err)
})
}
})
}
func fakeAgentAPITaskSendOK(t *testing.T, expectMessage, returnMessage string) map[string]http.HandlerFunc {
return map[string]http.HandlerFunc{
"/status": func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("Content-Type", "application/json")
_ = json.NewEncoder(w).Encode(map[string]string{
"status": "stable",
})
},
"/message": func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("Content-Type", "application/json")
w.WriteHeader(http.StatusOK)
var msg agentapisdk.PostMessageParams
if err := json.NewDecoder(r.Body).Decode(&msg); err != nil {
http.Error(w, err.Error(), http.StatusBadRequest)
return
}
assert.Equal(t, expectMessage, msg.Content)
message := agentapisdk.Message{
Id: 999,
Role: agentapisdk.RoleAgent,
Content: returnMessage,
Time: time.Now(),
}
_ = json.NewEncoder(w).Encode(message)
},
}
}
func fakeAgentAPITaskSendErr(returnErr error) map[string]http.HandlerFunc {
return map[string]http.HandlerFunc{
"/status": func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("Content-Type", "application/json")
_ = json.NewEncoder(w).Encode(map[string]string{
"status": "stable",
})
},
"/message": func(w http.ResponseWriter, r *http.Request) {
if r.Method != http.MethodPost {
http.Error(w, "Method not allowed", http.StatusMethodNotAllowed)
return
}
w.WriteHeader(http.StatusInternalServerError)
_, _ = w.Write([]byte(returnErr.Error()))
},
}
}