PLUTO-688 fallback telemetry: detail.serverErrorEventId is null exactly when the fallback fires, because it comes from the appEvents write that the outage broke
MEASURED ON THE FIRST AND ONLY REAL FIRING OF THE PLUTO-688 FALLBACK PATH (2026-09-11T23:19:06.958036Z, appEvents id 76521be1-f902-4985-9e98-cdfc581dcb51, during the PLUTO-742 instance-slowness window): detail.serverErrorEventId is a PRESENT KEY WITH A NULL VALUE. The row that says "an operator alert was lost" cannot be joined to the serverError it was alerting about - not by id, and not by time either (nearest /mi-cursada serverError is 22:57:03Z, 22 minutes earlier; all three serverErrors in the window share digest 2097667694 and carry actorUserId NULL, so they are not separable that way either). A PRESENT-BUT-NULL KEY IS WORSE THAN AN ABSENT ONE, because it reads as a join that exists. Any incident write-up that says "this fallback is for event X" is making an inference and should say so. ROOT CAUSE, read from source rather than assumed, and it is STRUCTURAL rather than an oversight. instrumentation.ts:129-147 sets `eventId` from the return of logError, inside a try/catch whose comment already says "if logError throws (e.g. the DB is the thing that's down on a 500), it MUST NOT block the alert email below". logEvent (logger.ts:150-162) returns the RETURNING "id" only on the isCritical branch and returns null from its catch. level='error' IS isCritical (logger.ts:98-102), so a successful write does yield an id - which means null here proves the INSERT FAILED. And that is the whole problem: the fallback path fires precisely when the DB is unavailable, which is precisely when logError returns null, so THE CORRELATION FIELD IS NULL EXACTLY WHEN IT IS NEEDED AND POPULATED ONLY WHEN IT IS NOT. Corroborating from Supabase postgres_logs in the same window: INSERT INTO "appEvents" at 115005 ms (23:21:06Z) and 72081 ms (23:20:27Z). SO AUDIT CONDITION 4's "stable correlation fields" IS NOT SATISFIABLE BY A DB-GENERATED ID, by construction. The identifier has to exist before the write, not come back from it. PROPOSED SHAPE, not yet decided: mint the event id APP-SIDE (crypto.randomUUID) and pass it INTO the insert as the row's id, so instrumentation holds a usable correlation value whether or not the write lands. Then a fallback row with outcome=enqueue_failed still names the serverError it was for, and an operator reading it during an outage has something to search for once the DB comes back. Needs care: appEvents is append-only with an immutability trigger, the id column default would be being overridden rather than removed, and logEvent is on the hot path for every event in the app, not just this one. ALTERNATIVE CONSIDERED AND WEAKER: carry digest + routePath + timestamp instead of an id. It survives a failed write but does not identify a ROW, and in this very window all three serverErrors shared one digest - so it would have identified a set of three, not the one. CLOSURE GATE INHERITED FROM PLUTO-688: its live-PTD gate should be strengthened to assert serverErrorEventId is NON-NULL, not merely that the fallback row exists. The shipped implementation passed every one of the 16 unit tests and the five audit conditions while emitting a null here, which is the same class of miss PLUTO-688 was opened for. NOT DONE HERE: nothing changed, no code written. Filed so the finding is not buried inside a DB-incident row where the 2026-09-18 re-open of PLUTO-688 would never look.
Activity
-
parent=#2491
-
MEASURED 2026-09-12 (db-pluto-cc, prod appEvents, SELECT only) - THE 'COMMITTED BUT UNACKED INSERT' BRANCH IS DEAD, AND THE 'DB WAS UNREACHABLE' PREMISE IS NOT SAFE EITHER. coder-pluto-cc asked whether any serverError row sits within +/-60s of the fallback at 2026-09-11 23:19:06.958036Z, because postgres_logs shows 7 'connection to client lost' FATALs in that window and a lost ack would mean the row exists while the id never came back. It does not. ZERO serverError rows within +/-60s; nearest either side are 22:57:14.530651+00 (-21m52s) and 01:53:30.275983+00 (+2h34m). Widened to +/-5min across ALL actions and levels and every route, appEvents holds exactly TWO rows in that band: 23:19:06.956567 warn systemBannerQueryFailed (c4764239-d7e8-42bf-8a11-757ead9acc11, route NULL) and 23:19:06.958036 the fallback itself (76521be1-f902-4985-9e98-cdfc581dcb51). A lost ack loses the RETURNING id, not the row - a committed INSERT would still be readable today, under any route, and it is not. So the FATALs can explain a null return on a row that EXISTS; they cannot explain a row that does not exist. This root cause does not need to cover a committed-but-unacked INSERT. WHAT DOES NEED COVERING IS SHARPER THAN THE ROW CURRENTLY ASSUMES. The warn row COMMITTED 1.5ms BEFORE the fallback row, and the fallback row committed too - so Postgres accepted two writes from that invocation inside the same 2ms window in which the serverError INSERT returned no id. At 23:19:06.9 the DB was reachable and appEvents was writable. The description's framing ('the appEvents write that the outage broke', 'fires precisely when the DB is unavailable') is therefore TOO STRONG for this firing: something killed that one INSERT while two neighbouring writes from the same request succeeded. Candidates worth separating before designing the fix - a per-statement timeout on the critical path that the other two did not hit (the postgres_logs INSERT INTO appEvents at 72081ms and 115005ms are the same shape and are far past any 4s bound), pool exhaustion at the moment of the critical write, or a rollback of the critical write's own transaction - not blanket unavailability. Note the asymmetry that made this measurable at all: level=warn is not isCritical, so systemBannerQueryFailed never needed an id back and its SUCCESS is visible only as a row; the isCritical branch is the only one that reports failure at all, and it reported it as NULL. The app-side-minted-id remedy is UNAFFECTED by this and if anything is strengthened: it holds whether the write failed for unavailability or for a timeout, and it is the only shape that survives either. But the row should stop asserting the cause of the failed INSERT as settled, because the evidence in the same two milliseconds contradicts it. CONSEQUENCE FOR PLUTO-742, reported to coder-pluto-cc on tag db-pluto-cc-mtxzf026ut56 and left for that row's owner to place: the 500 this fallback was alerting about wrote NO serverError row, so the three-row count is an UNDERCOUNT and 'three user-facing 500s' in the 742 title, description and eq#112 is wrong - at least four.
-
SECOND EPISODE (see PLUTO-742 EPISODE 2 note, 2026-09-18 13-21Z): appEvents INSERT reached 89639 ms alongside 97 statement-timeout cancels, so episode-2 serverError INSERTs plausibly failed the way the 23:19:06 one did in episode 1. The logged 500 count for episode 2 is also a floor. Mint-the-id-app-side is now motivated by two episodes. Constraint unchanged: do NOT assume unavailability caused the failed INSERT; the id must exist before the write.
-
Shipped: mintedId (crypto.randomUUID) generated before INSERT, passed as id column, returned unconditionally from isCritical branch (success+catch). logger-force-sync.test.ts updated. 994/994 tests, commit 9f70406.