| 1 | /** |
| 2 | * Tail events from g1t.page, as rows. Two Workers name this service as |
| 3 | * their Tail Worker, and each tells half of a request: |
| 4 | * |
| 5 | * - **The dispatcher** (`services/pages`), in front of every app: it |
| 6 | * writes one `g1t-request` line per request (`REQUEST_MARK`) with the |
| 7 | * request's id, the app's script and the trace it began or continued, |
| 8 | * and its tail event has the status, the time taken, the method, the |
| 9 | * address and where in the world it was served. Every request is here, |
| 10 | * including those a site's files answered without running its code. |
| 11 | * - **The app itself**, when its code ran: the logs it wrote, the |
| 12 | * exceptions it threw, its CPU time and outcome, and its tags |
| 13 | * (`TELEMETRY_TAG`: the project and the deployment). The dispatcher |
| 14 | * handed it the request's id (`x-g1t-request-id`) and a `traceparent`, |
| 15 | * which is how the halves meet, and how spans an OpenTelemetry SDK in |
| 16 | * the app sends join the request's trace. |
| 17 | * |
| 18 | * Halves arrive apart, in either order; the project's store merges them |
| 19 | * by id (./store.ts). The dispatcher's half names the project the |
| 20 | * deployments service noted for the app's hostname; when it had none yet, |
| 21 | * the service looks the script up itself (./index.ts). |
| 22 | */ |
| 23 | import { TELEMETRY_TAG, type Attributes, type TelemetryLog, type TelemetryRequest } from "@g1t/contracts/telemetry"; |
| 24 | |
| 25 | import { emptyBatch, type Batch } from "./batch.ts"; |
| 26 | import { sizeOf } from "./quota.ts"; |
| 27 | import { clip, hostPath, randomId, route, severityNumber, severityOf, text } from "./shape.ts"; |
| 28 | |
| 29 | /** The first argument of the dispatcher's line for each request. */ |
| 30 | export const REQUEST_MARK = "g1t-request"; |
| 31 | /** The header the dispatcher hands each app with the request's id. */ |
| 32 | export const REQUEST_ID_HEADER = "x-g1t-request-id"; |
| 33 | |
| 34 | /** |
| 35 | * What the dispatcher's line says: the request, its app, and what the |
| 36 | * deployments service noted for the app's hostname (`AppTelemetry` there), |
| 37 | * when the dispatcher had it. |
| 38 | */ |
| 39 | export type RequestMark = { |
| 40 | id: string; |
| 41 | script: string; |
| 42 | trace_id: string; |
| 43 | app?: { project: string; deployment: string | null; environment: string | null; service: string; commit: string | null } | null; |
| 44 | }; |
| 45 | |
| 46 | /** A request's half, merged with the other half by id in the store. */ |
| 47 | export type RequestHalf = Partial<TelemetryRequest> & { id: string; half: "edge" | "app" }; |
| 48 | |
| 49 | /** Rows for one project, or for one script whose project is not known yet. */ |
| 50 | export type TailGroup = { project_id: string | null; script: string; batch: Batch; halves: RequestHalf[] }; |
| 51 | |
| 52 | /** What a tail event is about: its project and deployment from its tags. */ |
| 53 | function tagged(tags: readonly string[] | undefined): { project_id: string | null; deployment_id: string | null; environment: string | null; service: string } { |
| 54 | let service = ""; |
| 55 | let project_id: string | null = null; |
| 56 | let deployment_id: string | null = null; |
| 57 | let environment: string | null = null; |
| 58 | for (const tag of tags ?? []) { |
| 59 | if (tag.startsWith(TELEMETRY_TAG.project)) project_id = tag.slice(TELEMETRY_TAG.project.length); |
| 60 | else if (tag.startsWith(TELEMETRY_TAG.deployment)) deployment_id = tag.slice(TELEMETRY_TAG.deployment.length); |
| 61 | else if (tag === "production" || tag === "preview") environment = tag; |
| 62 | // `project:<workspace>/<slug>`: the service is the project's name. |
| 63 | else if (tag.startsWith("project:")) service = tag.slice(tag.indexOf("/") + 1); |
| 64 | } |
| 65 | return { project_id, deployment_id, environment, service }; |
| 66 | } |
| 67 | |
| 68 | function markOf(item: TraceItem): RequestMark | null { |
| 69 | for (const log of item.logs) { |
| 70 | const message = log.message as unknown; |
| 71 | if (!Array.isArray(message) || message[0] !== REQUEST_MARK) continue; |
| 72 | const mark = message[1] as Partial<RequestMark> | undefined; |
| 73 | if (mark && typeof mark.id === "string" && typeof mark.script === "string") { |
| 74 | const app = mark.app && typeof mark.app.project === "string" ? mark.app : null; |
| 75 | return { id: mark.id, script: mark.script, trace_id: typeof mark.trace_id === "string" ? mark.trace_id : "", app }; |
| 76 | } |
| 77 | } |
| 78 | return null; |
| 79 | } |
| 80 | |
| 81 | function fetchInfo(item: TraceItem): TraceItemFetchEventInfo | null { |
| 82 | const event = item.event as TraceItemFetchEventInfo | null; |
| 83 | return event && typeof event === "object" && "request" in event ? event : null; |
| 84 | } |
| 85 | |
| 86 | function triggerOf(item: TraceItem): string { |
| 87 | const event = item.event as Record<string, unknown> | null; |
| 88 | if (!event) return "other"; |
| 89 | if ("request" in event) return "fetch"; |
| 90 | if ("cron" in event) return "scheduled"; |
| 91 | if ("queue" in event) return "queue"; |
| 92 | if ("mailFrom" in event) return "email"; |
| 93 | if ("rpcMethod" in event) return "rpc"; |
| 94 | if ("scheduledTime" in event) return "alarm"; |
| 95 | return "other"; |
| 96 | } |
| 97 | |
| 98 | /** The `traceparent` header's trace id, if it is a valid one. */ |
| 99 | export function traceIdOf(traceparent: string | undefined | null): string | null { |
| 100 | const m = /^[0-9a-f]{2}-([0-9a-f]{32})-([0-9a-f]{16})-[0-9a-f]{2}$/.exec((traceparent ?? "").trim().toLowerCase()); |
| 101 | return m && !/^0+$/.test(m[1]) ? m[1] : null; |
| 102 | } |
| 103 | |
| 104 | /** The status code of an event that failed before answering: what the visitor got. */ |
| 105 | function failedStatus(outcome: string): number | null { |
| 106 | if (outcome === "ok" || outcome === "canceled" || outcome === "responseStreamDisconnected") return null; |
| 107 | return outcome === "exceededCpu" || outcome === "exceededMemory" ? 503 : 500; |
| 108 | } |
| 109 | |
| 110 | /** Tail events as rows, grouped by the project (or, for the dispatcher's half, the script) they are of. */ |
| 111 | export function readTail(events: readonly TraceItem[]): TailGroup[] { |
| 112 | const groups = new Map<string, TailGroup>(); |
| 113 | const group = (project_id: string | null, script: string): TailGroup => { |
| 114 | const key = project_id ?? `script:${script}`; |
| 115 | let g = groups.get(key); |
| 116 | if (!g) groups.set(key, (g = { project_id, script, batch: emptyBatch(), halves: [] })); |
| 117 | return g; |
| 118 | }; |
| 119 | |
| 120 | for (const item of events) { |
| 121 | const time = (item.eventTimestamp ?? Date.now()) * 1000; |
| 122 | const info = fetchInfo(item); |
| 123 | const mark = markOf(item); |
| 124 | |
| 125 | if (mark) { |
| 126 | // The dispatcher's half: every request, whatever answered it. |
| 127 | const g = group(mark.app?.project ?? null, mark.script); |
| 128 | const where = info ? hostPath(info.request.url) : null; |
| 129 | const cf = (info?.request.cf ?? {}) as { colo?: string; country?: string }; |
| 130 | const status = info?.response?.status ?? failedStatus(item.outcome); |
| 131 | g.halves.push({ |
| 132 | id: mark.id, |
| 133 | half: "edge", |
| 134 | ...(mark.app |
| 135 | ? { |
| 136 | service: mark.app.service, |
| 137 | environment: mark.app.environment, |
| 138 | deployment_id: mark.app.deployment, |
| 139 | commit_sha: mark.app.commit, |
| 140 | source: "cloudflare" as const, |
| 141 | } |
| 142 | : {}), |
| 143 | time_us: time, |
| 144 | duration_us: Math.round(item.wallTime * 1000), |
| 145 | trigger: "fetch", |
| 146 | method: info?.request.method ?? null, |
| 147 | url: where?.url ?? null, |
| 148 | route: where ? route(where.path) : null, |
| 149 | status, |
| 150 | region: cf.colo ?? null, |
| 151 | country: cf.country ?? null, |
| 152 | trace_id: mark.trace_id || null, |
| 153 | }); |
| 154 | g.batch.bytes += sizeOf(g.halves[g.halves.length - 1]); |
| 155 | continue; |
| 156 | } |
| 157 | |
| 158 | const tags = tagged(item.scriptTags); |
| 159 | if (!tags.project_id) continue; |
| 160 | const g = group(tags.project_id, item.scriptName ?? ""); |
| 161 | const headers = info?.request.headers ?? {}; |
| 162 | const id = headers[REQUEST_ID_HEADER] || randomId(); |
| 163 | const trace_id = traceIdOf(headers.traceparent); |
| 164 | const origin = { |
| 165 | service: tags.service, |
| 166 | environment: tags.environment, |
| 167 | deployment_id: tags.deployment_id, |
| 168 | commit_sha: null, |
| 169 | source: "cloudflare" as const, |
| 170 | }; |
| 171 | |
| 172 | const logs: TelemetryLog[] = item.logs.map((log) => { |
| 173 | const number = severityNumber(log.level); |
| 174 | return { |
| 175 | ...origin, |
| 176 | id: randomId(), |
| 177 | time_us: log.timestamp * 1000, |
| 178 | severity: severityOf(number), |
| 179 | severity_number: number, |
| 180 | body: clip(text(log.message)), |
| 181 | trace_id, |
| 182 | span_id: null, |
| 183 | request_id: id, |
| 184 | attributes: (log.level === "log" ? {} : { "log.level": log.level }) as Attributes, |
| 185 | }; |
| 186 | }); |
| 187 | for (const e of item.exceptions) { |
| 188 | logs.push({ |
| 189 | ...origin, |
| 190 | id: randomId(), |
| 191 | time_us: e.timestamp * 1000, |
| 192 | severity: "error", |
| 193 | severity_number: 17, |
| 194 | body: clip(`${e.name}: ${e.message}${e.stack ? `\n${e.stack}` : ""}`), |
| 195 | trace_id, |
| 196 | span_id: null, |
| 197 | request_id: id, |
| 198 | attributes: { "exception.type": e.name, "exception.message": clip(e.message, 4096) }, |
| 199 | }); |
| 200 | g.batch.errors.push({ ...origin, time_us: e.timestamp * 1000, name: e.name, message: e.message, stack: e.stack ?? null, request_id: id, trace_id }); |
| 201 | } |
| 202 | if (item.truncated) { |
| 203 | logs.push({ |
| 204 | ...origin, |
| 205 | id: randomId(), |
| 206 | time_us: time, |
| 207 | severity: "warn", |
| 208 | severity_number: 13, |
| 209 | body: "Cloudflare cut this request's logs short: it wrote more than a tail event holds.", |
| 210 | trace_id, |
| 211 | span_id: null, |
| 212 | request_id: id, |
| 213 | attributes: {}, |
| 214 | }); |
| 215 | } |
| 216 | g.batch.logs.push(...logs); |
| 217 | |
| 218 | const where = info ? hostPath(info.request.url) : null; |
| 219 | const status = info?.response?.status ?? failedStatus(item.outcome); |
| 220 | const first = item.exceptions[0]; |
| 221 | g.halves.push({ |
| 222 | ...origin, |
| 223 | id, |
| 224 | half: "app", |
| 225 | time_us: time, |
| 226 | duration_us: Math.round(item.wallTime * 1000), |
| 227 | trigger: triggerOf(item), |
| 228 | method: info?.request.method ?? null, |
| 229 | url: where?.url ?? null, |
| 230 | route: where ? route(where.path) : null, |
| 231 | status, |
| 232 | outcome: item.outcome, |
| 233 | cpu_ms: item.cpuTime, |
| 234 | trace_id, |
| 235 | log_count: logs.length, |
| 236 | error: first |
| 237 | ? { name: first.name, message: clip(first.message, 2048) } |
| 238 | : item.outcome !== "ok" && item.outcome !== "canceled" |
| 239 | ? { name: item.outcome, message: outcomeText(item.outcome) } |
| 240 | : null, |
| 241 | }); |
| 242 | g.batch.bytes += sizeOf(g.halves[g.halves.length - 1]) + logs.reduce((n, l) => n + sizeOf(l), 0); |
| 243 | } |
| 244 | return [...groups.values()]; |
| 245 | } |
| 246 | |
| 247 | /** What Cloudflare's outcome means, for the request's error line. */ |
| 248 | export function outcomeText(outcome: string): string { |
| 249 | switch (outcome) { |
| 250 | case "exception": |
| 251 | return "The code threw before it answered."; |
| 252 | case "exceededCpu": |
| 253 | return "The request used more CPU time than it is allowed."; |
| 254 | case "exceededMemory": |
| 255 | return "The isolate ran out of memory."; |
| 256 | case "exceededWallTime": |
| 257 | return "The request ran longer than it is allowed."; |
| 258 | case "scriptNotFound": |
| 259 | return "No app was there to answer."; |
| 260 | case "loadShed": |
| 261 | return "Cloudflare shed the request under load."; |
| 262 | default: |
| 263 | return `The request ended with ${outcome}.`; |
| 264 | } |
| 265 | } |