Skip to content

[audit] Do we log all failures? Five verified holes — transient infra and pre-auth failures are never recorded, and 97% of the log is one bug #424

Closed

Description

@serge-ivo

Answer: mostly yes, and better than I expected — but there are five verified holes, and one of them is exactly the failure class the reporter hit

Audited every failure path I could reach, in response to "we have to log all failures to be able to investigate". Below is what is genuinely covered (do not rebuild it) and what is not.

What IS covered — verified, leave it alone

Mechanism Where Verdict
Durable write, never throws, bounded field sizes, mirrors into agent_events so failures appear inline in agent_trace lib/error-log.ts:25-64 Solid
Global app.onError → logUnhandled, with stack, attributed to the signed-in user index.ts:187-201, lib/on-error.ts:33-63 Solid
Client api() reports network errors and all 5xx to the durable log packages/sdk/src/client.ts:84, 101-103 Solid
Browser window.error + unhandledrejection → reportClientError store/console/src/main.tsx:10, 21 Solid
React ErrorBoundary.componentDidCatch — needed because window.onerror does not fire for exceptions React catches components/ErrorBoundary.tsx:39 Solid
Signature aggregation with count / firstSeen / lastSeen GET /v1/admin/errors/summary Excellent — this is what made #423 findable in one call
30-day retention, opportunistic (2% of writes), never blocks error-log.ts:55-61 Fine

agents/coder/web has no handlers of its own, but it is imported into the console (store/console/src/lib/surfaces.tsx:2), so it runs inside the console's boundary. Not a gap.

Server-side bare catch {} is down to 2 real sites (agent-think.ts:474, 550). The server is in good shape.

The five holes

H1 — Transient infra failures are never logged server-side

lib/on-error.ts:38:

if (isTransientInfraError(err)) return;   // ← before any logError

isTransientInfraError (:11-19) matches "Durable Object reset because its code was updated", "Durable Object is overloaded", "Network connection lost". Those return 503 {"error":"The service is updating…"} to the client and write zero server rows.

Consequence, from today: the 03:56:40Z chat failure — 13s after a Deploy API Worker run — exists in the log only because the browser reported it (client:api … → 503). Had that user been on a flaky connection, or a runner, or the MCP server, there would be no record at all. The question "how often does a deploy break a live request?" is currently unanswerable, and it is precisely the question that was asked.

The skip is deliberate and the reasoning (:24 "not a bug, self-heals") is sound for error severity. It is wrong for visibility. Fix: log it under a distinct source (transient) or level:"warn", excluded from error counts but countable.

H2 — Client failures before sign-in are dropped entirely

packages/sdk/src/client.ts:42:

const token = getToken();
if (!token) return;   // the log is per-user; nothing to attribute it to

So every sign-in, OAuth-callback and pre-auth failure is invisible — the exact class you cannot debug from the user's side. The premise is also wrong: migration 0034 declares user_id TEXT, -- nullable: some failures have no user context, and the server already writes null-user rows (every #423 cron row has user_id = null). Fix: allow an unauthenticated report to /v1/errors/client, rate-limited by IP.

H3 — 4xx never reaches the durable log from either side

  • Server: on-error.ts:39-40 — HttpError with status < 500 returns without logging.
  • Client: client.ts:101 — reports only res.status >= 500; the comment says ordinary 4xx "would just be noise".

Broadly right, but it makes some genuinely diagnostic failures invisible: 402 (no API key connected), 403, 409, and 429 (rate limited). A user repeatedly hitting a limit generates no evidence anywhere. Note the log does contain a 402 today — but only because chat logs it explicitly at its own call site, not through either path above. Fix: an allowlist of interesting 4xx at warn level, not all of them.

H4 — 61 bare catch {} remain, and #291 was closed saying they would not

Counted with grep -rnE "catch\s*(\([a-zA-Z_]*\))?\s*\{\s*\}", excluding tests:

workers/api/src            :  3   (2 real)
packages/sdk/src           : 10
store/console/src          : 38
agents/coder/web/src       :  8
packages/browser-runner/src:  2

#291 (CLOSED) reported "64 empty catch blocks" and its acceptance criteria said they would be "replaced with explicit benign comments only where failure is truly ignorable, or with structured logging/user-visible state where it is not." 64 → 61 is not that. This should be reopened or superseded rather than left looking done.

Important nuance, so this is not overstated: most of these wrap await api(...), and api() has already written the durable row for a 5xx or network error before throwing. So they are primarily a user-visible feedback failure, not a logging one — KnowledgeTab.tsx:92-112 silently renders an empty Documents/Credentials/Rules list when the load fails, which reads as "you have nothing" rather than "this didn't load". They become a logging failure only where the status is 4xx (H3).

