trace cache: after a hand-off with no action, endWaitMs counts the replay wait and the executor, and grows to 120 s

[oliverfried-zoa]

What happened

After a hand-off that the executor settles without acting, the trace cache saves an endWaitMs that includes the end wait of the failed replay and the whole run of the executor. The next replay waits that long, so the value grows in each run until it reaches MAX_TRACE_END_WAIT_MS (120 s). From then on, each hand-off of that step waits 120 s before the executor starts.

The cause is in dist/agent/step-cache.js, StepTraceSession.stage():

endWaitMs: Date.now() - (recorder.lastActionAtMs ?? this.startedMs) + END_WAIT_MARGIN_MS,

When the replay ends with end-mismatch and the executor then passes the step with no action (the comment on conclude() says this re-stages, "so it heals"), recorder.lastActionAtMs is the last replayed action. The time from that action to stage() contains:

1. the end wait of the replay itself (the old endWaitMs),
2. the run of the executor (model calls, observes),
3. the margin of 10 s.

So endWaitMs(n+1) ≈ endWaitMs(n) + executor time + 10 s, capped at 120 s. The comment on that line says the measure starts at the last action so that "the model's thinking time ... is no reason for a replay ... to wait", but after a hand-off the model's time comes after that action and is counted.

Expected: after a hand-off, the end wait measures the app, not the replay wait and the executor. Counting from the moment of the hand-off fixes it in my setup:

     handOff(outcome, stopReason) {
+        this.handedOffAtMs = Date.now();
         if (stopReason === 'end-mismatch')
@@
-            endWaitMs: Date.now() - (recorder.lastActionAtMs ?? this.startedMs) + END_WAIT_MARGIN_MS,
+            endWaitMs: Date.now() - Math.max(recorder.lastActionAtMs ?? this.startedMs, this.handedOffAtMs ?? 0) + END_WAIT_MARGIN_MS,

This still counts the run of the executor after the hand-off, but it stops the growth. A tighter fix could measure only up to the first observation of the executor.

Minimal reproduction

// Any act whose end screen differs between runs, so that each replay ends in `end-mismatch`
// and the executor passes the step without acting. For example, a list that other tests
// add rows to while this test runs.
test('a goal whose end screen changes in each run', async ({ app, agent, screen }) => {
  await app.open('/');
  await agent.act('open the list of orders');
  await expect(screen.getByRole('heading', 'Orders')).toBeVisible();
});

This is a sketch, not a tested repro. Run it several times with the default read-write cache, and read endWaitMs in the entry of the step in .e2e/cache/. By the formula above, it grows in each run until it stays at 120000. I did not record the growth run by run; I found 8 entries at 120000 in a cache of 26 tests, and a handed-off step then took about 120 s plus the executor time.

Versions

e2e 0.15.0, @e2e-dev/web 0.11.0, node 22.23.3. The same line is in e2e 0.17.0 (dist/agent/step-cache.js:499).

Engine

not engine specific

Anything else

Seen with a custom StepExecutor (it runs the claude CLI); the cause does not depend on the executor. In a suite of 26 tests, the cache had 8 entries at endWaitMs: 120000. In --debug, one handed-off step took 126.1 s: model 4.0 s, observe 3.0 s, action 0.1 s. With the patch above, the median endWaitMs fell to about 16 s, and a cached run of the suite fell from 6 min 51 s to 1 min 35 s.