Unified · Split
| @@ -0,0 +1,280 @@ | |||
| 1 | // Cloud-only: what an operator SEES when a write is rejected by the database. | ||
| 2 | // | ||
| 3 | // The product guarantee: a storage failure is reported under a stable headline | ||
| 4 | // built from the operation and the database's error code — never the statement | ||
| 5 | // text, never the values that were bound into it. Two consequences, both of | ||
| 6 | // them things production got wrong: | ||
| 7 | // | ||
| 8 | // - The values bound into a rejected statement are customer data (the | ||
| 9 | // organization id, the connection name, whatever the user typed into the | ||
| 10 | // description). They must not appear in the report's headline. | ||
| 11 | // - The headline is the grouping key of the error reporter, so one defect that | ||
| 12 | // hits several tables — or the same table through several WHERE shapes — | ||
| 13 | // must arrive as ONE report, not one per statement. | ||
| 14 | // | ||
| 15 | // The failure is induced through the public typed API only: PostgreSQL cannot | ||
| 16 | // store a NUL byte in a text column, so a connection whose description carries | ||
| 17 | // one is rejected by the driver with SQLSTATE 22021 while the statement and its | ||
| 18 | // bound parameters are already assembled. That is the same class of failure the | ||
| 19 | // production reports came from, reachable without touching the database. | ||
| 20 | // | ||
| 21 | // Two surfaces are asserted, both public: | ||
| 22 | // 1. What the CALLER gets — an opaque `InternalError` carrying only a trace | ||
| 23 | // id, with no driver text anywhere in the payload. | ||
| 24 | // 2. What the OPERATOR gets — the server's own error log, where the trace id | ||
| 25 | // the caller received joins to the report the server filed. Its headline — | ||
| 26 | // the captured exception's type and message — is what the error reporter | ||
| 27 | // files the report under, and groups by. | ||
| 28 | import { randomBytes } from "node:crypto"; | ||
| 29 | import { readFileSync } from "node:fs"; | ||
| 30 | import { resolve } from "node:path"; | ||
| 31 | |||
| 32 | import { expect } from "@effect/vitest"; | ||
| 33 | import { Cause, Effect, Exit, Schedule } from "effect"; | ||
| 34 | import type { HttpApiClient } from "effect/unstable/httpapi"; | ||
| 35 | import { composePluginApi } from "@executor-js/api/server"; | ||
| 36 | import { openApiHttpPlugin } from "@executor-js/plugin-openapi/api"; | ||
| 37 | import { AuthTemplateSlug, ConnectionName, IntegrationSlug } from "@executor-js/sdk/shared"; | ||
| 38 | |||
| 39 | import { RUNS_DIR, scenario } from "../src/scenario"; | ||
| 40 | import { Api, Target } from "../src/services"; | ||
| 41 | |||
| 42 | const api = composePluginApi([openApiHttpPlugin()] as const); | ||
| 43 | type Client = HttpApiClient.ForApi<typeof api>; | ||
| 44 | |||
| 45 | /** A text value PostgreSQL cannot store — the driver rejects it as 22021. */ | ||
| 46 | const NUL = String.fromCharCode(0); | ||
| 47 | |||
| 48 | const SLUG = "storage-error-report-shape"; | ||
| 49 | |||
| 50 | /** Minimal OpenAPI spec with a single GET /ping — never contacted here. */ | ||
| 51 | const pingSpec = JSON.stringify({ | ||
| 52 | openapi: "3.0.3", | ||
| 53 | info: { title: "Ping API", version: "1.0.0" }, | ||
| 54 | paths: { | ||
| 55 | "/ping": { | ||
| 56 | get: { operationId: "ping", summary: "Ping", responses: { "200": { description: "pong" } } }, | ||
| 57 | }, | ||
| 58 | }, | ||
| 59 | }); | ||
| 60 | |||
| 61 | /** Registers a fresh apiKey-authenticated integration for connections to bind to. */ | ||
| 62 | const registerIntegration = (client: Client) => | ||
| 63 | Effect.gen(function* () { | ||
| 64 | const slug = IntegrationSlug.make(`${SLUG}-${randomBytes(4).toString("hex")}`); | ||
| 65 | yield* client.openapi.addSpec({ | ||
| 66 | payload: { | ||
| 67 | spec: { kind: "blob", value: pingSpec }, | ||
| 68 | slug, | ||
| 69 | baseUrl: "http://127.0.0.1:59999", // never contacted during registration | ||
| 70 | authenticationTemplate: [ | ||
| 71 | { | ||
| 72 | slug: "apiKey", | ||
| 73 | type: "apiKey", | ||
| 74 | headers: { authorization: ["Bearer ", { type: "variable", name: "token" }] }, | ||
| 75 | }, | ||
| 76 | ], | ||
| 77 | }, | ||
| 78 | }); | ||
| 79 | return slug; | ||
| 80 | }); | ||
| 81 | |||
| 82 | interface RejectedWrite { | ||
| 83 | /** The trace id the caller was handed; joins to the server's report. */ | ||
| 84 | readonly traceId: string; | ||
| 85 | /** The name the caller chose for the connection — customer data. */ | ||
| 86 | readonly name: string; | ||
| 87 | /** The free text the caller typed — customer data, and the NUL carrier. */ | ||
| 88 | readonly description: string; | ||
| 89 | /** The whole client-visible failure, serialized. */ | ||
| 90 | readonly payload: string; | ||
| 91 | } | ||
| 92 | |||
| 93 | /** | ||
| 94 | * Create a connection whose description PostgreSQL will refuse, and return what | ||
| 95 | * the caller can see about the failure. | ||
| 96 | */ | ||
| 97 | const rejectedConnectionWrite = ( | ||
| 98 | client: Client, | ||
| 99 | integration: IntegrationSlug, | ||
| 100 | ): Effect.Effect<RejectedWrite> => | ||
| 101 | Effect.gen(function* () { | ||
| 102 | const name = ConnectionName.make( | ||
| 103 | `${SLUG.replaceAll("-", "")}${randomBytes(4).toString("hex")}`, | ||
| 104 | ); | ||
| 105 | const description = `desc-${randomBytes(6).toString("hex")}${NUL}tail`; | ||
| 106 | |||
| 107 | const exit = yield* Effect.exit( | ||
| 108 | client.connections.create({ | ||
| 109 | payload: { | ||
| 110 | owner: "org", | ||
| 111 | name, | ||
| 112 | integration, | ||
| 113 | template: AuthTemplateSlug.make("apiKey"), | ||
| 114 | description, | ||
| 115 | value: `sk-${randomBytes(4).toString("hex")}`, | ||
| 116 | }, | ||
| 117 | }), | ||
| 118 | ); | ||
| 119 | |||
| 120 | const failure = Exit.isFailure(exit) | ||
| 121 | ? exit.cause.reasons.find(Cause.isFailReason)?.error | ||
| 122 | : exit.value; | ||
| 123 | const error = failure as { readonly _tag?: string; readonly traceId?: string } | undefined; | ||
| 124 | |||
| 125 | // PostgreSQL refuses the NUL byte, so the write cannot succeed, and what | ||
| 126 | // comes back is the opaque internal failure — never the storage error. | ||
| 127 | expect(error?._tag, "the caller sees an opaque internal failure").toBe("InternalError"); | ||
| 128 | expect(error?.traceId ?? "", "the caller is handed a trace id to quote").toMatch( | ||
| 129 | /^[0-9a-f]{32}$/, | ||
| 130 | ); | ||
| 131 | |||
| 132 | return { | ||
| 133 | traceId: error?.traceId ?? "", | ||
| 134 | name, | ||
| 135 | description, | ||
| 136 | payload: JSON.stringify(failure), | ||
| 137 | }; | ||
| 138 | }); | ||
| 139 | |||
| 140 | /** | ||
| 141 | * The dev stack's stdout. The suite's globalsetup funnels it into the run | ||
| 142 | * artifacts; a scenario run against an already-booted instance (`cli up cloud`) | ||
| 143 | * reads that instance's log instead. | ||
| 144 | */ | ||
| 145 | const serverLogCandidates = [ | ||
| 146 | resolve(RUNS_DIR, "cloud", "server-logs", "boot.log"), | ||
| 147 | resolve(RUNS_DIR, "..", ".dev", "cloud.log"), | ||
| 148 | ]; | ||
| 149 | |||
| 150 | const readServerLog = (): string => { | ||
| 151 | const texts = serverLogCandidates.flatMap((path) => { | ||
| 152 | // oxlint-disable-next-line executor/no-try-catch-or-throw -- boundary: probing which of the two stdout sinks this run uses | ||
| 153 | try { | ||
| 154 | return [readFileSync(path, "utf8")]; | ||
| 155 | } catch { | ||
| 156 | return []; | ||
| 157 | } | ||
| 158 | }); | ||
| 159 | return texts.join("\n"); | ||
| 160 | }; | ||
| 161 | |||
| 162 | const REPORT_PREFIX = "[api] unhandled cause: "; | ||
| 163 | |||
| 164 | /** A stack frame in the logged cause — where the report's headline stops. */ | ||
| 165 | const STACK_FRAME = /^\s+at /; | ||
| 166 | |||
| 167 | interface FiledReport { | ||
| 168 | /** Type + message: what the reporter names and groups the report by. */ | ||
| 169 | readonly headline: string; | ||
| 170 | /** The whole record, headline and chained cause — what a diagnosis reads. */ | ||
| 171 | readonly full: string; | ||
| 172 | } | ||
| 173 | |||
| 174 | /** | ||
| 175 | * The report the server filed for one request. | ||
| 176 | * | ||
| 177 | * The headline is the captured cause's type and message up to the first stack | ||
| 178 | * frame — exactly what `Cause.prettyErrors` hands the reporter as the | ||
| 179 | * exception. The message is multi-line whenever the driver's text is | ||
| 180 | * (`Failed query: …\nparams: …`), so the whole headline has to be read, not | ||
| 181 | * just its first line. | ||
| 182 | * | ||
| 183 | * Found by walking back from the correlation record carrying the caller's trace | ||
| 184 | * id, so it is THIS request's report and not a neighbour's. | ||
| 185 | */ | ||
| 186 | const reportFor = (traceId: string): Effect.Effect<FiledReport, string> => | ||
| 187 | Effect.sync(() => { | ||
| 188 | const lines = readServerLog().split("\n"); | ||
| 189 | const correlated = lines.findLastIndex( | ||
| 190 | (line) => | ||
| 191 | line.includes('"event":"sentry_before_send_otel_correlation"') && | ||
| 192 | line.includes(`"sentry_event_id":"${traceId}"`), | ||
| 193 | ); | ||
| 194 | if (correlated === -1) return undefined; | ||
| 195 | const reported = lines | ||
| 196 | .slice(0, correlated) | ||
| 197 | .findLastIndex((line) => line.startsWith(REPORT_PREFIX)); | ||
| 198 | if (reported === -1) return undefined; | ||
| 199 | const block = [ | ||
| 200 | lines[reported]!.slice(REPORT_PREFIX.length), | ||
| 201 | ...lines.slice(reported + 1, correlated), | ||
| 202 | ]; | ||
| 203 | const end = block.slice(1).findIndex((line) => STACK_FRAME.test(line)); | ||
| 204 | return { | ||
| 205 | headline: block | ||
| 206 | .slice(0, end === -1 ? 1 : end + 1) | ||
| 207 | .join("\n") | ||
| 208 | .trimEnd(), | ||
| 209 | full: block.join("\n"), | ||
| 210 | }; | ||
| 211 | }).pipe( | ||
| 212 | Effect.filterOrFail( | ||
| 213 | (report): report is FiledReport => report !== undefined, | ||
| 214 | () => `no error report joined to trace id ${traceId} in the server log`, | ||
| 215 | ), | ||
| 216 | // The log is a file the dev stack appends to; the write lands moments after | ||
| 217 | // the response. Poll rather than sleep (~20s ceiling). | ||
| 218 | Effect.retry(Schedule.both(Schedule.spaced("500 millis"), Schedule.recurs(40))), | ||
| 219 | ); | ||
| 220 | |||
| 221 | scenario( | ||
| 222 | "Storage · a rejected write is reported without its SQL or the caller's data", | ||
| 223 | { timeout: 120_000 }, | ||
| 224 | Effect.gen(function* () { | ||
| 225 | const target = yield* Target; | ||
| 226 | const { client: apiClient } = yield* Api; | ||
| 227 | const identity = yield* target.newIdentity(); | ||
| 228 | const client = yield* apiClient(api, identity); | ||
| 229 | const integration = yield* registerIntegration(client); | ||
| 230 | |||
| 231 | const first = yield* rejectedConnectionWrite(client, integration); | ||
| 232 | const second = yield* rejectedConnectionWrite(client, integration); | ||
| 233 | |||
| 234 | for (const write of [first, second]) { | ||
| 235 | expect(write.payload, "the client payload carries no driver text").not.toContain( | ||
| 236 | "Failed query", | ||
| 237 | ); | ||
| 238 | expect(write.payload, "the client payload carries no bound parameter").not.toContain( | ||
| 239 | write.description, | ||
| 240 | ); | ||
| 241 | } | ||
| 242 | |||
| 243 | const report = yield* reportFor(first.traceId); | ||
| 244 | const headline = report.headline; | ||
| 245 | |||
| 246 | // The symptom: the statement and everything bound into it used to BE the | ||
| 247 | // headline, so the report was named after the customer's data. | ||
| 248 | expect(headline, "the report headline carries no statement text").not.toContain("Failed query"); | ||
| 249 | expect(headline, "the report headline carries no statement text").not.toContain("insert into"); | ||
| 250 | expect(headline, "the report headline carries no bound parameters").not.toContain("params:"); | ||
| 251 | expect(headline, "the report headline carries no user-typed description").not.toContain( | ||
| 252 | first.description, | ||
| 253 | ); | ||
| 254 | expect(headline, "the report headline carries no user-chosen connection name").not.toContain( | ||
| 255 | first.name, | ||
| 256 | ); | ||
| 257 | expect(headline, "the report headline carries no organization id").not.toContain("org_"); | ||
| 258 | |||
| 259 | // What it says instead: which operation failed, and how the database | ||
| 260 | // refused it — enough to act on, stable across calls. | ||
| 261 | expect(headline, "the report still names the failing operation").toContain("connection.create"); | ||
| 262 | expect(headline, "the report still names the database's error code").toContain("22021"); | ||
| 263 | |||
| 264 | // Shaping the headline must not mean throwing the diagnosis away: the | ||
| 265 | // driver's own text is still filed with the report, one level down, where | ||
| 266 | // it informs a fix instead of naming the report. | ||
| 267 | expect(report.full, "the driver's statement is still filed under the report").toContain( | ||
| 268 | "Failed query", | ||
| 269 | ); | ||
| 270 | |||
| 271 | // The fan-out: the two writes bound different names, descriptions and | ||
| 272 | // secrets, so their statements differ in every parameter. One defect, one | ||
| 273 | // report — not one report per set of values. | ||
| 274 | const secondReport = yield* reportFor(second.traceId); | ||
| 275 | expect( | ||
| 276 | secondReport.headline, | ||
| 277 | "a second rejected write with different values files the same report", | ||
| 278 | ).toBe(headline); | ||
| 279 | }), | ||
| 280 | ); | ||