cloudflare / cloudflare/cloudflare-os
executeCode: "Timed out waiting for logs" hides two opposite failures (output lost vs. code never ran); batched tail events are dropped
- Dominant language
- TypeScript
- Stars
- 9.9k
- Forks
- 1.2k
- Avg merge
- 1d 20h
- Merged PRs (30d)
- 107
Description
## Summary
`executeCode` reports **"Timed out waiting for logs from code execution."** and the model receives nothing, in two situations that look identical from the model's side but are opposite underneath:
- **Mode A – the code ran, only the output was lost.** Our backend audit log shows every RPC the sandbox made; the Workshop still threw the timeout.
- **Mode B – nothing ran at all.** For ~14 minutes every `executeCode` in the chat returned the timeout, including one whose whole body was `console.log("logs_ok")`, and the backend audit shows zero RPCs in that window.
Because the error is the same string in both cases, an agent cannot tell "reconcile, the write already happened" from "nothing happened, retry". Guidance we give the model in either direction is wrong half the time, and in Mode A a retry of a write is dangerous.
## Environment
- Self-hosted deployment pinned at `1ef6020` (#275, 2026-08-21). I re-checked `main` at `8727352` (2026-09-03): the relevant code is unchanged (details below).
- Model-independent: reproduced with an OpenAI model behind a shim and with Claude.
- The sandbox code calls a **service binding** (a gatekeeper Worker that relays RPCs to an external HTTP gateway). That gateway keeps an append-only audit log with timestamps, which is how we know whether the sandboxed code actually executed.
## Where it happens
`packages/workshop-backend/src/overseer.ts` (line numbers from `main` @ `8727352`):
- ~8640–8658: after `await entrypoint.run(...)` returns, the code waits at most 5 s for the tail trace (`scheduler.wait(5000)`) and throws `Timed out waiting for logs from code execution.` if it has not arrived. The run's `error` and (since #300) its return value are only ever emitted *through that trace*, so they are lost together with the logs.
- ~10505 (`CodeModeTailLoopback.tail`): `if (events.length != 1) { logger.error("unexpected gadget trace size", …); return; }` – a batched tail delivery is dropped wholesale, which by itself produces Mode A whenever two runs' traces arrive together.
## Evidence
**Mode A (2026-08-27 and 2026-08-28 sessions).** Dozens of timeouts in one afternoon. For each, the backend audit shows the RPC executed normally (5–70 s calls). On 08-27 the model, told the call had timed out, retried a write and duplicated lines in an ERP document; the audit shows both applies.
**Mode B (2026-09-04, 09:33–09:49 local, and again 10:42–10:50).** Sequence, from the chat transcript cross-checked with the backend audit:
1. 09:34:14 – 09:34:37: four `executeCode` runs back to back, each making one ~7 s service-binding RPC. All four succeeded; all four RPCs are in the audit.
2. 09:35 onwards: the fifth run (same shape) → timeout. The model then tried a read (timeout), a different read (timeout), a `CONTEXT.search` (timeout) and finally a run whose only statement was `console.log("logs_ok")` → timeout.
3. The audit has **no entry** for any of those runs. Nothing reached the service binding for 14 minutes.
4. The next user turn (09:49) worked normally; the same RPC that had "timed out" then succeeded on the first try.
The second episode (10:42–10:50) has the same shape: a burst of quick successive runs, then every run in the turn fails, then the next turn is fine. We have no workerd-level visibility, so I can't say whether the dynamic worker was not being loaded, the isolate was wedged, or the binding calls were hanging; only that from the Workshop's side it was reported as the identical trace timeout.
## What would help
1. **Report the outcome through a channel that does not depend on the tail**, e.g. capture console output inside the dynamic worker and return it (with the return value and any exception) from `run()`; keep the tail as a supplement rather than the only source.
2. **In `tail()`, iterate over `events` instead of returning when `events.length != 1`** (match each item to its execution by `executionId`/script name). This alone would remove a large share of Mode A.
3. **When the trace really is lost, return a structured result instead of throwing**: something like `{ executed: true, logsLost: true, error, returnValue }`. The model can then reconcile instead of guessing.
4. **Give Mode B its own error.** If the run never executed (loader failure, isolate not started, binding call never issued), say so; even a distinct string would let agents retry safely.
5. Make the 5 s wait configurable per deployment.
Related: #282 (the `Subrequest depth limit exceeded` failure of binding calls from `executeCode`), which is the other reason our agents cannot rely on reads from inside the sandbox.
I can share the exact audit timestamps and the chat action logs for both days if useful, and I'm happy to test a patch on our deployment.
Contributor guide
Research direction
Read packages/workshop-backend/src/overseer.ts around the executeCode wait at lines 8640–8658 and CodeModeTailLoopback.tail around line 10505. Trace how run errors, return values, and tail events reach the caller, then reproduce the separate output-loss and no-execution cases described in the issue. Done means batched tail events are handled and the caller can distinguish execution outcomes when logs are unavailable.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- typescript
- Domain
- backend
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 55/100