fix(cli): report functions serve outcomes from real container state (CLI-2426) - #6594
fix(cli): report functions serve outcomes from real container state (CLI-2426)#6594Prashansa-K wants to merge 10 commits into
Conversation
There was a problem hiding this comment.
🤖 AI Review
Both independent reviews completed. After verification, all 11 deduplicated findings are confirmed: one major false-success path, four runtime/error-handling issues, one stale compatibility contract, and five test/comment maintainability nits.
Findings
| Severity | Location | Category | Sources | Claim |
|---|---|---|---|---|
| 🟠 MAJOR | apps/cli/src/shared/functions/serve.ts:1327 |
correctness |
codex | A clean docker logs -f exit can make the command treat a still-running container as gracefully stopped because it checks only .State.ExitCode, which is also zero while a container is running. |
| 🟡 MINOR | apps/cli/src/shared/functions/serve.ts:1332 |
telemetry-classification |
claude | Every inspected non-zero container exit except 137 is classified as an internal runtime_crash, including signal-derived exits such as 143 that can result from an external docker stop. |
| 🟡 MINOR | apps/cli/src/shared/functions/serve.ts:1981 |
race-condition |
codex | A filesystem restart arriving during the 50 ms shutdown grace period can win the outer race and suppress a log-stream or container failure that occurred first. |
| 🟡 MINOR | apps/cli/src/shared/functions/serve.ts:1974 |
concurrency |
claude | The shutdown signal is latched only within each log-stream race, leaving gaps between startup, race iterations, and teardown in which a held SIGINT or SIGTERM is discarded. |
| 🟡 MINOR | apps/cli/src/shared/functions/serve.errors.ts:42 |
error-handling |
claude | The daemon-down error advertises a canonical start_docker suggestion to telemetry but carries no user-visible remediation text. |
| 🟡 MINOR | apps/cli/src/commands/functions/serve/SIDE_EFFECTS.md:66 |
documentation |
claude+codex | The compatibility contract omits the new successful exit when the edge-runtime container stops with code zero. |
| ⚪ NIT | apps/cli/src/commands/functions/serve/serve.integration.test.ts:2085 |
test-coverage |
claude | The Ctrl-C regression test does not exercise the grace interval because its queued signal is retained and can resolve the shutdown latch without any delay. |
| ⚪ NIT | apps/cli/src/commands/functions/serve/serve.integration.test.ts:2114 |
maintainability |
claude+codex | The assertion embeds literal ESC control bytes instead of visible Unicode escape sequences. |
| ⚪ NIT | apps/cli/src/shared/functions/serve.ts:127 |
comment-policy |
claude+codex | The new timing and race comments exceed the repository's limit for inline rationale and substantially narrate the implementation. |
| ⚪ NIT | apps/cli/src/commands/functions/serve/serve.integration.test.ts:2048 |
comment-policy |
claude+codex | The test suite name uses an internal ticket identifier as provenance. |
| ⚪ NIT | apps/cli/src/commands/functions/serve/serve.integration.test.ts:2086 |
comment-policy |
claude | The new fixture comment is eight lines long and uses the specifically banned emphasis word exactly. |
Findings outside the diff
- 🟡 MINOR
apps/cli/src/commands/functions/serve/SIDE_EFFECTS.md:66— The compatibility contract omits the new successful exit when the edge-runtime container stops with code zero.
Stats
Claude findings: 7 · Codex findings: 6 · Confirmed: 11 · Refuted: 0 · Uncertain: 0
Models: claude-opus-5 + gpt-5.6-sol · Trigger: auto · Workflow run
This review runs once per PR. A maintainer can request another with a /ai-review comment.
streamContainerLogs treated a container that exited with code 0 as an
error ("container exited gracefully"), which meant a normal edge
runtime shutdown always produced a non-zero functions serve exit. A
clean exit now succeeds instead of failing, letting serveFunctions end
the session normally.
The two remaining genuine failure paths (a container crash with a
non-zero exit code, and an unrecoverable docker logs -f failure) were
bare, untagged Error instances, which is why they carried no
error_fingerprint in telemetry and fell into the catch-all
error:unknown bucket. They are now Data.TaggedError classes
(EdgeRuntimeContainerCrashedError, DockerLogsStreamError) in a new
serve.errors.ts, each keeping the container id, exit code, and stderr
as fields, and classified through the existing actionability.unknown
preset since an exit code or stderr alone can't attribute a root
cause. The error-tags fixture is regenerated for the two new literals.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Ctrl-C reaches both this process and the un-detached docker logs -f child at once, so the signal arm and a log-stream failure could become ready within microseconds of each other; Effect.raceFirst picks whichever settles first, success or failure, so a coin flip decided whether functions serve exited 0 or 1 on a normal Ctrl-C. A Deferred, completed by a background fork of awaitSignal that outlives the race's own decision, now latches once a shutdown signal is observed. A log-stream failure races that latch against a short grace period instead of failing immediately: if the latch is already set, or becomes set within the grace period, the failure is downgraded to the same shutdown outcome Ctrl-C already produces. A genuine crash with no pending signal still fails, just after the same bounded grace period. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Adds the four termination-path cases for CLI-2426: SIGINT racing a concurrent log-stream failure now exits 0 with the usual "Stopped serving" message (the regression test — reliably fails without the shutdown latch, verified by temporarily reverting it); a container crash with a non-zero exit code still fails with the new tagged EdgeRuntimeContainerCrashedError; a graceful container exit (code 0) now ends the session normally; and a container that never starts still fails as before. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…stream DockerLogsStreamError is introduced by this branch, so it has no telemetry history yet. Classifying it now rather than in a follow-up keeps the tag's meaning stable for its whole life: if the declaration landed in a later release, tag:DockerLogsStreamError would report error_category unknown on some CLI versions and docker_not_running on others, splitting the category history of a single fingerprint. The daemon-unreachable decision is made in streamContainerLogs, where docker's stderr is produced, and carried as a daemonDown flag so consumers never inspect message text — the convention DockerRunError already documents. Detection reuses the shared isDockerDaemonUnreachable predicate, which serve.ts already imports, rather than adding a second copy of the heuristic. Failures that are not daemon-unreachable keep actionability.unknown: an exit code and an arbitrary stderr string do not identify a root cause, and guessing one would understate the counter-metric. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…failures A runtime the CLI launches and supervises can die on its own. That is our bug, but no existing category said so: `panic` means the CLI threw and `impossible_state` means a should-never-happen branch was reached, so these failures were reported as `unknown` kind and category. Add `runtime_crash` under the `internal_bug` kind and classify `EdgeRuntimeContainerCrashedError` with it. The edge runtime's own worker bootstrap converts user function failures into HTTP 503/500 responses without exiting, so a container that actually exits non-zero is not the user's code — it is the runtime or the image we ship. This moves volume out of `unknown` and into the internal-bug counter metric. That reading is worse and correct: these failures were always ours, only mis-filed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
`docker logs -f` can exit 0 while the container is still running, so inspecting only `.State.ExitCode` let a healthy container be torn down and reported as a clean exit. Inspect `.State.Running` alongside the exit code and re-attach the stream instead. Hoist the shutdown latch and its listener fiber to the loop's lifetime so a signal arriving between the startup race and a log-stream race is not dropped, and move the grace-period arbitration outside the outer race so a watched-file restart cannot suppress a failure that already settled. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…l-bug counter Every non-137 container exit was classified `runtime_crash`, an internal bug. Exits from a supervisor's termination signal (`docker stop`, `supabase stop`) are not our bug, so route 129, 130, 131, and 143 to `cancelled`. Crash signals such as SIGSEGV and SIGABRT stay `runtime_crash`, since those are the runtime failing on its own. Also surface the Docker install suggestion on a daemon-down log-stream failure, which previously told telemetry a remediation was offered while the user saw none. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
9103be5 to
85acdb0
Compare
Coly010
left a comment
There was a problem hiding this comment.
Verdict: Request changes. The mechanical pieces here are good and I want most of them merged — the hoisted Deferred, the tagged errors, exit 0 on a clean container exit, daemonDown. What I can't approve is the root-cause story: it only holds on Windows, and the telemetry the PR cites points at a different bucket that this PR leaves untouched.
1. The docker logs -f child is not in the CLI's process group on macOS/Linux
The PR body and serve.ts:127 say spawnContainerCli never passes detached, so the child shares the process group and one Ctrl-C hits both arms. The spawner's default is the opposite:
// @effect/platform-node-shared/dist/internal/nodeChildProcessSpawner.js
const detached = options.detached ?? platform !== "win32";Verified empirically on Bun 1.3.14 through BunServices.layer with the same options object streamContainerLogs passes ({ stdin: "ignore", stdout: "pipe", stderr: "pipe", extendEnv: true }):
{"via":"effect-spawner-default","childPgid":"5118","parentPgid":"5091","sameGroup":false}
{"via":"effect-spawner-detached-false","childPgid":"5091","parentPgid":"5091","sameGroup":true}
A detached child is in its own session, so the tty's SIGINT never reaches it. The race this PR arbitrates with a 50 ms sleep cannot occur on macOS/Linux — and the codebase already knows this: go-proxy.layer.ts:180-183 sets detached: false precisely so Ctrl-C does reach the Go child. On Windows the default flips to detached: false and CTRL_C_EVENT goes to every console-attached process, so there the race is real.
2. What the 30-day telemetry actually shows for functions serve
cli_command_executed, current versions only (2.116.0 + 2.117.0), os × outcome:
| os | outcome | runs | devices | p50 duration | p90 | in a TTY |
|---|---|---|---|---|---|---|
| darwin | success | 41,446 | 4,454 | 41.9 s | 2,105 s | 12% |
| darwin | error:unknown |
40,811 | 2,792 | 0.0 s | 48.5 s | 4% |
| linux | error:unknown |
406,963 | 11,059 | 0.1 s | 0.3 s | 0.2% |
| linux | success | 32,322 | 17,924 | 24.7 s | 504 s | 4% |
| win32 | error:unknown |
11,639 | 3,432 | 141.6 s | 12,394 s | 22% |
| win32 | success | 345 | 111 | 279.8 s | 7,391 s | 99% |
- On macOS/Linux the unknown failures die in well under a second and almost never in a TTY. Those are startup failures, not Ctrl-C. The only sub-second path that runs on every invocation and fails with a bare
ErrorisassertLocalDbRunning—serve.ts:1388(supabase start is not running.) and:1400-1401(failed to inspect service: …, including the daemon-down branch). That is most likely the bucket CLI-2426 is actually about, and this PR doesn't tag it. (Inferred from timing — the fingerprint carries no message — but two tagged errors there would settle it in a week of data.) - The fingerprint a signal-killed
docker logschild would leave (tag:PlatformError:platform_error—exitCodefails oncode === null) appears 34 times on darwin in 30 days, against ~88kerror:unknown. - Windows is the one platform whose unknowns are long-lived sessions, consistent with the race as described. It is ~3% of runs.
3. What this means for the PR
Keep the mechanism; fix the explanation and close the gap the data points at:
serve.ts:127,serve.integration.test.ts:2086and the PR body should describe a Windows console-signal tie-break. If the 50 ms grace stays for Windows (harmless elsewhere), apply it to the startup race too — a Windows user sits on Ctrl-C duringdocker pull, not during log streaming.- Tag the two
assertLocalDbRunningfailures (auser_actionable"runsupabase start" and the existingdockerNotRunningpreset) — here or in a follow-up opened before this merges. Without them the KPI-1 goal in CLI-2426 doesn't move. - The inline items below: the duplicated
inspectContainerState, the re-attach log replay, the 143/cancelledinconsistency, the wrong Docker suggestion text, and the SIDE_EFFECTS drift.
Stress-tested the two timing tests locally: 8 unloaded runs plus 6 under 2× CPU saturation, all green. Nice work on the Deferred hoist — that was a real dropped-signal bug.
`streamContainerLogs` decided the daemon was unreachable, and whether a stream failure was retriable, by substring-matching the tail of the container's own logs — arbitrary user function output. Both decisions now come from a follow-up `docker container inspect`, which is Docker's output alone, so a function that logs "no such container" can no longer flip a fatal failure into an endless retry. Reuse the shared `inspectContainerState` rather than a same-named private copy that parsed a different wire format and failed with bare `Error`s: a container removed between the log stream ending and the inspect now ends the session instead of reporting raw Docker text as an unclassified failure. Supervisor teardown codes (129/130/131/143) end the session successfully with their own message; real crash signals still fail as `runtime_crash`. A clean container exit prints a line distinct from the user-initiated shutdown so scrollback can tell the two apart. Re-attaches resume with `--since` instead of replaying the whole log history, are capped, and run in their own scope so child handles no longer accumulate for the session. The local-database pre-flight failed with bare `Error`s, so the check that runs on every invocation reported no category at all. It now carries tagged identities: a missing stack suggests `supabase start`, an unreachable daemon suggests starting Docker. The shutdown grace period only guarded the log-stream race, leaving the startup race — where a cold image pull is most likely to meet a Ctrl-C — to lose the same coin flip. Both races now share one helper, and the grace and retry timers are injectable so their tests no longer race a real clock. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
TL;DR
supabase functions servereported almost every session as a failure, and almost none of those failures carried a usable classification. This makes the command report what actually happened.Refs CLI-2426
What was wrong
Outcomes that were not failures were reported as failures. A container that stopped on its own with exit
0was returned asEffect.fail. A container torn down by a supervisor —supabase stopin another terminal stops every project container — exited143and was charged to the internal-bug counter. Both are ordinary ways for a serve session to end.Decisions were made from the wrong source.
streamContainerLogsjudged whether the Docker daemon was reachable, and whether a stream failure was retriable, by substring-matching the tail of the container's own logs. That text is arbitrary user function output: a function logging "Cannot connect to the Docker daemon" earned a Docker suggestion, and one logging "no such container" could turn a fatal stream failure into an endless retry. A privateinspectContainerStateshadowed an existing shared helper, parsed a different wire format, and failed with bareErrors.A clean
docker logs -fexit was read as a stopped container. The code checked only.State.ExitCode, which is also0while a container runs, so a daemon that closed the stream underneath a healthy runtime got it torn down and reported as a graceful stop.The check that runs on every invocation carried no classification.
assertLocalDbRunningfailed with bareErrors. Those have no tag and no actionability declaration, so they fall through tounknown— which is most of what this command's failures looked like in telemetry.The shutdown race is real, but only on Windows. The Effect spawner defaults to
detachedoff Windows andspawnContainerClinever overrides it, so thedocker logs -fchild runs in its own session and never receives the terminal's SIGINT — the two arms of the race cannot become ready together there. On Windows the default flips andCTRL_C_EVENTreaches every console-attached process, so the tie-break does matter. An earlier revision of this description had that backwards.What changed
Container state decides the outcome.
streamContainerLogsinspectsRunningandExitCodetogether through the sharedinspectContainerState, and re-attaches when the container is still alive. A container that has already been removed ends the session instead of surfacing raw Docker text.Ordinary endings end ordinarily. Exit
0and the supervisor-teardown codes (129/130/131/143) end the session successfully, each with its own message so scrollback can tell "I stopped it" from "the runtime walked out". Real crash signals still fail asruntime_crash.137keeps its existing retry.Classification comes from Docker's own output.
daemonDownand the retry/fatal decision are derived from a follow-updocker container inspect, never from the log tail. No container log text is emitted to telemetry.The failure paths carry tagged identities — including the local-database pre-flight, which is the check every invocation runs: a missing stack suggests
supabase start, an unreachable daemon suggests starting Docker. A daemon that dies mid-session now says "start Docker" rather than "install Docker Desktop", which is what it said before despite having just created and started a container.Re-attaches are bounded. They resume with
--sinceinstead of replaying the container's whole log history, are capped, and run in their own scope so child handles stop accumulating for the session.Shutdown is latched once for the loop's lifetime, so a signal arriving between races is not dropped, and the grace period guards both the startup race and the log-stream race — a cold image pull is where a Windows user is most likely to reach for Ctrl-C. Both timers are injectable, so their tests do not race a real clock.
New
runtime_crashcategory. A runtime we launch and supervise can die on its own;panic(the CLI threw) andimpossible_state(unreachable branch) don't describe that, so these were filed asunknown. Note this makes the internal-bug counter-metric go up. That reading is worse and correct: those failures were always ours, just mis-filed.Known gaps, deliberately not here
137is still swallowed by a retry loop. The container has no--restartpolicy. Filed separately.gen typeshas the same untagged local-stack pre-flight failure. Filed separately.time_to_ready_msforfunctions serve— next PR.🤖 Generated with Claude Code