Merge sandbox errors: onStop never throws, runs past 100 minutes are not stopped early, real failures logged, and scripts/ops/runner-errors.mjs to read them
6 files+965−80/6 viewed
| 391 | 391 | Not yet seen on Cloudflare itself: watch the first runs' logs for the | |
| 392 | 392 | `Docker: started` line, and `dockerd.log` if it does not come. | |
| 393 | 393 | ||
| 394 | + | #### Sandbox errors | |
| 395 | + | ||
| 396 | + | Each sandbox is a Durable Object of `g1t-runner`, and Cloudflare counts | |
| 397 | + | each of its invocations: the `run` call that starts it, `halt`, | |
| 398 | + | `noteBlocked` and `flagAbuse`, and its alarms. The containers library keeps | |
| 399 | + | an alarm going for as long as the container runs (each one waits up to | |
| 400 | + | three minutes), and runs `onStop` from the alarm after the container | |
| 401 | + | exits, so most of a sandbox's invocations are alarms. | |
| 402 | + | ||
| 403 | + | To see what the errors are, by namespace and status, and what was thrown: | |
| 404 | + | ||
| 405 | + | ```sh | |
| 406 | + | CLOUDFLARE_API_TOKEN=<token> node scripts/ops/runner-errors.mjs # the last 7 days | |
| 407 | + | CLOUDFLARE_API_TOKEN=<token> node scripts/ops/runner-errors.mjs --days 30 --json | |
| 408 | + | ``` | |
| 409 | + | ||
| 410 | + | The token needs Account Analytics: Read and Workers Observability: Read | |
| 411 | + | (Workers Scripts: Read adds namespace names). The report puts each message | |
| 412 | + | in a bucket and says whether it is expected: | |
| 413 | + | ||
| 414 | + | | Bucket | Expected | What it is | | |
| 415 | + | | --- | --- | --- | | |
| 416 | + | | `deploy_reset` | Yes | A runner deploy resets every sandbox's object, failing the alarm or call in flight. The container keeps running and the next alarm picks it up. | | |
| 417 | + | | `no_capacity` | Yes | No container instance was free (`max_instances`). The work fails to start and says so. | | |
| 418 | + | | `container_exited`, `caller_gone` | Yes | A container that stopped, or a caller that went away first. | | |
| 419 | + | | `stop_not_reported` | No | `onStop` could not tell a service that the sandbox stopped after two tries. The five-minute sweep catches the work up. | | |
| 420 | + | | `alarm_failed`, `not_started`, `storage`, `limits`, `other` | No | Read the message. | | |
| 421 | + | ||
| 422 | + | The runner logs these at error level, each with a fixed prefix you can | |
| 423 | + | search for in Workers Logs: | |
| 424 | + | ||
| 425 | + | - `sandbox not started` | |
| 426 | + | - `sandbox stop not reported` | |
| 427 | + | - `sandbox alarm failed` | |
| 428 | + | - `sandbox container error` | |
| 429 | + | - `sandbox not destroyed` | |
| 430 | + | ||
| 431 | + | `onStop` never throws. A throw would fail the alarm, which Cloudflare | |
| 432 | + | retries and counts as an error each time, running the whole stop again. | |
| 433 | + | A sandbox's run inside its time cap is not stopped for inactivity. The | |
| 434 | + | library's `sleepAfter` (100 minutes) would otherwise stop a run whose | |
| 435 | + | guardrails allow longer, up to 240 minutes, because the runner never | |
| 436 | + | fetches the container, so to the library every sandbox looks idle. | |
| 437 | + | ||
| 394 | 438 | ## Build speed | |
| 395 | 439 | ||
| 396 | 440 | Measured on the development machine (Windows, 32 cores, warm Cargo cache), |
| 1 | + | #!/usr/bin/env node | |
| 2 | + | // What are the runner's Durable Object errors? The sandboxes that run agent | |
| 3 | + | // attempts, workflow jobs and merge-queue builds are Durable Objects of the | |
| 4 | + | // g1t-runner Worker (services/runner: AttemptSandbox, Sandbox2Core, | |
| 5 | + | // Sandbox4Core). This asks Cloudflare, over the last N days: | |
| 6 | + | // | |
| 7 | + | // 1. GraphQL Analytics (durableObjectsInvocationsAdaptiveGroups): requests | |
| 8 | + | // and errors by namespace and status, and by day and status. | |
| 9 | + | // 2. Workers Observability (the telemetry query API): the runner's failed | |
| 10 | + | // invocations by class, event type (alarm, rpc, fetch) and outcome; the | |
| 11 | + | // exceptions they threw, by message; the runner's own error-level logs | |
| 12 | + | // (`sandbox stop not reported`, `sandbox alarm failed`, `sandbox not | |
| 13 | + | // started`, `sandbox container error`), by message; and a few recent | |
| 14 | + | // failed invocations in full. | |
| 15 | + | // | |
| 16 | + | // Each message is put in a bucket (`classify`): a deploy resetting the | |
| 17 | + | // object, no container free, a container that exited, and so on, so what is | |
| 18 | + | // expected and what is a bug can be told apart at a glance. | |
| 19 | + | // | |
| 20 | + | // Read-only: GraphQL queries, one Durable Objects listing for names, and | |
| 21 | + | // telemetry queries. Never prints the token. | |
| 22 | + | // | |
| 23 | + | // CLOUDFLARE_API_TOKEN=<token> node scripts/ops/runner-errors.mjs [--days 7] [--json] | |
| 24 | + | // | |
| 25 | + | // The token needs Account Analytics: Read (GraphQL) and Workers Observability: | |
| 26 | + | // Read (logs); Workers Scripts: Read adds namespace names. A part the token | |
| 27 | + | // cannot read is a note in the report, never the end of it. | |
| 28 | + | ||
| 29 | + | import { ACCOUNT_ID, cloudflareAuth } from "../deploy/cloudflare.mjs"; | |
| 30 | + | ||
| 31 | + | const API = "https://api.cloudflare.com/client/v4"; | |
| 32 | + | ||
| 33 | + | const HELP = `node scripts/ops/runner-errors.mjs [--days N] [--script NAME] [--samples N] [--json] [--keys] [--account <id>] | |
| 34 | + | ||
| 35 | + | The runner's Durable Object errors: requests and errors by namespace and | |
| 36 | + | status (GraphQL Analytics), and what failed and why (Workers Observability). | |
| 37 | + | ||
| 38 | + | --days N how far back, in days (default 7, at most 31) | |
| 39 | + | --script NAME the Worker (default g1t-runner) | |
| 40 | + | --samples N recent failed invocations shown in full (default 10) | |
| 41 | + | --json one JSON object, snake_case keys | |
| 42 | + | --keys also list the telemetry keys the runner's events have | |
| 43 | + | --account <id> the Cloudflare account (default CLOUDFLARE_ACCOUNT_ID, else g1t's) | |
| 44 | + | --help this text | |
| 45 | + | ||
| 46 | + | Needs CLOUDFLARE_API_TOKEN (Account Analytics: Read, Workers Observability: | |
| 47 | + | Read), or CLOUDFLARE_API_KEY with CLOUDFLARE_EMAIL. Exits 1 when nothing | |
| 48 | + | could be read.`; | |
| 49 | + | ||
| 50 | + | /** The command line. */ | |
| 51 | + | export function parseArgs(argv, env = process.env) { | |
| 52 | + | const option = (name) => { | |
| 53 | + | const at = argv.indexOf(name); | |
| 54 | + | return at >= 0 && argv[at + 1] && !argv[at + 1].startsWith("--") ? argv[at + 1] : null; | |
| 55 | + | }; | |
| 56 | + | const days = Number(option("--days") ?? NaN); | |
| 57 | + | const samples = Number(option("--samples") ?? NaN); | |
| 58 | + | return { | |
| 59 | + | help: argv.includes("--help") || argv.includes("-h"), | |
| 60 | + | json: argv.includes("--json"), | |
| 61 | + | keys: argv.includes("--keys"), | |
| 62 | + | days: Number.isFinite(days) && days > 0 ? Math.min(31, days) : 7, | |
| 63 | + | samples: Number.isFinite(samples) && samples >= 0 ? Math.min(100, Math.floor(samples)) : 10, | |
| 64 | + | script: option("--script") || "g1t-runner", | |
| 65 | + | account: option("--account") || env.CLOUDFLARE_ACCOUNT_ID || ACCOUNT_ID, | |
| 66 | + | }; | |
| 67 | + | } | |
| 68 | + | ||
| 69 | + | /** The window: the last `days` days up to `now`. */ | |
| 70 | + | export function windowOf(now, days) { | |
| 71 | + | return { start: new Date(now.getTime() - days * 86_400_000).toISOString(), end: now.toISOString() }; | |
| 72 | + | } | |
| 73 | + | ||
| 74 | + | /** | |
| 75 | + | * The GraphQL queries, each with variants tried in order when Cloudflare | |
| 76 | + | * refuses a field. Rows come back under `rows`. | |
| 77 | + | */ | |
| 78 | + | export const DO_QUERIES = [ | |
| 79 | + | { | |
| 80 | + | key: "by_namespace", | |
| 81 | + | label: "Durable Object requests by namespace and status", | |
| 82 | + | variants: [ | |
| 83 | + | { sum: ["requests", "errors", "wallTime"], dims: ["namespaceId", "status"] }, | |
| 84 | + | { sum: ["requests", "errors"], dims: ["namespaceId", "status"] }, | |
| 85 | + | { sum: ["requests"], dims: ["namespaceId", "status"] }, | |
| 86 | + | { sum: ["requests", "errors"], dims: ["namespaceId"] }, | |
| 87 | + | ], | |
| 88 | + | }, | |
| 89 | + | { | |
| 90 | + | key: "by_day", | |
| 91 | + | label: "Durable Object requests by day and status", | |
| 92 | + | variants: [ | |
| 93 | + | { sum: ["requests", "errors"], dims: ["date", "status"] }, | |
| 94 | + | { sum: ["requests"], dims: ["date", "status"] }, | |
| 95 | + | ], | |
| 96 | + | }, | |
| 97 | + | ]; | |
| 98 | + | ||
| 99 | + | /** One DO invocations query for one script, for one variant. */ | |
| 100 | + | export function doQuery(variant) { | |
| 101 | + | return `query RunnerErrors($accountTag: String!, $start: Time!, $end: Time!, $script: String!) { | |
| 102 | + | viewer { | |
| 103 | + | accounts(filter: { accountTag: $accountTag }) { | |
| 104 | + | rows: durableObjectsInvocationsAdaptiveGroups(limit: 10000, filter: { datetime_geq: $start, datetime_leq: $end, scriptName: $script }) { | |
| 105 | + | sum { ${variant.sum.join(" ")} } | |
| 106 | + | dimensions { ${variant.dims.join(" ")} } | |
| 107 | + | } | |
| 108 | + | } | |
| 109 | + | } | |
| 110 | + | }`; | |
| 111 | + | } | |
| 112 | + | ||
| 113 | + | const snake = (name) => name.replace(/[A-Z]/g, (letter) => `_${letter.toLowerCase()}`); | |
| 114 | + | ||
| 115 | + | /** | |
| 116 | + | * A GraphQL answer as rows: one per dimension combination, the first | |
| 117 | + | * dimension named through `names` (namespace ids to names), with each sum | |
| 118 | + | * and the error rate, largest first by requests. Throws with Cloudflare's | |
| 119 | + | * message when the answer has errors. | |
| 120 | + | */ | |
| 121 | + | export function parseDoGroups(body, variant, names = {}) { | |
| 122 | + | if (body?.errors?.length) throw new Error(body.errors.map((error) => error.message).join("; ").slice(0, 400)); | |
| 123 | + | const groups = body?.data?.viewer?.accounts?.[0]?.rows; | |
| 124 | + | if (!Array.isArray(groups)) throw new Error("no rows in the answer"); | |
| 125 | + | const rows = groups.map((group) => { | |
| 126 | + | const row = {}; | |
| 127 | + | variant.dims.forEach((dim, at) => { | |
| 128 | + | const value = group.dimensions?.[dim]; | |
| 129 | + | const text = value == null || value === "" ? "(none)" : String(value); | |
| 130 | + | row[snake(dim)] = at === 0 && names[text] ? names[text] : text; | |
| 131 | + | }); | |
| 132 | + | for (const field of variant.sum) row[snake(field)] = Number(group.sum?.[field] ?? 0); | |
| 133 | + | return row; | |
| 134 | + | }); | |
| 135 | + | const sortKey = variant.dims[0] === "date" ? null : "requests"; | |
| 136 | + | rows.sort((a, b) => (sortKey ? b.requests - a.requests : 0) || String(a[snake(variant.dims[0])]).localeCompare(String(b[snake(variant.dims[0])]))); | |
| 137 | + | const totals = Object.fromEntries(variant.sum.map((field) => [snake(field), rows.reduce((sum, row) => sum + row[snake(field)], 0)])); | |
| 138 | + | return { dims: variant.dims.map(snake), metrics: variant.sum.map(snake), rows, totals }; | |
| 139 | + | } | |
| 140 | + | ||
| 141 | + | /** | |
| 142 | + | * Requests and errors per status, summed over namespaces: which statuses | |
| 143 | + | * the errors are (`scriptThrewException`, `internalError`, | |
| 144 | + | * `clientDisconnected`, `exceededResources`, ...). | |
| 145 | + | */ | |
| 146 | + | export function byStatus(parsed) { | |
| 147 | + | if (!parsed.dims.includes("status")) return []; | |
| 148 | + | const out = new Map(); | |
| 149 | + | for (const row of parsed.rows) { | |
| 150 | + | const entry = out.get(row.status) ?? { status: row.status, requests: 0, errors: 0 }; | |
| 151 | + | entry.requests += row.requests ?? 0; | |
| 152 | + | entry.errors += row.errors ?? 0; | |
| 153 | + | out.set(row.status, entry); | |
| 154 | + | } | |
| 155 | + | return [...out.values()].sort((a, b) => b.requests - a.requests); | |
| 156 | + | } | |
| 157 | + | ||
| 158 | + | /** The telemetry keys the questions below group by and filter on. */ | |
| 159 | + | export const KEYS = { | |
| 160 | + | outcome: "$workers.outcome", | |
| 161 | + | eventType: "$workers.eventType", | |
| 162 | + | entrypoint: "$workers.entrypoint", | |
| 163 | + | error: "$metadata.error", | |
| 164 | + | message: "$metadata.message", | |
| 165 | + | level: "$metadata.level", | |
| 166 | + | }; | |
| 167 | + | ||
| 168 | + | /** Which key names the Worker: tried in order, the next when one finds nothing. */ | |
| 169 | + | export const SERVICE_KEYS = ["$workers.scriptName", "$metadata.service"]; | |
| 170 | + | ||
| 171 | + | const filter = (key, operation, value) => (value === undefined ? { key, operation, type: "string" } : { key, operation, type: "string", value }); | |
| 172 | + | ||
| 173 | + | /** | |
| 174 | + | * The telemetry questions: each a body for `POST .../workers/observability/ | |
| 175 | + | * telemetry/query`, for the Worker named under `serviceKey`. | |
| 176 | + | */ | |
| 177 | + | export function telemetryQuestions({ script, from, to, samples, serviceKey = SERVICE_KEYS[0] }) { | |
| 178 | + | const service = filter(serviceKey, "eq", script); | |
| 179 | + | const failed = filter(KEYS.outcome, "neq", "ok"); | |
| 180 | + | const base = { timeframe: { from, to }, limit: 100 }; | |
| 181 | + | const count = [{ operator: "count", alias: "events" }]; | |
| 182 | + | const group = (...keys) => keys.map((value) => ({ type: "string", value })); | |
| 183 | + | return [ | |
| 184 | + | { | |
| 185 | + | key: "failed_invocations", | |
| 186 | + | label: "Failed invocations by class, event and outcome", | |
| 187 | + | body: { | |
| 188 | + | ...base, | |
| 189 | + | queryId: "g1t-runner-failed-invocations", | |
| 190 | + | view: "calculations", | |
| 191 | + | parameters: { datasets: ["cloudflare-workers"], filters: [service, failed], calculations: count, groupBys: group(KEYS.entrypoint, KEYS.eventType, KEYS.outcome) }, | |
| 192 | + | }, | |
| 193 | + | }, | |
| 194 | + | { | |
| 195 | + | key: "exceptions", | |
| 196 | + | label: "Exceptions by message", | |
| 197 | + | body: { | |
| 198 | + | ...base, | |
| 199 | + | queryId: "g1t-runner-exceptions", | |
| 200 | + | view: "calculations", | |
| 201 | + | parameters: { datasets: ["cloudflare-workers"], filters: [service, filter(KEYS.error, "exists")], calculations: count, groupBys: group(KEYS.error) }, | |
| 202 | + | }, | |
| 203 | + | }, | |
| 204 | + | { | |
| 205 | + | key: "error_logs", | |
| 206 | + | label: "The runner's error-level logs by message", | |
| 207 | + | body: { | |
| 208 | + | ...base, | |
| 209 | + | queryId: "g1t-runner-error-logs", | |
| 210 | + | view: "calculations", | |
| 211 | + | parameters: { datasets: ["cloudflare-workers"], filters: [service, filter(KEYS.level, "eq", "error")], calculations: count, groupBys: group(KEYS.message) }, | |
| 212 | + | }, | |
| 213 | + | }, | |
| 214 | + | { | |
| 215 | + | key: "samples", | |
| 216 | + | label: "Recent failed invocations", | |
| 217 | + | body: { | |
| 218 | + | ...base, | |
| 219 | + | limit: Math.max(1, samples), | |
| 220 | + | queryId: "g1t-runner-failed-samples", | |
| 221 | + | view: "events", | |
| 222 | + | parameters: { datasets: ["cloudflare-workers"], filters: [service, failed] }, | |
| 223 | + | }, | |
| 224 | + | }, | |
| 225 | + | ]; | |
| 226 | + | } | |
| 227 | + | ||
| 228 | + | /** | |
| 229 | + | * A telemetry calculations answer as rows: each group's key values and its | |
| 230 | + | * count, largest first. Throws with Cloudflare's message when it failed. | |
| 231 | + | */ | |
| 232 | + | export function parseCalculations(body) { | |
| 233 | + | if (body?.success === false || body?.errors?.length) throw new Error(messagesOf(body)); | |
| 234 | + | const calculation = body?.result?.calculations?.[0]; | |
| 235 | + | if (!calculation) throw new Error("no calculations in the answer"); | |
| 236 | + | const rows = (calculation.aggregates ?? []).map((aggregate) => { | |
| 237 | + | const row = {}; | |
| 238 | + | for (const group of aggregate.groups ?? []) row[group.key] = group.value == null || group.value === "" ? "(none)" : String(group.value); | |
| 239 | + | row.count = Number(aggregate.value ?? aggregate.count ?? 0); | |
| 240 | + | return row; | |
| 241 | + | }); | |
| 242 | + | return rows.sort((a, b) => b.count - a.count); | |
| 243 | + | } | |
| 244 | + | ||
| 245 | + | /** A telemetry events answer as plain records: when, which class, event, outcome, and what went wrong. */ | |
| 246 | + | export function parseEvents(body) { | |
| 247 | + | if (body?.success === false || body?.errors?.length) throw new Error(messagesOf(body)); | |
| 248 | + | const events = body?.result?.events?.events ?? body?.result?.events ?? []; | |
| 249 | + | if (!Array.isArray(events)) throw new Error("no events in the answer"); | |
| 250 | + | return events.map((event) => { | |
| 251 | + | const workers = event.$workers ?? {}; | |
| 252 | + | const metadata = event.$metadata ?? {}; | |
| 253 | + | const at = event.timestamp ?? metadata.startTime ?? workers.timestamp; | |
| 254 | + | return { | |
| 255 | + | at: typeof at === "number" ? new Date(at).toISOString() : (at ?? null), | |
| 256 | + | entrypoint: workers.entrypoint ?? null, | |
| 257 | + | event_type: workers.eventType ?? null, | |
| 258 | + | outcome: workers.outcome ?? null, | |
| 259 | + | object: typeof workers.durableObjectId === "string" ? workers.durableObjectId.slice(0, 12) : null, | |
| 260 | + | error: metadata.error ?? null, | |
| 261 | + | message: metadata.message ?? (typeof event.source === "string" ? event.source : (event.source?.message ?? null)), | |
| 262 | + | }; | |
| 263 | + | }); | |
| 264 | + | } | |
| 265 | + | ||
| 266 | + | function messagesOf(body) { | |
| 267 | + | const errors = body?.errors ?? []; | |
| 268 | + | const text = errors.map((error) => error.message ?? JSON.stringify(error)).join("; "); | |
| 269 | + | return (text || `request failed${body?.status ? ` with ${body.status}` : ""}`).slice(0, 400); | |
| 270 | + | } | |
| 271 | + | ||
| 272 | + | /** | |
| 273 | + | * What a failure most likely is, from its message or outcome: a bucket and | |
| 274 | + | * whether it is expected. Order matters: the first match wins. | |
| 275 | + | */ | |
| 276 | + | export const BUCKETS = [ | |
| 277 | + | { bucket: "deploy_reset", expected: true, why: "a runner deploy reset the object mid-invocation", test: /code (was|has been) updated|reset because its code|new version of the (script|worker)|durable object reset/i }, | |
| 278 | + | { bucket: "stop_not_reported", expected: false, why: "onStop could not tell a service the sandbox stopped (now logged, not thrown)", test: /sandbox stop not reported/i }, | |
| 279 | + | { bucket: "alarm_failed", expected: false, why: "the sandbox's alarm threw (retried by Cloudflare)", test: /sandbox alarm failed/i }, | |
| 280 | + | { bucket: "no_capacity", expected: true, why: "no container instance free (max_instances, or provisioning)", test: /no container instance|max(imum)? concurrent instance|too many containers per second/i }, | |
| 281 | + | { bucket: "not_started", expected: false, why: "a sandbox could not start (guardrails unreadable, or the container would not start)", test: /sandbox not started|could not read this project's guardrails|did not start after|failed to start container/i }, | |
| 282 | + | { bucket: "container_exited", expected: true, why: "the container exited or was stopped (a finished run, a time cap, a stop)", test: /container exited|runtime signalled|exited before we could determine|crashed while checking for ports|exit code/i }, | |
| 283 | + | { bucket: "connection_lost", expected: false, why: "the connection to the container was lost", test: /network connection lost|disconnected/i }, | |
| 284 | + | { bucket: "storage", expected: false, why: "Durable Object storage failed or was overloaded", test: /storage|sqlite|overloaded/i }, | |
| 285 | + | { bucket: "limits", expected: false, why: "a CPU, memory or subrequest limit", test: /exceeded|too many subrequests|memory limit/i }, | |
| 286 | + | { bucket: "container_error", expected: false, why: "the containers library reported an error", test: /sandbox container error|container error/i }, | |
| 287 | + | ]; | |
| 288 | + | ||
| 289 | + | /** The bucket of one failure's message (or, failing that, its outcome). */ | |
| 290 | + | export function classify(message, outcome = null) { | |
| 291 | + | const text = String(message ?? ""); | |
| 292 | + | for (const bucket of BUCKETS) if (text && bucket.test.test(text)) return { bucket: bucket.bucket, expected: bucket.expected, why: bucket.why }; | |
| 293 | + | if (/canceled|cancelled|clientdisconnected|responsestreamdisconnected/i.test(String(outcome ?? ""))) { | |
| 294 | + | return { bucket: "caller_gone", expected: true, why: "the caller went away before the object answered" }; | |
| 295 | + | } | |
| 296 | + | return { bucket: "other", expected: false, why: "not recognised: read the message" }; | |
| 297 | + | } | |
| 298 | + | ||
| 299 | + | /** Rows of messages with counts, summed into buckets, largest first. */ | |
| 300 | + | export function bucketsOf(rows, messageKey) { | |
| 301 | + | const out = new Map(); | |
| 302 | + | for (const row of rows) { | |
| 303 | + | const found = classify(row[messageKey], row[KEYS.outcome]); | |
| 304 | + | const entry = out.get(found.bucket) ?? { ...found, count: 0 }; | |
| 305 | + | entry.count += row.count; | |
| 306 | + | out.set(found.bucket, entry); | |
| 307 | + | } | |
| 308 | + | return [...out.values()].sort((a, b) => b.count - a.count); | |
| 309 | + | } | |
| 310 | + | ||
| 311 | + | const number = (value) => (Number.isInteger(value) ? value.toLocaleString("en-US") : value.toLocaleString("en-US", { maximumFractionDigits: 2 })); | |
| 312 | + | const percent = (part, whole) => (whole > 0 ? `${((100 * part) / whole).toFixed(1)}%` : "-"); | |
| 313 | + | ||
| 314 | + | function table(rows, columns) { | |
| 315 | + | if (!rows.length) return [" (nothing in this window)"]; | |
| 316 | + | const cells = [columns.map((c) => c.title), ...rows.map((row) => columns.map((c) => c.value(row)))]; | |
| 317 | + | const widths = columns.map((_, at) => Math.max(...cells.map((row) => String(row[at]).length))); | |
| 318 | + | return cells.map((row) => " " + row.map((cell, at) => (columns[at].right ? String(cell).padStart(widths[at]) : String(cell).padEnd(widths[at]))).join(" ")); | |
| 319 | + | } | |
| 320 | + | ||
| 321 | + | /** The report as plain text. */ | |
| 322 | + | export function format(report, top = 25) { | |
| 323 | + | const lines = [`Durable Object errors of ${report.script} on account ${report.account}, ${report.start} to ${report.end}`]; | |
| 324 | + | for (const query of report.analytics) { | |
| 325 | + | lines.push("", query.label); | |
| 326 | + | if (query.error) { | |
| 327 | + | lines.push(` could not read: ${query.error}`); | |
| 328 | + | continue; | |
| 329 | + | } | |
| 330 | + | const columns = [ | |
| 331 | + | ...query.dims.map((dim) => ({ title: dim, value: (row) => row[dim] })), | |
| 332 | + | ...query.metrics.map((metric) => ({ title: metric, right: true, value: (row) => number(row[metric]) })), | |
| 333 | + | ]; | |
| 334 | + | if (query.metrics.includes("errors")) columns.push({ title: "error_rate", right: true, value: (row) => percent(row.errors, row.requests) }); | |
| 335 | + | lines.push(...table(query.rows.slice(0, top), columns)); | |
| 336 | + | lines.push(` total: ${Object.entries(query.totals).map(([metric, value]) => `${metric} ${number(value)}`).join(", ")}`); | |
| 337 | + | if (query.by_status?.length) { | |
| 338 | + | lines.push(" by status:"); | |
| 339 | + | lines.push(...table(query.by_status, [ | |
| 340 | + | { title: "status", value: (row) => row.status }, | |
| 341 | + | { title: "requests", right: true, value: (row) => number(row.requests) }, | |
| 342 | + | { title: "errors", right: true, value: (row) => number(row.errors) }, | |
| 343 | + | ]).map((line) => ` ${line}`)); | |
| 344 | + | } | |
| 345 | + | } | |
| 346 | + | for (const question of report.telemetry) { | |
| 347 | + | lines.push("", question.label); | |
| 348 | + | if (question.error) { | |
| 349 | + | lines.push(` could not read: ${question.error}`); | |
| 350 | + | continue; | |
| 351 | + | } | |
| 352 | + | if (question.key === "samples") { | |
| 353 | + | if (!question.rows.length) lines.push(" (none)"); | |
| 354 | + | for (const row of question.rows) { | |
| 355 | + | lines.push(` ${row.at ?? "?"} ${row.entrypoint ?? "?"} ${row.event_type ?? "?"} ${row.outcome ?? "?"}${row.object ? ` ${row.object}` : ""}`); | |
| 356 | + | if (row.error || row.message) lines.push(` ${String(row.error ?? row.message).slice(0, 300)}`); | |
| 357 | + | } | |
| 358 | + | continue; | |
| 359 | + | } | |
| 360 | + | const keys = Object.keys(question.rows[0] ?? {}).filter((key) => key !== "count"); | |
| 361 | + | lines.push(...table(question.rows.slice(0, top), [ | |
| 362 | + | ...keys.map((key) => ({ title: key, value: (row) => String(row[key] ?? "").slice(0, 120) })), | |
| 363 | + | { title: "count", right: true, value: (row) => number(row.count) }, | |
| 364 | + | ])); | |
| 365 | + | if (question.buckets?.length) { | |
| 366 | + | lines.push(" most likely:"); | |
| 367 | + | for (const bucket of question.buckets) lines.push(` ${String(number(bucket.count)).padStart(6)} ${bucket.bucket}${bucket.expected ? " (expected)" : ""}: ${bucket.why}`); | |
| 368 | + | } | |
| 369 | + | } | |
| 370 | + | if (report.keys) lines.push("", "Telemetry keys:", ...report.keys.map((key) => ` ${key}`)); | |
| 371 | + | if (report.notes.length) lines.push("", "Notes:", ...report.notes.map((note) => ` ${note}`)); | |
| 372 | + | return lines.join("\n"); | |
| 373 | + | } | |
| 374 | + | ||
| 375 | + | async function post(auth, path, body) { | |
| 376 | + | const response = await fetch(`${API}${path}`, { | |
| 377 | + | method: "POST", | |
| 378 | + | headers: { ...auth, "content-type": "application/json", "user-agent": "g1t-ops" }, | |
| 379 | + | body: JSON.stringify(body), | |
| 380 | + | }); | |
| 381 | + | const answer = await response.json().catch(() => ({ success: false, errors: [{ message: `HTTP ${response.status}, not JSON` }] })); | |
| 382 | + | if (!response.ok && !answer.errors?.length) answer.errors = [{ message: `HTTP ${response.status}` }]; | |
| 383 | + | return answer; | |
| 384 | + | } | |
| 385 | + | ||
| 386 | + | async function durableNames(auth, account) { | |
| 387 | + | const out = {}; | |
| 388 | + | try { | |
| 389 | + | for (let page = 1; page <= 10; page++) { | |
| 390 | + | const response = await fetch(`${API}/accounts/${account}/workers/durable_objects/namespaces?per_page=100&page=${page}`, { headers: { ...auth, "user-agent": "g1t-ops" } }); | |
| 391 | + | const body = await response.json(); | |
| 392 | + | if (!response.ok || !Array.isArray(body.result)) break; | |
| 393 | + | for (const item of body.result) if (item.id) out[item.id] = item.name ?? item.id; | |
| 394 | + | if (body.result.length < 100) break; | |
| 395 | + | } | |
| 396 | + | } catch { | |
| 397 | + | // Ids stand in for names. | |
| 398 | + | } | |
| 399 | + | return out; | |
| 400 | + | } | |
| 401 | + | ||
| 402 | + | async function analytics(auth, options, window, names) { | |
| 403 | + | return Promise.all( | |
| 404 | + | DO_QUERIES.map(async (query) => { | |
| 405 | + | let error = null; | |
| 406 | + | for (const variant of query.variants) { | |
| 407 | + | try { | |
| 408 | + | const body = await post(auth, "/graphql", { query: doQuery(variant), variables: { accountTag: options.account, start: window.start, end: window.end, script: options.script } }); | |
| 409 | + | const parsed = parseDoGroups(body, variant, names); | |
| 410 | + | return { key: query.key, label: query.label, ...parsed, by_status: query.key === "by_namespace" ? byStatus(parsed) : undefined }; | |
| 411 | + | } catch (thrown) { | |
| 412 | + | error ??= String(thrown.message ?? thrown); | |
| 413 | + | } | |
| 414 | + | } | |
| 415 | + | return { key: query.key, label: query.label, error }; | |
| 416 | + | }), | |
| 417 | + | ); | |
| 418 | + | } | |
| 419 | + | ||
| 420 | + | async function telemetry(auth, options, window) { | |
| 421 | + | const path = `/accounts/${options.account}/workers/observability/telemetry/query`; | |
| 422 | + | const from = Date.parse(window.start); | |
| 423 | + | const to = Date.parse(window.end); | |
| 424 | + | let results = null; | |
| 425 | + | for (const serviceKey of SERVICE_KEYS) { | |
| 426 | + | results = await Promise.all( | |
| 427 | + | telemetryQuestions({ script: options.script, from, to, samples: options.samples, serviceKey }).map(async (question) => { | |
| 428 | + | try { | |
| 429 | + | const body = await post(auth, path, question.body); | |
| 430 | + | if (question.key === "samples") return { key: question.key, label: question.label, rows: parseEvents(body) }; | |
| 431 | + | const rows = parseCalculations(body); | |
| 432 | + | const messageKey = question.key === "exceptions" ? KEYS.error : question.key === "error_logs" ? KEYS.message : null; | |
| 433 | + | return { key: question.key, label: question.label, rows, buckets: messageKey ? bucketsOf(rows, messageKey) : undefined }; | |
| 434 | + | } catch (error) { | |
| 435 | + | return { key: question.key, label: question.label, error: String(error.message ?? error) }; | |
| 436 | + | } | |
| 437 | + | }), | |
| 438 | + | ); | |
| 439 | + | // Another key names the Worker when this one found nothing at all. | |
| 440 | + | if (results.some((result) => result.rows?.length)) return { serviceKey, results }; | |
| 441 | + | } | |
| 442 | + | return { serviceKey: SERVICE_KEYS.at(-1), results }; | |
| 443 | + | } | |
| 444 | + | ||
| 445 | + | async function telemetryKeys(auth, options, window) { | |
| 446 | + | const body = await post(auth, `/accounts/${options.account}/workers/observability/telemetry/keys`, { | |
| 447 | + | timeframe: { from: Date.parse(window.start), to: Date.parse(window.end) }, | |
| 448 | + | datasets: ["cloudflare-workers"], | |
| 449 | + | filters: [filter(SERVICE_KEYS[0], "eq", options.script)], | |
| 450 | + | limit: 500, | |
| 451 | + | }); | |
| 452 | + | if (body?.success === false || body?.errors?.length) throw new Error(messagesOf(body)); | |
| 453 | + | return (body.result ?? []).map((key) => (typeof key === "string" ? key : `${key.key} (${key.type})`)).sort(); | |
| 454 | + | } | |
| 455 | + | ||
| 456 | + | async function main() { | |
| 457 | + | const options = parseArgs(process.argv.slice(2)); | |
| 458 | + | if (options.help) { | |
| 459 | + | console.log(HELP); | |
| 460 | + | return 0; | |
| 461 | + | } | |
| 462 | + | const auth = cloudflareAuth(); | |
| 463 | + | if (!auth) { | |
| 464 | + | console.error(`Set CLOUDFLARE_API_TOKEN to a token with Account Analytics: Read and Workers Observability: Read on account ${options.account}.`); | |
| 465 | + | return 2; | |
| 466 | + | } | |
| 467 | + | const window = windowOf(new Date(), options.days); | |
| 468 | + | const names = await durableNames(auth, options.account); | |
| 469 | + | const [graph, logs, keys] = await Promise.all([ | |
| 470 | + | analytics(auth, options, window, names), | |
| 471 | + | telemetry(auth, options, window), | |
| 472 | + | options.keys ? telemetryKeys(auth, options, window).catch((error) => [`could not list keys: ${error.message}`]) : Promise.resolve(null), | |
| 473 | + | ]); | |
| 474 | + | const notes = []; | |
| 475 | + | if (!Object.keys(names).length) notes.push("Namespace ids are not named: the token cannot read the Durable Objects listing (Workers Scripts: Read)."); | |
| 476 | + | notes.push(`Telemetry is filtered on ${logs.serviceKey}.`); | |
| 477 | + | const report = { account: options.account, script: options.script, start: window.start, end: window.end, analytics: graph, telemetry: logs.results, keys, notes }; | |
| 478 | + | console.log(options.json ? JSON.stringify(report, null, 2) : format(report)); | |
| 479 | + | const read = [...graph, ...logs.results].some((part) => !part.error); | |
| 480 | + | return read ? 0 : 1; | |
| 481 | + | } | |
| 482 | + | ||
| 483 | + | if (process.argv[1]?.replaceAll("\\", "/").endsWith("scripts/ops/runner-errors.mjs")) { | |
| 484 | + | main().then( | |
| 485 | + | (code) => process.exit(code), | |
| 486 | + | (error) => { | |
| 487 | + | console.error(`runner-errors: ${error.message}`); | |
| 488 | + | process.exit(1); | |
| 489 | + | }, | |
| 490 | + | ); | |
| 491 | + | } |
| 1 | + | // The runner's Durable Object error report, from answers shaped as | |
| 2 | + | // Cloudflare gives them, without the network. | |
| 3 | + | ||
| 4 | + | import assert from "node:assert/strict"; | |
| 5 | + | import { test } from "node:test"; | |
| 6 | + | ||
| 7 | + | import { | |
| 8 | + | DO_QUERIES, | |
| 9 | + | KEYS, | |
| 10 | + | SERVICE_KEYS, | |
| 11 | + | bucketsOf, | |
| 12 | + | byStatus, | |
| 13 | + | classify, | |
| 14 | + | doQuery, | |
| 15 | + | format, | |
| 16 | + | parseArgs, | |
| 17 | + | parseCalculations, | |
| 18 | + | parseDoGroups, | |
| 19 | + | parseEvents, | |
| 20 | + | telemetryQuestions, | |
| 21 | + | windowOf, | |
| 22 | + | } from "./runner-errors.mjs"; | |
| 23 | + | ||
| 24 | + | const answer = (rows) => ({ data: { viewer: { accounts: [{ rows }] } } }); | |
| 25 | + | const byNamespace = DO_QUERIES.find((query) => query.key === "by_namespace").variants[1]; | |
| 26 | + | ||
| 27 | + | test("the command line has defaults and bounds", () => { | |
| 28 | + | assert.deepEqual(parseArgs([], {}), { help: false, json: false, keys: false, days: 7, samples: 10, script: "g1t-runner", account: "1e6f2cffa3f445920836e8ebe446bb58" }); | |
| 29 | + | const options = parseArgs(["--days", "90", "--samples", "3", "--script", "other", "--json", "--keys"], { CLOUDFLARE_ACCOUNT_ID: "acct" }); | |
| 30 | + | assert.equal(options.days, 31); | |
| 31 | + | assert.equal(options.samples, 3); | |
| 32 | + | assert.equal(options.script, "other"); | |
| 33 | + | assert.equal(options.account, "acct"); | |
| 34 | + | assert.ok(options.json && options.keys); | |
| 35 | + | assert.equal(parseArgs(["--days", "soon"], {}).days, 7); | |
| 36 | + | }); | |
| 37 | + | ||
| 38 | + | test("the window is the last N days", () => { | |
| 39 | + | assert.deepEqual(windowOf(new Date("2026-10-08T12:00:00Z"), 7), { start: "2026-10-01T12:00:00.000Z", end: "2026-10-08T12:00:00.000Z" }); | |
| 40 | + | }); | |
| 41 | + | ||
| 42 | + | test("the query is for one script, with the variant's sums and dimensions", () => { | |
| 43 | + | const query = doQuery(byNamespace); | |
| 44 | + | assert.match(query, /durableObjectsInvocationsAdaptiveGroups\(limit: 10000, filter: \{ datetime_geq: \$start, datetime_leq: \$end, scriptName: \$script \}\)/); | |
| 45 | + | assert.match(query, /sum \{ requests errors \}/); | |
| 46 | + | assert.match(query, /dimensions \{ namespaceId status \}/); | |
| 47 | + | assert.match(query, /\$script: String!/); | |
| 48 | + | }); | |
| 49 | + | ||
| 50 | + | test("rows are named, summed per status and sorted by requests", () => { | |
| 51 | + | const body = answer([ | |
| 52 | + | { sum: { requests: 900, errors: 300 }, dimensions: { namespaceId: "ns1", status: "scriptThrewException" } }, | |
| 53 | + | { sum: { requests: 1000, errors: 0 }, dimensions: { namespaceId: "ns1", status: "success" } }, | |
| 54 | + | { sum: { requests: 40, errors: 20 }, dimensions: { namespaceId: "ns2", status: "internalError" } }, | |
| 55 | + | { sum: { requests: 10, errors: 0 }, dimensions: { namespaceId: "ns2", status: "success" } }, | |
| 56 | + | ]); | |
| 57 | + | const parsed = parseDoGroups(body, byNamespace, { ns1: "g1t-runner_AttemptSandbox" }); | |
| 58 | + | assert.deepEqual(parsed.dims, ["namespace_id", "status"]); | |
| 59 | + | assert.deepEqual(parsed.rows[0], { namespace_id: "g1t-runner_AttemptSandbox", status: "success", requests: 1000, errors: 0 }); | |
| 60 | + | assert.equal(parsed.rows.at(-1).namespace_id, "ns2"); | |
| 61 | + | assert.deepEqual(parsed.totals, { requests: 1950, errors: 320 }); | |
| 62 | + | assert.deepEqual(byStatus(parsed), [ | |
| 63 | + | { status: "success", requests: 1010, errors: 0 }, | |
| 64 | + | { status: "scriptThrewException", requests: 900, errors: 300 }, | |
| 65 | + | { status: "internalError", requests: 40, errors: 20 }, | |
| 66 | + | ]); | |
| 67 | + | }); | |
| 68 | + | ||
| 69 | + | test("Cloudflare's refusal becomes the error, so the next variant is tried", () => { | |
| 70 | + | assert.throws(() => parseDoGroups({ errors: [{ message: "unknown field wallTime" }] }, byNamespace), /unknown field wallTime/); | |
| 71 | + | assert.throws(() => parseDoGroups({ data: {} }, byNamespace), /no rows/); | |
| 72 | + | }); | |
| 73 | + | ||
| 74 | + | test("the telemetry questions filter on the script and on failures", () => { | |
| 75 | + | const questions = telemetryQuestions({ script: "g1t-runner", from: 1, to: 2, samples: 5 }); | |
| 76 | + | assert.deepEqual(questions.map((q) => q.key), ["failed_invocations", "exceptions", "error_logs", "samples"]); | |
| 77 | + | const failed = questions[0].body; | |
| 78 | + | assert.equal(failed.view, "calculations"); | |
| 79 | + | assert.deepEqual(failed.timeframe, { from: 1, to: 2 }); | |
| 80 | + | assert.deepEqual(failed.parameters.filters, [ | |
| 81 | + | { key: SERVICE_KEYS[0], operation: "eq", type: "string", value: "g1t-runner" }, | |
| 82 | + | { key: KEYS.outcome, operation: "neq", type: "string", value: "ok" }, | |
| 83 | + | ]); | |
| 84 | + | assert.deepEqual(failed.parameters.groupBys.map((g) => g.value), [KEYS.entrypoint, KEYS.eventType, KEYS.outcome]); | |
| 85 | + | assert.equal(questions[3].body.view, "events"); | |
| 86 | + | assert.equal(questions[3].body.limit, 5); | |
| 87 | + | const other = telemetryQuestions({ script: "g1t-runner", from: 1, to: 2, samples: 5, serviceKey: "$metadata.service" }); | |
| 88 | + | assert.equal(other[1].body.parameters.filters[0].key, "$metadata.service"); | |
| 89 | + | }); | |
| 90 | + | ||
| 91 | + | test("a calculations answer becomes rows with counts, largest first", () => { | |
| 92 | + | const body = { | |
| 93 | + | success: true, | |
| 94 | + | result: { | |
| 95 | + | calculations: [ | |
| 96 | + | { | |
| 97 | + | aggregates: [ | |
| 98 | + | { groups: [{ key: KEYS.entrypoint, value: "AttemptSandbox" }, { key: KEYS.eventType, value: "rpc" }], value: 12 }, | |
| 99 | + | { groups: [{ key: KEYS.entrypoint, value: "AttemptSandbox" }, { key: KEYS.eventType, value: "alarm" }], value: 540 }, | |
| 100 | + | { groups: [{ key: KEYS.entrypoint, value: "" }, { key: KEYS.eventType, value: "alarm" }], count: 3 }, | |
| 101 | + | ], | |
| 102 | + | }, | |
| 103 | + | ], | |
| 104 | + | }, | |
| 105 | + | }; | |
| 106 | + | assert.deepEqual(parseCalculations(body), [ | |
| 107 | + | { [KEYS.entrypoint]: "AttemptSandbox", [KEYS.eventType]: "alarm", count: 540 }, | |
| 108 | + | { [KEYS.entrypoint]: "AttemptSandbox", [KEYS.eventType]: "rpc", count: 12 }, | |
| 109 | + | { [KEYS.entrypoint]: "(none)", [KEYS.eventType]: "alarm", count: 3 }, | |
| 110 | + | ]); | |
| 111 | + | assert.throws(() => parseCalculations({ success: false, errors: [{ message: "Unauthorized" }] }), /Unauthorized/); | |
| 112 | + | assert.throws(() => parseCalculations({ success: true, result: {} }), /no calculations/); | |
| 113 | + | }); | |
| 114 | + | ||
| 115 | + | test("an events answer becomes plain records, the object id cut short", () => { | |
| 116 | + | const body = { | |
| 117 | + | success: true, | |
| 118 | + | result: { | |
| 119 | + | events: { | |
| 120 | + | events: [ | |
| 121 | + | { | |
| 122 | + | timestamp: Date.UTC(2026, 9, 7, 3, 4, 5), | |
| 123 | + | $workers: { entrypoint: "AttemptSandbox", eventType: "alarm", outcome: "exception", durableObjectId: "0123456789abcdef0123" }, | |
| 124 | + | $metadata: { error: "Durable Object reset because its code was updated." }, | |
| 125 | + | }, | |
| 126 | + | { $workers: { eventType: "rpc", outcome: "canceled" }, source: { message: "sandbox not started" } }, | |
| 127 | + | ], | |
| 128 | + | }, | |
| 129 | + | }, | |
| 130 | + | }; | |
| 131 | + | assert.deepEqual(parseEvents(body), [ | |
| 132 | + | { at: "2026-10-07T03:04:05.000Z", entrypoint: "AttemptSandbox", event_type: "alarm", outcome: "exception", object: "0123456789ab", error: "Durable Object reset because its code was updated.", message: null }, | |
| 133 | + | { at: null, entrypoint: null, event_type: "rpc", outcome: "canceled", object: null, error: null, message: "sandbox not started" }, | |
| 134 | + | ]); | |
| 135 | + | }); | |
| 136 | + | ||
| 137 | + | test("messages fall into buckets, expected or not", () => { | |
| 138 | + | assert.equal(classify("Durable Object reset because its code was updated.").bucket, "deploy_reset"); | |
| 139 | + | assert.equal(classify("Durable Object reset because its code was updated.").expected, true); | |
| 140 | + | assert.equal(classify("sandbox stop not reported checks report_checks failed with status 500").bucket, "stop_not_reported"); | |
| 141 | + | assert.equal(classify("sandbox alarm failed abc retry 2 storage overloaded").bucket, "alarm_failed"); | |
| 142 | + | assert.equal(classify("there is no container instance that can be provided to this durable object").bucket, "no_capacity"); | |
| 143 | + | assert.equal(classify("sandbox not started agent g1t could not read this project's guardrails: down").bucket, "not_started"); | |
| 144 | + | assert.equal(classify("container exited with unexpected exit code: 137").bucket, "container_exited"); | |
| 145 | + | assert.equal(classify("Network connection lost.").bucket, "connection_lost"); | |
| 146 | + | assert.equal(classify("", "canceled").bucket, "caller_gone"); | |
| 147 | + | assert.equal(classify("something new").bucket, "other"); | |
| 148 | + | assert.equal(classify("something new").expected, false); | |
| 149 | + | }); | |
| 150 | + | ||
| 151 | + | test("buckets sum the counts of their messages", () => { | |
| 152 | + | const rows = [ | |
| 153 | + | { [KEYS.error]: "Durable Object reset because its code was updated.", count: 200 }, | |
| 154 | + | { [KEYS.error]: "Network connection lost.", count: 7 }, | |
| 155 | + | { [KEYS.error]: "Durable Object reset because its code was updated (2).", count: 50 }, | |
| 156 | + | ]; | |
| 157 | + | assert.deepEqual( | |
| 158 | + | bucketsOf(rows, KEYS.error).map((b) => [b.bucket, b.count]), | |
| 159 | + | [ | |
| 160 | + | ["deploy_reset", 250], | |
| 161 | + | ["connection_lost", 7], | |
| 162 | + | ], | |
| 163 | + | ); | |
| 164 | + | }); | |
| 165 | + | ||
| 166 | + | test("the text report shows rates, statuses, buckets and what could not be read", () => { | |
| 167 | + | const parsed = parseDoGroups( | |
| 168 | + | answer([ | |
| 169 | + | { sum: { requests: 100, errors: 31 }, dimensions: { namespaceId: "ns1", status: "scriptThrewException" } }, | |
| 170 | + | { sum: { requests: 200, errors: 0 }, dimensions: { namespaceId: "ns1", status: "success" } }, | |
| 171 | + | ]), | |
| 172 | + | byNamespace, | |
| 173 | + | { ns1: "g1t-runner_AttemptSandbox" }, | |
| 174 | + | ); | |
| 175 | + | const rows = [{ [KEYS.error]: "Durable Object reset because its code was updated.", count: 31 }]; | |
| 176 | + | const text = format({ | |
| 177 | + | account: "acct", | |
| 178 | + | script: "g1t-runner", | |
| 179 | + | start: "2026-10-01T00:00:00.000Z", | |
| 180 | + | end: "2026-10-08T00:00:00.000Z", | |
| 181 | + | analytics: [ | |
| 182 | + | { key: "by_namespace", label: "By namespace", ...parsed, by_status: byStatus(parsed) }, | |
| 183 | + | { key: "by_day", label: "By day", error: "unknown field date" }, | |
| 184 | + | ], | |
| 185 | + | telemetry: [ | |
| 186 | + | { key: "exceptions", label: "Exceptions", rows, buckets: bucketsOf(rows, KEYS.error) }, | |
| 187 | + | { key: "samples", label: "Samples", rows: [{ at: "2026-10-07T00:00:00.000Z", entrypoint: "AttemptSandbox", event_type: "alarm", outcome: "exception", object: "abc", error: "boom", message: null }] }, | |
| 188 | + | ], | |
| 189 | + | keys: null, | |
| 190 | + | notes: ["Telemetry is filtered on $workers.scriptName."], | |
| 191 | + | }); | |
| 192 | + | assert.match(text, /g1t-runner_AttemptSandbox\s+scriptThrewException\s+100\s+31\s+31\.0%/); | |
| 193 | + | assert.match(text, /by status:/); | |
| 194 | + | assert.match(text, /could not read: unknown field date/); | |
| 195 | + | assert.match(text, /31\s+deploy_reset \(expected\)/); | |
| 196 | + | assert.match(text, /AttemptSandbox alarm exception abc/); | |
| 197 | + | assert.match(text, /\n {4}boom/); | |
| 198 | + | assert.doesNotMatch(text, /Bearer|authorization/i); | |
| 199 | + | }); |
| 95 | 95 | import { buildMentionPrompt, describeThread, handleMention, jobTokenRefusal, planMention } from "./mentions"; | |
| 96 | 96 | import { instructionsFor, repoInstructions, withBlock } from "./repo-instructions"; | |
| 97 | 97 | import { cancelTask, enqueueTask, handedOverStep, selfHostedRoute, taskEnv, taskRepo } from "./self-hosted"; | |
| 98 | + | import { answered, describeError, tellStopped, withinTimeCap } from "./lifecycle"; | |
| 98 | 99 | import { | |
| 99 | 100 | ABUSE_EXIT_CODE, | |
| 100 | 101 | ABUSE_HOST, | |
| ⋯ | |||
| 412 | 413 | * it and cleans up if it dies without reporting. | |
| 413 | 414 | */ | |
| 414 | 415 | export class AttemptSandbox extends Container<RunnerEnv> { | |
| 415 | − | // Past the longest time cap (implement, 90 minutes) and its alarm, so a | |
| 416 | − | // long run is never put to sleep before its own cap ends it. A finished | |
| 416 | + | // Past the longest default time cap (implement, 90 minutes) and its | |
| 417 | + | // alarm. A run whose guardrails allow longer (up to 240 minutes) is kept | |
| 418 | + | // past it by `onActivityExpired`, so only its own cap ends it. A finished | |
| 417 | 419 | // run's process exits and stops the sandbox well before this. | |
| 418 | 420 | sleepAfter = "100m"; | |
| 419 | 421 | // A guarded sandbox's HTTPS goes through `egress` too (guard.ts). | |
| ⋯ | |||
| 439 | 441 | ? withPlanLimits(await buildGuardFor(this.env.WORK, build.repo, build.kind, build.minutes, build.repoId, build.job, build.hosts), limits) | |
| 440 | 442 | : null; | |
| 441 | 443 | } catch (error) { | |
| 444 | + | // Thrown to the caller, which says why the work did not start; logged | |
| 445 | + | // here too, so a sandbox that never started is traceable on its own. | |
| 446 | + | console.error("sandbox not started", run.kind, describeError(error)); | |
| 442 | 447 | await this.settle(0); | |
| 443 | 448 | throw error; | |
| 444 | 449 | } | |
| ⋯ | |||
| 501 | 506 | await this.schedule(cap * 60 + ALARM_GRACE_SECONDS, "timeUp"); | |
| 502 | 507 | } | |
| 503 | 508 | } catch (error) { | |
| 509 | + | console.error("sandbox not started", run.kind, describeError(error)); | |
| 504 | 510 | await revokeCredentials(this.env.IDENTITY, this.ctx.storage, this.env.INTEGRATIONS); | |
| 505 | 511 | if (tracked) await this.closeRun("failed", `The sandbox could not start: ${String(error)}`); | |
| 506 | 512 | await this.settle(0); | |
| ⋯ | |||
| 632 | 638 | await this.remoteEnded(1, reason); | |
| 633 | 639 | return; | |
| 634 | 640 | } | |
| 635 | − | await this.destroy(); | |
| 641 | + | // A container already gone has nothing to stop; one that will not stop | |
| 642 | + | // is logged, and its time cap still ends it. | |
| 643 | + | await this.destroy().catch((error: unknown) => console.error("sandbox not destroyed", reason, describeError(error))); | |
| 644 | + | } | |
| 645 | + | ||
| 646 | + | /** | |
| 647 | + | * The library's `sleepAfter` has passed. The runner never fetches its | |
| 648 | + | * container, so to the library every sandbox looks idle: a run inside its | |
| 649 | + | * time cap keeps going, and the cap's own alarm (`timeUp`) ends it. Only | |
| 650 | + | * a sandbox with no cap is stopped for inactivity. | |
| 651 | + | */ | |
| 652 | + | override async onActivityExpired(): Promise<void> { | |
| 653 | + | const started = await this.ctx.storage.get<number>("started"); | |
| 654 | + | const cap = await this.ctx.storage.get<number>("timeCap"); | |
| 655 | + | if (withinTimeCap(started, cap, Date.now(), ALARM_GRACE_SECONDS)) return; | |
| 656 | + | await super.onActivityExpired(); | |
| 657 | + | } | |
| 658 | + | ||
| 659 | + | /** | |
| 660 | + | * A container that crashed or could not be reached, as the library tells | |
| 661 | + | * it. Logged at error level with the sandbox, never thrown: the library | |
| 662 | + | * ignores what this throws, and the stop that follows is handled by | |
| 663 | + | * `onStop` or by `run`, which says why the work did not start. | |
| 664 | + | */ | |
| 665 | + | override onError(error: unknown): void { | |
| 666 | + | console.error("sandbox container error", this.ctx.id.toString(), describeError(error)); | |
| 636 | 667 | } | |
| 637 | 668 | ||
| 638 | 669 | /** | |
| 670 | + | * The library's alarm: scheduled callbacks, the container's keep-alive, | |
| 671 | + | * and `onStop` once it has stopped. A failure is logged with the retry it | |
| 672 | + | * was, then thrown so Cloudflare tries the alarm again. | |
| 673 | + | */ | |
| 674 | + | override async alarm(alarmProps?: AlarmInvocationInfo): Promise<void> { | |
| 675 | + | try { | |
| 676 | + | await super.alarm(alarmProps); | |
| 677 | + | } catch (error) { | |
| 678 | + | console.error("sandbox alarm failed", this.ctx.id.toString(), `retry ${alarmProps?.retryCount ?? 0}`, describeError(error)); | |
| 679 | + | throw error; | |
| 680 | + | } | |
| 681 | + | } | |
| 682 | + | ||
| 683 | + | /** | |
| 639 | 684 | * A self-hosted runner's task ended (the actions service says so, or g1t | |
| 640 | 685 | * stopped it): everything a container's stop does, once. | |
| 641 | 686 | */ | |
| ⋯ | |||
| 713 | 758 | if (ended === "stopped" && run && STOP_ENDS.has(run.kind)) return; | |
| 714 | 759 | console.log("sandbox stopped", run?.kind, "exit", exitCode, reason); | |
| 715 | 760 | if (!run) return; | |
| 761 | + | // Never thrown: this runs in the sandbox's alarm, which a throw would | |
| 762 | + | // fail, retry and count as an error, running all of the above again. | |
| 763 | + | // What could not be told is logged, and the sweep catches it up. | |
| 764 | + | await tellStopped(run.kind, () => this.reportStopped(run, why, exitCode)); | |
| 765 | + | } | |
| 766 | + | ||
| 767 | + | /** | |
| 768 | + | * Tells whoever is waiting on the sandbox's work that it stopped without | |
| 769 | + | * finishing it. Each is refused harmlessly when the sandbox reported its | |
| 770 | + | * end before it stopped. Throws when the service could not be reached. | |
| 771 | + | */ | |
| 772 | + | private async reportStopped(run: Run, why: string | null, exitCode: number): Promise<void> { | |
| 716 | 773 | if (run.kind === "actions") { | |
| 717 | 774 | // Refused harmlessly if the job reported its end before it stopped. | |
| 718 | − | await this.env.ACTIONS.fetch("https://actions/rpc/job_report", { | |
| 775 | + | const response = await this.env.ACTIONS.fetch("https://actions/rpc/job_report", { | |
| 719 | 776 | method: "POST", | |
| 720 | 777 | headers: { "content-type": "application/json" }, | |
| 721 | 778 | body: JSON.stringify({ | |
| ⋯ | |||
| 724 | 781 | report: { kind: "done", conclusion: "failure", reason: why ?? "The runner stopped before the job finished." }, | |
| 725 | 782 | }), | |
| 726 | 783 | }); | |
| 784 | + | await answered("job_report", response); | |
| 727 | 785 | return; | |
| 728 | 786 | } | |
| 729 | 787 | // Nothing was pushed, so no pull request opens; why is in its log. | |
| ⋯ | |||
| 731 | 789 | if (run.kind === "backup") { | |
| 732 | 790 | // Refused harmlessly if the sandbox reported before it stopped; the | |
| 733 | 791 | // job is otherwise tried again later tonight. | |
| 734 | − | await reposClient(this.env.REPOS) | |
| 735 | − | .failBackup(run.jobId, run.token, why ?? `The sandbox exited with ${exitCode}.`) | |
| 736 | − | .catch((error: unknown) => console.log("backup failure not reported", run.jobId, String(error))); | |
| 792 | + | await reposClient(this.env.REPOS).failBackup(run.jobId, run.token, why ?? `The sandbox exited with ${exitCode}.`); | |
| 737 | 793 | return; | |
| 738 | 794 | } | |
| 739 | 795 | if (run.kind === "deploy") { | |
| 740 | 796 | // Refused harmlessly if the build reported its end before it stopped. | |
| 741 | − | await this.env.DEPLOYMENTS.fetch(`https://deployments/jobs/${run.deployId}/fail`, { | |
| 797 | + | const response = await this.env.DEPLOYMENTS.fetch(`https://deployments/jobs/${run.deployId}/fail`, { | |
| 742 | 798 | method: "POST", | |
| 743 | 799 | headers: { "content-type": "application/json" }, | |
| 744 | 800 | body: JSON.stringify({ token: run.token, message: why ?? "The build stopped before it finished." }), | |
| 745 | 801 | }); | |
| 802 | + | await answered("deploy fail", response); | |
| 746 | 803 | return; | |
| 747 | 804 | } | |
| 748 | 805 | const work = workClient(this.env.WORK); | |
| 1 | + | import assert from "node:assert/strict"; | |
| 2 | + | import { test } from "node:test"; | |
| 3 | + | ||
| 4 | + | import { answered, describeError, tellStopped, withinTimeCap } from "./lifecycle.ts"; | |
| 5 | + | ||
| 6 | + | const quiet = { waitMs: 0 }; | |
| 7 | + | ||
| 8 | + | test("a stop that is told the first time is told once and logs nothing", async () => { | |
| 9 | + | const logged: unknown[][] = []; | |
| 10 | + | let calls = 0; | |
| 11 | + | const told = await tellStopped("checks", async () => void calls++, { ...quiet, log: (...data) => logged.push(data) }); | |
| 12 | + | assert.equal(told, true); | |
| 13 | + | assert.equal(calls, 1); | |
| 14 | + | assert.deepEqual(logged, []); | |
| 15 | + | }); | |
| 16 | + | ||
| 17 | + | test("a stop that fails once is tried again, and gets through", async () => { | |
| 18 | + | const logged: unknown[][] = []; | |
| 19 | + | let calls = 0; | |
| 20 | + | const told = await tellStopped( | |
| 21 | + | "queue", | |
| 22 | + | async () => { | |
| 23 | + | calls++; | |
| 24 | + | if (calls === 1) throw new Error("report_queue failed with status 500"); | |
| 25 | + | }, | |
| 26 | + | { ...quiet, log: (...data) => logged.push(data) }, | |
| 27 | + | ); | |
| 28 | + | assert.equal(told, true); | |
| 29 | + | assert.equal(calls, 2); | |
| 30 | + | assert.deepEqual(logged, []); | |
| 31 | + | }); | |
| 32 | + | ||
| 33 | + | test("a stop that cannot be told never throws, and is logged with what and why", async () => { | |
| 34 | + | const logged: unknown[][] = []; | |
| 35 | + | let calls = 0; | |
| 36 | + | const told = await tellStopped( | |
| 37 | + | "actions", | |
| 38 | + | async () => { | |
| 39 | + | calls++; | |
| 40 | + | throw new Error("job_report answered 503"); | |
| 41 | + | }, | |
| 42 | + | { ...quiet, log: (...data) => logged.push(data) }, | |
| 43 | + | ); | |
| 44 | + | assert.equal(told, false); | |
| 45 | + | assert.equal(calls, 2); | |
| 46 | + | assert.deepEqual(logged, [["sandbox stop not reported", "actions", "job_report answered 503"]]); | |
| 47 | + | }); | |
| 48 | + | ||
| 49 | + | test("whatever is thrown, even nothing, is logged as one line", async () => { | |
| 50 | + | const logged: unknown[][] = []; | |
| 51 | + | await tellStopped("plan", () => Promise.reject(undefined), { ...quiet, attempts: 1, log: (...data) => logged.push(data) }); | |
| 52 | + | assert.deepEqual(logged, [["sandbox stop not reported", "plan", "no reason given"]]); | |
| 53 | + | assert.equal(describeError("gone"), "gone"); | |
| 54 | + | assert.equal(describeError({ code: 7 }), '{"code":7}'); | |
| 55 | + | assert.equal(describeError(new TypeError("bad")), "bad"); | |
| 56 | + | }); | |
| 57 | + | ||
| 58 | + | test("a service that cannot answer is a failure; one that refuses is not", async () => { | |
| 59 | + | await answered("job_report", new Response("{}", { status: 200 })); | |
| 60 | + | // The deployments service's answer for a build that already finished. | |
| 61 | + | await answered("deploy fail", new Response("{}", { status: 404 })); | |
| 62 | + | await answered("job_report", new Response("{}", { status: 409 })); | |
| 63 | + | await assert.rejects(answered("job_report", new Response("worker threw", { status: 500 })), /job_report answered 500: worker threw/); | |
| 64 | + | await assert.rejects(answered("deploy fail", new Response("", { status: 503 })), /^Error: deploy fail answered 503$/); | |
| 65 | + | await assert.rejects(answered("job_report", new Response("slow down", { status: 429 })), /429/); | |
| 66 | + | }); | |
| 67 | + | ||
| 68 | + | test("a run inside its time cap is not stopped for inactivity", () => { | |
| 69 | + | const started = Date.UTC(2026, 9, 8, 12, 0, 0); | |
| 70 | + | const minute = 60_000; | |
| 71 | + | const grace = 180; | |
| 72 | + | // A 240-minute cap outlives the 100-minute sleepAfter. | |
| 73 | + | assert.equal(withinTimeCap(started, 240, started + 100 * minute, grace), true); | |
| 74 | + | assert.equal(withinTimeCap(started, 240, started + 242 * minute, grace), true); | |
| 75 | + | // Past the cap and its alarm's grace: the library may stop it. | |
| 76 | + | assert.equal(withinTimeCap(started, 240, started + 243 * minute, grace), false); | |
| 77 | + | assert.equal(withinTimeCap(started, 90, started + 100 * minute, grace), false); | |
| 78 | + | }); | |
| 79 | + | ||
| 80 | + | test("a sandbox with no cap or no start is stopped for inactivity as before", () => { | |
| 81 | + | const now = Date.now(); | |
| 82 | + | assert.equal(withinTimeCap(undefined, 90, now, 180), false); | |
| 83 | + | assert.equal(withinTimeCap(now - 1000, undefined, now, 180), false); | |
| 84 | + | assert.equal(withinTimeCap(now - 1000, null, now, 180), false); | |
| 85 | + | assert.equal(withinTimeCap(now - 1000, 0, now, 180), false); | |
| 86 | + | }); |
| 1 | + | /** | |
| 2 | + | * How a sandbox's Durable Object handles the end of its container without | |
| 3 | + | * failing the invocation it happens in. The containers library calls | |
| 4 | + | * `onStop` from the object's alarm: a stop hook that throws fails that | |
| 5 | + | * alarm, which Cloudflare retries and counts as an error each time, and | |
| 6 | + | * which runs the whole hook again. So the hook's calls to other services | |
| 7 | + | * go through `tellStopped`, which tries twice and logs at error level, and | |
| 8 | + | * never throws. Pure, so it is tested on its own. | |
| 9 | + | */ | |
| 10 | + | ||
| 11 | + | /** How long `tellStopped` waits before its second try. */ | |
| 12 | + | export const RETRY_AFTER_MS = 500; | |
| 13 | + | ||
| 14 | + | /** | |
| 15 | + | * Tells another service that a sandbox stopped: `step` runs, and once more | |
| 16 | + | * if it throws. Never throws: a step that fails twice is logged with | |
| 17 | + | * `log` as `sandbox stop not reported`, with what and why, so it shows in | |
| 18 | + | * the runner's logs at error level and the five-minute sweep picks the | |
| 19 | + | * work up instead. Returns whether it got through. | |
| 20 | + | */ | |
| 21 | + | export async function tellStopped( | |
| 22 | + | what: string, | |
| 23 | + | step: () => Promise<unknown>, | |
| 24 | + | options: { log?: (...data: unknown[]) => void; attempts?: number; waitMs?: number } = {}, | |
| 25 | + | ): Promise<boolean> { | |
| 26 | + | const log = options.log ?? console.error; | |
| 27 | + | const attempts = Math.max(1, options.attempts ?? 2); | |
| 28 | + | let last: unknown = null; | |
| 29 | + | for (let attempt = 1; attempt <= attempts; attempt++) { | |
| 30 | + | try { | |
| 31 | + | await step(); | |
| 32 | + | return true; | |
| 33 | + | } catch (error) { | |
| 34 | + | last = error; | |
| 35 | + | if (attempt < attempts) await new Promise((resolve) => setTimeout(resolve, options.waitMs ?? RETRY_AFTER_MS)); | |
| 36 | + | } | |
| 37 | + | } | |
| 38 | + | log("sandbox stop not reported", what, describeError(last)); | |
| 39 | + | return false; | |
| 40 | + | } | |
| 41 | + | ||
| 42 | + | /** | |
| 43 | + | * A service binding's answer as a step's outcome: a 5xx (or 429) throws, so | |
| 44 | + | * `tellStopped` tries again and logs it. A refusal is not a failure: the | |
| 45 | + | * work already reported its end, and services say so with `ok: false` or a | |
| 46 | + | * 4xx (the deployments service answers 404 for a build that has finished). | |
| 47 | + | */ | |
| 48 | + | export async function answered(what: string, response: Response): Promise<void> { | |
| 49 | + | if (response.status < 500 && response.status !== 429) return; | |
| 50 | + | const body = await response.text().catch(() => ""); | |
| 51 | + | throw new Error(`${what} answered ${response.status}${body ? `: ${body.slice(0, 200)}` : ""}`); | |
| 52 | + | } | |
| 53 | + | ||
| 54 | + | /** | |
| 55 | + | * Whether a sandbox whose `sleepAfter` has passed is still inside its run's | |
| 56 | + | * time cap, and so keeps running: the cap, not inactivity, ends a run (the | |
| 57 | + | * runner never fetches the container, so to the library every sandbox looks | |
| 58 | + | * idle). Without a cap or a start time, `sleepAfter` applies. | |
| 59 | + | */ | |
| 60 | + | export function withinTimeCap( | |
| 61 | + | started: number | null | undefined, | |
| 62 | + | capMinutes: number | null | undefined, | |
| 63 | + | now: number, | |
| 64 | + | graceSeconds: number, | |
| 65 | + | ): boolean { | |
| 66 | + | if (typeof started !== "number" || typeof capMinutes !== "number" || capMinutes <= 0) return false; | |
| 67 | + | return now < started + (capMinutes * 60 + graceSeconds) * 1000; | |
| 68 | + | } | |
| 69 | + | ||
| 70 | + | /** An error as one line, for a log: its message, or what was thrown. */ | |
| 71 | + | export function describeError(error: unknown): string { | |
| 72 | + | if (error instanceof Error) return error.message || error.name; | |
| 73 | + | if (error === undefined) return "no reason given"; | |
| 74 | + | if (typeof error === "string") return error; | |
| 75 | + | try { | |
| 76 | + | return JSON.stringify(error) ?? String(error); | |
| 77 | + | } catch { | |
| 78 | + | return String(error); | |
| 79 | + | } | |
| 80 | + | } |