feat(workers logs): add supabase experimental workers logs - #6410
feat(workers logs): add supabase experimental workers logs#6410johnstonmatt wants to merge 5 commits into
supabase experimental workers logs#6410Conversation
Codex Review SummaryThis comment shows the latest Codex review activity on this pull request.
ℹ️ About Codex in GitHubYour team has set up Codex to review pull requests in this repo. Reviews are triggered when you
Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings. |
`status` reports the deployment; nothing reported the runtime. Once `push` succeeded and `status` said `active`, a misbehaving worker was a black box from the CLI. Reads the project's unified logs stream rather than a worker route — there is no worker-scoped log endpoint — via `v1GetProjectLogs`, which the generated client already carries. `--source app|requests|builds` narrows to one of the three streams; without it all three are returned. `--tail` caps the rows. Three things about that endpoint are load-bearing and non-obvious, so they are documented at each site: - **The filter is `log_attributes`, not the `source` column.** Worker rows carry an empty top-level `source`, because the Workers Logflare source is not enrolled as a category in the generic logs path. `where source = 'worker_guest_logs'` matches nothing. The `in (...)` list over the three known streams is therefore a tenancy guard, not a convenience — with `source` empty it is the only thing excluding a non-worker row that happens to carry a `worker` attribute. - **Both timestamp bounds are always sent, spanning under 24h.** One bound alone yields a one-minute window, silently; neither is an outright error; and a span over 24h is clamped to `start + 24h`, which returns an *older* slice than the one asked for rather than a truncated one. - **A failed query can arrive as HTTP 200** with a populated `error`, so the envelope is checked before `result`. The response is decoded against a local schema rather than the generated `V1GetProjectLogsOutput`: that schema marks `result`/`error` optional but allows neither to be `null`, while the endpoint always sends one of them as an explicit `null`, so decoding any real response against it fails. Rendering is per-stream, because `event_message` differs in kind — on the request stream it is only `"GET /"`, with status and duration in `log_attributes`, so the request line is composed. `severity_text` is ignored: it is `INFO` on every row of every stream, so the level is derived, and guest lines report none rather than a guess. A guest message is tenant-controlled bytes, so escape sequences are stripped before it reaches a terminal while a stack trace's newlines and indentation survive. `mapRequestError`/`unexpectedStatus`/`decodeBody` move out of `workers-api.ts` into `workers-api-status.ts`, unchanged, now that a second seam needs them. The test helper records `urlParams`: `HttpClientRequest` keeps them off the URL, so without this no test could assert the emitted SQL or window.
Matches the only other log-line format this shell prints — the `--debug` HTTP logger, which uses Go's `log.LstdFlags` (`legacy-debug-logger.layer.ts`). Someone reading a tail is asking "what just happened", and the answer gets compared against their own clock. Text output only. The machine payload keeps both unambiguous forms, so nothing that is parsed, sorted, or pasted into an issue depends on the reader's zone: `timestamp` stays ISO-8601 UTC and `timestamp_ms` the raw epoch value. The unit tests derive their expected prefix from the same instant with the same field accessors, rather than hardcoding one: a literal `"14:45:32"` would have passed only on a UTC machine. One case additionally pins the zone choice itself — asserting the output is *not* the UTC rendering — guarded so it stays meaningful on a UTC machine, where the two coincide. Verified green under `TZ=Asia/Tokyo`, `TZ=UTC`, and the ambient zone.
Opt-in, matching `workers push --wait`: long-running behaviour in this family is asked for, never defaulted. **The poll interval is set by the rate limit, not by responsiveness.** The v1 analytics endpoints allow 10 requests per 60 seconds, so the two-second poll a live tail suggests would spend the whole allowance in ten seconds. Six seconds is the arithmetic floor; ten leaves room for the history query, the deployed-worker check, and a retry in the same window. Measured at ~7 requests in the worst 60-second window. The interval is in `--follow`'s help text, because a 10-second tail is visibly not a live stream and would otherwise look broken. The cursor deliberately lags 60 seconds behind the newest line printed. Guest lines are relayed CloudWatch -> subscription filter -> Lambda -> Logflare and arrive late and out of order, so a cursor sitting on the newest timestamp would drop every straggler permanently. Overlap is therefore guaranteed and expected; dedupe on the Logflare-minted `id` is what makes it invisible, bounded so a long tail does not grow the set forever. `followWindow` clamps to the same sub-24h span as a bounded read, so a tail resumed after a laptop suspend cannot ask for a wider window — the server answers those by returning an *older* slice. Every poll sends both timestamp bounds. Advancing only `iso_timestamp_start` is the obvious implementation and is wrong: it yields a one-minute window. Output: - `-o json|yaml|toml` and `--output-format json` are refused up front, beside the `-o env` refusal and for the same reason — each promises one terminal payload and a tail has no last element. - `--output-format stream-json` emits one `log-entry` event per line instead of a single `result`, reusing the existing variant. `stream` splits error/warn to `stderr`; `source` separates backlog from live. - SIGINT exits 130, matching the local `supabase logs` command. - `--tail 0` skips the backlog and makes no history request, since the endpoint rejects `limit 0`. It also suppresses the not-deployed check, which would otherwise read "no rows" as "no worker" when no query was made at all. Both schedules are injectable, as `awaitWorkerBuild`'s are, so the cursor, dedupe and retry paths are tested without a wall clock. The SIGINT test forks the handler and synchronises on the mock's `awaitExit` — `exit` never returns, so the handler cannot be awaited. Stressed over five consecutive runs.
Comments explaining why code is shaped a certain way now state the constraint directly instead of narrating what an earlier version did. The reasoning is unchanged; only the framing is.
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 6a0ae82d95
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| // A poll asks for whatever arrived since the cursor, not for `--tail` lines; | ||
| // `--tail 0` means "no history", not "no new lines". | ||
| const pollTail = Math.max(flags.tail, 1); |
There was a problem hiding this comment.
When more than flags.tail rows arrive between polls, this cap causes the descending query to return only the newest rows, after which the cursor advances past the omitted rows and they can never be emitted. This is especially easy with --tail 1 --follow, but the default also silently loses logs above 100 rows per polling interval; use an independent polling/page size and continue fetching until the cursor is drained.
Useful? React with 👍 / 👎.
| const streams = Option.isSome(flags.source) | ||
| ? [WORKER_LOG_STREAMS[flags.source.value as WorkerLogSourceChoice]] | ||
| : ALL_WORKER_LOG_STREAMS; |
There was a problem hiding this comment.
The as WorkerLogSourceChoice assertion papers over the CLI flag type instead of preserving the relationship between SOURCE_VALUES and WORKER_LOG_STREAMS; if those definitions drift, this can turn an accepted source into an undefined SQL stream rather than producing a type error. Restructure the shared choice declaration so the inferred flag value indexes the map without an assertion.
AGENTS.md reference: apps/cli/AGENTS.md:L94-L94
Useful? React with 👍 / 👎.
| const seenIds = yield* Ref.make(new Set(entries.map((entry) => entry.id))); | ||
| const newestSeenMs = yield* Ref.make( | ||
| entries.length === 0 ? Date.now() : entries[entries.length - 1]!.timestampMs, | ||
| ); |
There was a problem hiding this comment.
For --tail 0 --follow, entries is empty, so the cursor starts at Date.now(), but followWindow subtracts the 60-second grace period from that cursor. The immediate first poll can therefore emit a log written up to a minute before the command started, contradicting the advertised “skip history and print only new lines” behavior; retain the invocation boundary and filter the initial overlap accordingly.
Useful? React with 👍 / 👎.
| // A 429 or a blip should not end a tail the user is watching; the schedule is | ||
| // spaced in seconds, so retrying rides out a transient failure without | ||
| // spending the rate limit. | ||
| const poll = pollOnce.pipe(Effect.retry({ schedule: readRetrySchedule })); |
There was a problem hiding this comment.
When a follow poll receives a definitive error such as 401, 402, 404, or a malformed response, this unconditional retry repeats the same request on the five-second schedule for up to a minute before reporting it. It also needlessly consumes the shared logs allowance; restrict retries to transport/transient status failures and fail terminal typed errors immediately.
Useful? React with 👍 / 👎.
| // The ref is resolved outside the finalizers because caching it is one of them; | ||
| // everything that can fail on its own belongs inside, so those failures still | ||
| // flush telemetry. Same shape as the rest of the family. | ||
| const projectRef = yield* resolver.resolve(flags.projectRef); |
There was a problem hiding this comment.
When resolving the project ref fails—for example, an unlinked non-interactive checkout or a failed project picker—the failure occurs before either Effect.ensuring is installed, so telemetryState.flush does not run despite the command having started. Wrap project resolution in the telemetry finalizer while keeping the linked-project cache conditional on obtaining a ref.
AGENTS.md reference: apps/cli/AGENTS.md:L288-L290
Useful? React with 👍 / 👎.
| /** Leftover C0 controls and DEL, keeping tab, newline and carriage return. */ | ||
| const C0_CONTROLS = /[\u0000-\u0008\u000b\u000c\u000e-\u001f\u007f]/gu; |
There was a problem hiding this comment.
When a worker emits an embedded \r, this regex deliberately preserves it, and the resulting text is written directly to a terminal. A carriage return moves the cursor back to column zero, allowing tenant-controlled output to overwrite the timestamp or forge the apparent prefix even though ANSI escape sequences were removed; normalize CRLF and strip or escape standalone carriage returns.
Useful? React with 👍 / 👎.
| if (response.status !== 200) { | ||
| // A rejected query or the server's 30-second timeout lands here rather than | ||
| // in the 200-with-`error` branch below, so both paths have to exist. | ||
| return yield* unexpectedStatus({ | ||
| operation, | ||
| status: response.status, | ||
| body: yield* response.text.pipe(Effect.orElseSucceed(() => "")), | ||
| }); |
There was a problem hiding this comment.
When the analytics endpoint returns a non-2xx query rejection or its documented query timeout, this branch raises the generic WorkersApiUnexpectedStatusError, even though WorkerLogsQueryFailedError was added specifically to cover those failures and give them the query fingerprint. As written, the non-2xx half of that error class is unreachable and query regressions are grouped with unrelated Workers transport statuses; map the known query-execution responses to the query failure while retaining status-specific handling for authentication and permission errors.
Useful? React with 👍 / 👎.
| if (flags.follow) { | ||
| const machineOutput = yield* legacyWorkersMachineOutputRequested(); | ||
| if (machineOutput || output.format === "json") { |
There was a problem hiding this comment.
With -o pretty --output-format json --follow, machineOutput is false while output.format is still json, so this rejects an invocation that should run as a text tail because the explicitly supplied legacy --output value takes precedence. The bounded path similarly emits JSON instead of pretty text; resolve the effective format from --output first and only consult output.format when no legacy value was supplied.
AGENTS.md reference: apps/cli/AGENTS.md:L300-L300
Useful? React with 👍 / 👎.
| yield* Effect.raceFirst( | ||
| poll.pipe(Effect.repeat({ schedule: pollSchedule })), | ||
| processControl | ||
| .awaitSignal() | ||
| .pipe(Effect.flatMap((signal) => processControl.exit(signal === "SIGINT" ? 130 : 0))), |
There was a problem hiding this comment.
On the normal Ctrl+C path, the production ProcessControl.exit calls process.exit synchronously from this race branch, terminating the runtime before the outer Effect.ensuring finalizers and the instrumentation wrapper can run. Consequently a followed command does not write the linked-project cache, flush telemetry, or emit its post-run command event; record the desired exit code and return or interrupt through Effect so cleanup completes before the root exits.
AGENTS.md reference: apps/cli/AGENTS.md:L288-L290
Useful? React with 👍 / 👎.
| yield* output.event({ | ||
| type: "log-entry", | ||
| timestamp: new Date(entry.timestampMs).toISOString(), | ||
| service: name, | ||
| stream: level === "error" || level === "warn" ? "stderr" : "stdout", | ||
| line: entry.message, | ||
| source: origin, |
There was a problem hiding this comment.
In --output-format stream-json --follow, using entry.message bypasses the per-stream composition used by text output. Request messages contain only method and path, so status and duration disappear, and build messages omit the structured failure reason; because log-entry has no attributes field, consumers cannot recover those details. Populate line from the same semantic request/build fields used by the renderer, without terminal coloring.
Useful? React with 👍 / 👎.
![depthfirst-app[bot]](https://avatars.githubusercontent.com/in/1021002?s=60&v=4){kind=small}
|
|
||
| if (entry.stream === WORKER_LOG_STREAMS.requests) { | ||
| const { status, method, path, duration_ms: duration } = entry.attributes; | ||
| const request = [status, method, path].filter((part) => part !== undefined).join(" "); |
There was a problem hiding this comment.
🟡 Severity: MEDIUM
An external caller controls the request URL path, and worker/build failures can carry untrusted event/reason; these attributes are joined directly into rendered text. The handler writes it through output.raw, allowing terminal controls to reposition or overwrite the reader's terminal and forge apparent log or CLI output.
Helpful? Add 👍 / 👎
💡 Fix Suggestion
Suggestion: Apply stripControlSequences to all externally-controlled string attributes before they are concatenated into the rendered output. Since entry.attributes is typed as Record<string, string>, all parts are already strings and can be passed directly to stripControlSequences. Two locations need fixing:
-
Line 194 (requests stream) – sanitize
path,method, andstatusbefore joining:
const request = [status, method, path].filter((part) => part !== undefined).map(stripControlSequences).join(" "); -
Lines 201-203 (builds stream) – sanitize
eventandreasonsimilarly:
const described = [event ?? entry.message, reason].filter((part) => part !== undefined).map(stripControlSequences).join(" ");
Both changes mirror the pattern already in use at line 209 for guest messages, ensuring no terminal control sequences embedded in externally-supplied request paths, build events, or failure reasons can reach the terminal via output.raw.
⚠️ Experimental Feature: This code suggestion is automatically generated. Please review carefully.
| const request = [status, method, path].filter((part) => part !== undefined).join(" "); | |
| const request = [status, method, path].filter((part) => part !== undefined).map(stripControlSequences).join(" "); |
6a0ae82 to
c66065d
Compare
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: c66065d71f
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| * one line each, with a different layout per stream. | ||
| */ | ||
|
|
||
| export type WorkerLogLevel = "info" | "warn" | "error"; |
There was a problem hiding this comment.
Rename WorkerLogLevel with the required Legacy prefix; exporting the bare name from src/legacy/ defeats the shell-disambiguation convention enforced for every exported token in this tree.
AGENTS.md reference: apps/cli/AGENTS.md:L222-L224
Useful? React with 👍 / 👎.
| | `0` | success, including "no logs in the last 24 hours" | | ||
| | `1` | invalid worker name | | ||
| | `1` | nothing deployed under that name | | ||
| | `1` | the log query failed (rejected, or the server's 30s timeout) | | ||
| | `1` | log usage exceeded (402), or rate limited (429) | | ||
| | `1` | API error, or project not enrolled in the alpha | |
There was a problem hiding this comment.
Add exit code 130 for --follow interrupted by SIGINT: the handler explicitly calls processControl.exit(130) and the new integration test asserts that result, but this compatibility table documents only codes 0 and 1. Leaving it out makes the command's required side-effect record inaccurate and can mislead the E2E coverage derived from it.
AGENTS.md reference: apps/cli/AGENTS.md:L359-L366
Useful? React with 👍 / 👎.
| // rows says nothing about whether the worker exists. | ||
| if (entries.length === 0 && flags.tail > 0) { | ||
| const deployed = yield* getWorker(api, projectRef, name); | ||
| if (Option.isNone(deployed)) { |
There was a problem hiding this comment.
When the logs query returns no rows, the fetching task is cleared before this second API call, so a slow getWorker request leaves text-mode users with no progress indication and makes the command appear hung. Keep the existing task active through this lookup or wrap the deployment check in its own output.task, as required for asynchronous API calls.
AGENTS.md reference: apps/cli/AGENTS.md:L425-L437
Useful? React with 👍 / 👎.
Supabase CLI previewnpx --yes https://pkg.pr.new/supabase/cli/supabase@c66065d71f6fe67f459800ca492046a383715bf1Preview package for commit |
1 participant
Summary
supabase experimental workers logs <name>— the runtime counterpart toexperimental workers status.statusreports the deployment; nothing reported what the worker actually printed, so oncepushsucceeded andstatussaidactive, a misbehaving worker was a black box from the CLI.Reads the project's unified logs stream rather than a worker route — there is no worker-scoped log endpoint — via
v1GetProjectLogs, which the generated client already carries.--source app|requests|buildsnarrows to one of the three streams; without it all three are returned, tagged per line.--tailcaps the rows.--followkeeps printing until interrupted.Three non-obvious things about that endpoint
Each is documented at its call site, because none is guessable from the API surface:
log_attributes, not thesourcecolumn. Worker rows carry an empty top-levelsource, because the Workers Logflare source is not enrolled as a category in the generic logs path, sowhere source = 'worker_guest_logs'matches nothing. Thein (...)list over the three known streams is a tenancy guard rather than a convenience — withsourceempty it is the only thing excluding a non-worker row that happens to carry aworkerattribute.start + 24h, returning an older slice than the one asked for rather than a truncated one.error, so the envelope is checked beforeresult.The response is decoded against a local schema rather than the generated
V1GetProjectLogsOutput: that schema marksresult/erroroptional but permits neither to benull, while the endpoint always sends one of them as an explicitnull. Decoding a real response against it always fails — worth fixing in the spec separately.Rendering
Per-stream, because
event_messagediffers in kind: on the request stream it is only"GET /", with status and duration inlog_attributes, so the request line is composed.severity_textis ignored — it isINFOon every row of every stream — so the level is derived, and app lines report none rather than a guess. An app message is tenant-controlled bytes, so escape sequences are stripped before it reaches a terminal while a stack trace's newlines and indentation survive.--followThe poll interval is set by the rate limit, not by responsiveness: the v1 analytics endpoints allow 10 requests per 60 seconds, so the two-second poll a live tail suggests would spend the whole allowance in ten seconds. It polls every 10 seconds, measured at ~7 requests in the worst 60-second window.
The cursor deliberately lags 60 seconds behind the newest line printed. Guest lines are relayed CloudWatch → subscription filter → Lambda → Logflare and arrive late and out of order, so a cursor sitting on the newest timestamp would drop every straggler permanently. Overlap is therefore guaranteed; dedupe on the Logflare-minted
idis what makes it invisible.-o json|yaml|tomland--output-format jsonare refused up front — each promises one terminal payload and a tail has no last element.--output-format stream-jsonemits onelog-entryevent per line. SIGINT exits 130.Stack
On top of the workers output polish (#6389), with
push --wait(#6371) stacked above so it can be rejected independently. Below those: theworkers newname prompt (#6349).Note
Replaces #6408, which GitHub marked merged during a stack reorder. It was never merged to
develop; the branch and its commits are intact here.