H5 — A failure with no error object cannot be logged by any of the above

This is the one the reporter actually hit. In #421 the transcription fetch (stt.ts:344) has no signal, and there is no AbortController anywhere in packages/sdk/src/voice/ (grep -c → 0). A request that never settles produces no throw, no non-OK response, no rejection — so api(), window.onerror, unhandledrejection, ErrorBoundary and app.onError all have nothing to fire on. It is not under-logging; it is a failure the logging model cannot represent.

So "log all failures" is necessary but not sufficient. Anything that waits on a network must carry a deadline, or its failure mode is silence by construction. Tracked in #421; noted here because it is the structural answer to the question.

And the counterweight: volume already defeats the instrument

#423 — 1780 of ~1845 rows (97%) are one repeating cron failure. My own first pass at this investigation queried the log, got 4 voice rows, and I reported "the logs show nothing". That conclusion was wrong and the log's own volume caused it.

So the answer to "log all failures" must include collapse at write time: for an identical signature repeating within a window, increment a count rather than insert a row. The read side already models this correctly (/v1/admin/errors/summary); the write side does not.

What to do — cheapest first

  1. H1 — log transient infra under source:"transient" instead of returning early. ~3 lines. Makes deploy disruption countable, which is the specific thing asked for.
  2. H2 — accept unauthenticated /v1/errors/client reports (IP rate-limited), and drop the if (!token) return. Unblocks all auth debugging.
  3. Write-side repeat collapse — bounded volume, and it is what makes (1) and (3) safe to add without recreating [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423.
  4. H3 — allowlist 402/403/409/429 at warn level.
  5. H4 — reopen or supersede [bug] Stop swallowing runtime errors across voice, coder, and worker paths #291 with the real count; triage the 38 console sites by whether they wrap a read (show "couldn't load — Retry") or a write (never silent — a swallowed save tells the user their edit persisted when it did not). Worth grepping the writes first; that is where the harm is.
  6. H5 — timeouts, per [bug] A stalled transcription hangs on "Transcribing…" forever and locks the composer — no timeout, no retry, no dismiss, reload is the only escape #421. Not a logging change.

Alternatives considered and rejected

  • Remove the isTransientInfraError skip so these log as 500 errors. Rejected: it was added because these were being logged as bogus 500s and the 503 response is correct. Log them at a different severity, do not un-classify them.
  • Log all 4xx. Rejected: 401/404 on an SPA are constant background traffic and would recreate the [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423 flood at higher volume than the cron did.
  • Ban catch {} with a lint rule and let it fail CI. Rejected as the first step: it forces 61 mechanical edits with no judgement about which are reads and which are writes, and the write ones need a real user-facing behaviour, not a console.warn. Worth adding after the triage, to hold the line.

Acceptance criteria

  • A deploy-time 503 produces a server-side row without a browser present.
  • A failed sign-in produces a durable row with user_id = null.
  • A signature repeating every minute for an hour produces bounded rows, and its count is still visible in /errors/summary.
  • No swallowed write in the console: a failed save shows the user that it failed.
  • /v1/admin/errors is readable — no single signature exceeds a large share of the recent feed.

Related: #291 (closed, empty catches — count essentially unchanged), #325 (closed, triage empty catches/silent rejections), #421 (the failure class logging cannot catch), #423 (the flood that makes the log unreadable), #387 (a giving-up path that produced no evidence — the same family, already fixed).

Activity

  1. serge-ivo commented on Aug 8, 2026

    @serge-ivo
    ContributorAuthor

    Self-review before implementation: two of the five items above are wrong, the ordering is wrong, and the biggest hole is missing

    Re-read against the code rather than against my own text. Corrections first, then the implementation-ready spec.


    ✗ Correction 1 — H2 is overstated, and the fix I proposed is a security hole

    The claim was wrong. I wrote that "every sign-in, OAuth-callback and pre-auth failure is invisible — the exact class you cannot debug". Server-side auth failures are already logged, at four call sites in routes/auth.ts:

    :116  logError(source:"auth", 401, `GitHub sign-in failed: ${reason}`, {provider:"github"})
    :136  logError(...)
    :253  logError(source:"auth", 401, `Google sign-in failed: ${reason}`, {provider:"google", redirectUri})
    

    So the real gap is far narrower: a client-side JS exception in the SPA before a token exists — a crash on the login screen, a failed /v1/auth/config fetch. Everything the server sees is already covered.

    And the fix I proposed was worse than the gap. "Accept unauthenticated /v1/errors/client reports (IP rate-limited)" creates an unauthenticated D1 write endpoint open to the internet — a free storage-and-cost amplification vector, mitigated only by a rate limiter. That is a bad trade for a narrow diagnostic, and I should not have proposed it.

    Replacement — buffer and flush, no new attack surface:

    • In reportClientError (client.ts:42), when there is no token, push to sessionStorage (capped, e.g. 10 entries × 2KB) instead of return.
    • On the next successful auth, flush the buffer to /v1/errors/client with the now-known token, tagging each context.preAuth = true and carrying its original timestamp.
    • Accept the residual gap honestly: if sign-in never succeeds, nothing flushes. That case is already covered server-side by the auth.ts rows above, which is why it is acceptable — and it is the whole reason this correction matters.

    ✗ Correction 2 — the ordering was wrong, and it made the cheapest fix look expensive

    I wrote that H1/H2/H3 should land after write-side repeat collapse, on the grounds that adding sources to a drowning log makes it worse.

    That inverted the economics. 97% of the volume is one bug (#423). Fixing it is a single query rewrite and reclaims all the headroom immediately. Collapse is a schema change plus edits to three read paths (routes/admin.ts, admin-instance-detail.ts, lib/admin-errors.ts).

    Corrected order:

    1. Fix [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423. Log drops from ~1845 rows to ~65. Free headroom, no new machinery.
    2. Then H1/H3 — with headroom, they are safe unaggregated. Sizing check: H1 fires on DO-reset-per-deploy (~9 deploys/day observed) — tens of rows/day, not thousands.
    3. Collapse last, as a ratchet — insurance against the next [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423, not a prerequisite for anything.

    ✗ Correction 3 — H1 needs a bound that I did not specify

    "Log transient infra under source:"transient"" is under-specified in the one way that matters: a DO overload storm is transient, correlated, and unbounded — precisely the shape that produces thousands of rows in minutes. Deploys are bounded; overload is not.

    Add: cap transient writes with the same 30s per-signature de-dup the client already uses (client.ts:46), applied server-side in logUnhandled before the write. One row per transient signature per 30s is enough to answer "did deploys break requests" and cannot storm.


    ✚ Missing — H6: nothing is watching. This is the biggest hole, and #424 did not mention it

    routes/admin-ops.ts:91-95:

    // Error-log volume in the last 24h (the spike signal).
    const errRow = await c.env.DB.prepare(
      `SELECT COUNT(*) AS n FROM error_log WHERE created_at >= datetime('now', '-24 hours')`,
    ).first<{ n: number }>();
    const errors24h = Number(errRow?.n ?? 0);

    The comment calls it "the spike signal". It is a number in an admin JSON response that only appears if a human opens the page and interprets it. Nothing thresholds it, nothing fires.

    That is why #423 ran 1780 times across 29.6 hours unnoticed — not because it was unlogged. It was logged perfectly, 1780 times. Every fix in #424 improves the recording of failures nobody is reading. Recording without notification is the actual hole.

    The platform already has everything needed: lib/notifications.ts, lib/web-push.ts, and a * * * * * cron (wrangler.toml:8) already running five independent sweeps (index.ts:222-244), each following the same "swallow and log its own errors" contract.

    Spec — runErrorAlertSweep(env), a sixth sweep in the same shape:

    • Group the last 15 minutes by signature (reuse summarizeErrors from lib/admin-errors.ts — already written and tested).
    • Fire when a signature is new (firstSeen inside the window) or crosses a rate threshold (e.g. ≥20 in 15 min).
    • Notify the operator account via lib/notifications.ts; include count, firstSeen, source, and the sample message.
    • De-dup per signature per 24h, so a persistent failure alerts once and then stays quiet. Without this the alerting itself becomes the flood — the same mistake one layer up.
    • Ship it with a deliberate self-test: [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423's own signature would have alerted within 15 minutes instead of 29.6 hours. That is the acceptance criterion.

    ✓ Unchanged after review


    Revised implementation order

    # Change Cost Why here
    1 Fix #423 1 query Reclaims 97% of the log for free
    2 H6 alert sweep 1 sweep, reuses summarizeErrors + notifications Converts logging into finding out — the actual hole
    3 H1 transient, 30s per-signature de-dup ~5 lines Makes deploy disruption countable
    4 H2 buffer-and-flush ~15 lines, no new endpoint Closes the narrow real gap, no attack surface
    5 H3 4xx allowlist ~3 lines Small, safe once 1 is done
    6 H4 triage — writes before reads 61 sites, judgement each Largest, lowest urgency
    7 Write-side collapse Migration + 3 read paths Ratchet against the next #423

    If only one thing ships, it should be #2. #424 as originally written would have improved the recording of failures that nobody reads; the alert sweep is what would have caught #423 on the day it shipped.

  2. serge-ivo commented on Aug 8, 2026

    @serge-ivo
    ContributorAuthor

    Four of the five holes closed and verified in production. 8c55639 (+ 7852232 for the counterweight, #423). Migration 0103.

    Shipped

    H1 — transient infra is now recorded. logUnhandled no longer returns before writing. These go in as source:"transient", level:"warn", status 503. A distinct source as well as a distinct level, so deploy disruption is countable with ?source=transient rather than by matching platform wording that isn't ours and can change under us. The severity reasoning at on-error.ts:24 was right and is preserved; only the visibility changed.

    H2 — pre-auth client failures are recorded. Both ends. /v1/errors/client takes an optional session; the SDK no longer returns early with no token and simply omits the Authorization header. Your reading of the premise was correct — migration 0034 declares the column nullable and the server has always written null-user rows.

    H3 — 402/403/409/429 at warn, from both sides. Allowlist, not all 4xx, for the reason you gave: 401/404 on an SPA would recreate the flood at higher volume.

    Write-side repeat collapse. An identical failure inside an hour increments repeat_count on the row already recording it, and skips the agent_events mirror — #423 put 1811 error events there too, so collapsing only one of the two would have left the trace unreadable.

    Design decisions worth recording, since each had a plausible wrong answer:

    • Identity is EXACT — source, level, status, user and byte-identical message — not the normalized signature /errors/summary groups by. Merging "instance abc failed" with "instance def failed" at write time discards which instance and no read gets it back. Exact text carries no extra information, which is what makes collapsing it lossless. (Verified this suffices for the motivating case: [bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423's 1811 rows had 1 distinct message between them.)
    • The window is anchored on created_at, not on the last hit. A rolling window folds a permanently failing sweep into one row updated forever, hiding when it started and whether it is still going. Anchored: ≤24 rows/day/signature, and a coarse timeline survives.
    • Reads and retention order/age on COALESCE(last_seen_at, created_at). A collapsed row keeps the created_at of the bucket it opened, so ordering on that would sink — and retention would delete — an outage that is still happening.
    • summarizeErrors counts OCCURRENCES and reports rows alongside. Counting rows would have reported "2" for a failure that happened 1800 times, understating precisely the runaway the counter exists to surface. A signature that is ever a real error is not filed under warn.
    • A failing collapse falls through to the INSERT, not out to the catch. Migrations apply before the Worker is replaced, so the columns are there — but the failure mode if that's ever wrong is total silence in the one component whose job is to not be silent.

    Verified in production

    Three identical anonymous POSTs to /v1/errors/client, no Authorization header:

    http 200 ×3  →  rows: 1
    source        client:verify-424
    user_id       null            ← H2: previously a 401
    repeat_count  3               ← collapse: 3 occurrences, 1 row
    created_at    2026-08-08 05:56:07
    last_seen_at  2026-08-08 05:56:08   ← both ends preserved
    

    Migration applied and backfilled (level, repeat_count, last_seen_at present; 0 rows missing last_seen_at). Every new read/write statement executed against production D1 to prove it parses: listErrors with and without the level filter, the admin errorQuery, the retention predicate, and the collapse lookup.

    (That probe row is still in the log, deliberately — it's the evidence, and deleting production rows to tidy a report is the wrong instinct.)

    Acceptance criteria

    • A failed sign-in produces a durable row with user_id = null.
    • A signature repeating every minute for an hour produces bounded rows, and its count is still visible in /errors/summary.
    • /v1/admin/errors is readable — no single signature exceeds a large share of the recent feed. ([bug] The stats rollup has failed on every cron tick since it shipped — 1780 identical D1 compound-SELECT errors in 29h, and it is 97% of the error log #423's 97% is gone; the live feed since that deploy is 2 chat, 2 client:api, 1 probe.)
    • A deploy-time 503 produces a server-side row without a browser present. Covered by unit test (source transient, level warn, status 503, path in context) but not yet observed live — a DO reset only occurs when a request is in flight during a code update, and none was during today's deploys. Evidence will accumulate on its own; I'm not claiming it verified.
    • No swallowed write in the console: a failed save shows the user that it failed. — see H4 below. Not done.

    Not done, and saying so rather than narrowing quietly

    H4 — the 61 bare catch {}. Not touched. Your own nuance is why: most wrap await api(...), which has already written the durable row before throwing, so the remaining problem is user-visible feedback, not logging — 38 console sites each needing a read-vs-write judgement and a real UI behaviour, not a console.warn. That is a UI triage in files three other agents are editing today, and this issue itself asks for #291 to be reopened or superseded rather than quietly re-closed. Leaving #424 open for it.

    H5 — a request that never settles. Correctly out of scope; you say so yourself. It needs a deadline, not a log. Tracked in #421, held by another agent.

    Unrelated finding from #423, needs its own issue: unionAll in lib/instance-work.ts builds one UNION ALL branch per instance, so supervision reads break for a supervisor with ≥6 subordinates — the same D1 five-term ceiling, measured. A static scan can't see a runtime-built union; it needs a cap at construction.

  3. serge-ivo commented on Aug 8, 2026

    @serge-ivo
    ContributorAuthor

    Four holes closed and verified in production. H4 has moved to the reopened #291. Closing.

    8c55639 + migration 0103 are on main and in the deployed API (ancestor of b6f6c9f6).

    Verified live, from the durable log itself

    GET /v1/admin/errors?limit=25          (2026-08-08 13:2x UTC)
    
    2026-08-08 08:34:41  lvl=error  repeat_count=2  last_seen=2026-08-08 08:37:58   client:voice-control
    2026-08-08 06:30:30  lvl=warn   repeat_count=1                                  unhandled  (Drive/WorkDrive refusal)
    2026-08-08 05:58:11  lvl=error  repeat_count=2  last_seen=2026-08-08 06:03:29   chat
    2026-08-08 05:56:07  lvl=error  repeat_count=3  last_seen=2026-08-08 05:56:08   client:verify-424
    
    • H2 — pre-auth client reports. The client:verify-424 rows are an anonymous, unauthenticated
      report landing in the durable log. The premise the old if (!token) return rested on was wrong, and
      migration 0034 had said so all along (user_id TEXT, -- nullable).
    • Write-side repeat collapse. repeat_count 2 and 3 with a moving last_seen_at, live. This is the
      counterweight the audit said the other fixes needed: the read side already modelled repetition
      correctly and the write side did not.
    • H3 — diagnostic 4xx at warn. level=warn rows are present, and DIAGNOSTIC_CLIENT_ERRORS
      (lib/on-error.ts:33) is the allowlist — {402, 403, 409, 429} — not "all 4xx", which the audit
      rejected for good reason.
    • H1 — transient infra. Wired at lib/on-error.ts:54-60: source:"transient", level:"warn",
      countable with ?source=transient rather than by matching platform wording. Not yet observed live
      — ?source=transient returns 0 rows, because no Durable Object reset or overload has happened since
      the deploy. Code-verified, not production-verified, and I would rather say so than imply otherwise.

    And the counterweight the audit led with

    The #423 flood stopped. Its last row is 2026-08-08 05:28:07; #423 was fixed and closed at 05:57.
    In the eight hours since, the log has taken 13 rows, all distinct. The instrument is readable again.
    The 1,811 historical rows still dominate the all-time totals and will until 30-day retention clears
    them — that is residue, not an ongoing condition, and the write-side collapse now bounds any recurrence.

    Acceptance criteria

    • A deploy-time 503 produces a server-side row without a browser present — code-verified; awaiting
      a real transient to observe it.
    • A failed sign-in produces a durable row with user_id = null — observed above.
    • A signature repeating every minute for an hour produces bounded rows, count still visible in
      /errors/summary — repeat_count + last_seen_at, observed above.
    • No swallowed write in the console: a failed save shows the user that it failed. → [bug] Stop swallowing runtime errors across voice, coder, and worker paths #291
    • /v1/admin/errors is readable — no single signature exceeds a large share of the recent feed.

    H4 and H5

    H4 — counted again on main today: 60 bare catch {} (3 api / 10 sdk / 37 console / 8
    coder-web / 2 runner). 64 → 60 is not what #291 promised. This issue asked for #291 to be reopened
    rather than #424 re-closed
    , and that is what has happened: #291 is reopened, carrying the measured
    count, the read-vs-write triage, and the note that most of these are a user-visible feedback failure
    rather than a logging one (because api() has already written the row before it throws). The one
    unmet criterion above lives there.

    H5 — not a logging change, and correctly tracked in #421, which is open and being worked. A
    request with no deadline produces no throw, no non-OK response and no rejection; that failure mode
    cannot be represented by any amount of logging, which is the structural answer to the question asked.

    Nothing left here that is not #291 or #421. Closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions