Enable Cloudflare tracing + bind rayId/traceparent/instanceId onto logs

src/main.test.ts

@@ -1,5 +1,7 @@
-import { describe, expect, test } from "vitest";
-import worker from "./main";
+import { afterEach, beforeEach, describe, expect, test, vi } from "vitest";
+import worker, { __setAppBotLoginForTests } from "./main";
+import workflowRunSuccess from "./testing/fixtures/workflow-run-success.json";
+import { computeSignature } from "./testing/workflow-test-helpers";
 
 describe("Worker default export", () => {
 	test("has a fetch handler", () => {
@@ -12,3 +14,146 @@ describe("Worker default export", () => {
 		expect(res.status).toBe(404);
 	});
 });
+
+// ── Worker tracing bindings ───────────────────────────────────────────────────
+//
+// The Worker's `handleGithubWebhook` builds `reqLogger` after
+// `parseWebhookRequest` succeeds and immediately emits a "Webhook received"
+// log line on it. We drive a real signed webhook through `worker.fetch`, spy
+// on `console.log` (JSON mode), then inspect the emitted record to assert
+// which tracing bindings ended up on the child logger.
+
+const TEST_SECRET = "test-webhook-secret";
+const TEST_APP_ID = "123";
+const TEST_PRIVATE_KEY =
+	"-----BEGIN RSA PRIVATE KEY-----\nfake-key\n-----END RSA PRIVATE KEY-----";
+const AGENT_LOGIN = "xmtp-coder-agent";
+
+const baseEnv = {
+	APP_ID: TEST_APP_ID,
+	PRIVATE_KEY: TEST_PRIVATE_KEY,
+	WEBHOOK_SECRET: TEST_SECRET,
+	AGENT_GITHUB_USERNAME: AGENT_LOGIN,
+	CODER_URL: "https://coder.example.com",
+	CODER_TOKEN: "token",
+	CODER_TASK_NAME_PREFIX: "gh",
+	CODER_TEMPLATE_NAME: "task-template",
+	CODER_TEMPLATE_NAME_CODEX: "task-template-codex",
+	CODER_ORGANIZATION: "default",
+	LOG_FORMAT: "json",
+};
+
+function makeTracingEnv() {
+	return {
+		...baseEnv,
+		TASK_RUNNER_WORKFLOW: {
+			create: (args: { id: string; params: unknown }) =>
+				Promise.resolve({ id: args.id }),
+		},
+	} as unknown as Parameters<typeof worker.fetch>[1];
+}
+
+interface BuildReqOpts {
+	headers?: Record<string, string>;
+}
+
+async function buildWebhookRequestWithHeaders(
+	opts: BuildReqOpts = {},
+): Promise<Request> {
+	const body = JSON.stringify(workflowRunSuccess);
+	const signature = await computeSignature(TEST_SECRET, body);
+	return new Request("https://example.com/webhooks/github", {
+		method: "POST",
+		headers: {
+			"Content-Type": "application/json",
+			"X-Hub-Signature-256": signature,
+			"X-GitHub-Event": "workflow_run",
+			"X-GitHub-Delivery": "trace-delivery-1",
+			...(opts.headers ?? {}),
+		},
+		body,
+	});
+}
+
+/**
+ * Invoke the Worker with the given request, capture every `console.log` call,
+ * and return the JSON record (if any) whose `msg === "Webhook received"`.
+ */
+async function captureWebhookReceivedLog(
+	req: Request,
+): Promise<Record<string, unknown>> {
+	const spy = vi.spyOn(console, "log").mockImplementation(() => {});
+	try {
+		await worker.fetch(req, makeTracingEnv(), {} as ExecutionContext);
+	} finally {
+		// Spy cleanup is handled by `afterEach(vi.restoreAllMocks)` in the
+		// enclosing describe block.
+	}
+	const entries: Record<string, unknown>[] = [];
+	for (const call of spy.mock.calls) {
+		const arg = call[0];
+		if (typeof arg !== "string") continue;
+		try {
+			entries.push(JSON.parse(arg) as Record<string, unknown>);
+		} catch {
+			// non-JSON console.log output — ignore.
+		}
+	}
+	const match = entries.find((e) => e.msg === "Webhook received");
+	if (!match) {
+		throw new Error(
+			`"Webhook received" log not emitted. Captured: ${JSON.stringify(entries)}`,
+		);
+	}
+	return match;
+}
+
+describe("Worker tracing bindings", () => {
+	afterEach(() => {
+		vi.restoreAllMocks();
+	});
+
+	beforeEach(() => {
+		__setAppBotLoginForTests("xmtp-coder-tasks[bot]");
+	});
+
+	test("cf-ray + valid traceparent → rayId, traceId, spanId bound on reqLogger", async () => {
+		const req = await buildWebhookRequestWithHeaders({
+			headers: {
+				"cf-ray": "8a1-SJC",
+				traceparent: "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
+			},
+		});
+		const log = await captureWebhookReceivedLog(req);
+		expect(log.deliveryId).toBe("trace-delivery-1");
+		expect(log.eventName).toBe("workflow_run");
+		expect(log.rayId).toBe("8a1-SJC");
+		expect(log.traceId).toBe("0af7651916cd43dd8448eb211c80319c");
+		expect(log.spanId).toBe("b7ad6b7169203331");
+	});
+
+	test("missing cf-ray and missing traceparent → no rayId/traceId/spanId keys", async () => {
+		const req = await buildWebhookRequestWithHeaders();
+		const log = await captureWebhookReceivedLog(req);
+		expect(log.deliveryId).toBe("trace-delivery-1");
+		expect(log.eventName).toBe("workflow_run");
+		expect("rayId" in log).toBe(false);
+		expect("traceId" in log).toBe(false);
+		expect("spanId" in log).toBe(false);
+	});
+
+	test("cf-ray present but traceparent malformed → rayId only", async () => {
+		const req = await buildWebhookRequestWithHeaders({
+			headers: {
+				"cf-ray": "9zz-IAD",
+				traceparent: "garbage",
+			},
+		});
+		const log = await captureWebhookReceivedLog(req);
+		expect(log.deliveryId).toBe("trace-delivery-1");
+		expect(log.eventName).toBe("workflow_run");
+		expect(log.rayId).toBe("9zz-IAD");
+		expect("traceId" in log).toBe(false);
+		expect("spanId" in log).toBe(false);
+	});
+});

src/main.ts

@@ -7,7 +7,7 @@ import {
 	parseWebhookRequest,
 	WebhookRequestError,
 } from "./http/parse-webhook-request";
-import { createLogger } from "./utils/logger";
+import { createLogger, parseTraceparent } from "./utils/logger";
 import { WebhookRouter } from "./webhooks/github/router";
 import type { TaskRunnerWorkflowEnv } from "./workflows/task-runner-workflow";
 import {
@@ -59,7 +59,14 @@ async function handleGithubWebhook(
 	}
 
 	const { eventName, deliveryId, payload } = parsed;
-	const reqLogger = logger.child({ deliveryId, eventName });
+	const rayId = request.headers.get("cf-ray");
+	const trace = parseTraceparent(request.headers.get("traceparent"));
+	const reqLogger = logger.child({
+		deliveryId,
+		eventName,
+		...(rayId ? { rayId } : {}),
+		...(trace ? { traceId: trace.traceId, spanId: trace.spanId } : {}),
+	});
 	reqLogger.info("Webhook received");
 
 	// Stage 2: route via WebhookRouter.

src/utils/logger.test.ts

@@ -1,5 +1,5 @@
 import { describe, expect, test, vi } from "vitest";
-import { createLogger, TestLogger } from "./logger";
+import { createLogger, parseTraceparent, TestLogger } from "./logger";
 
 describe("TestLogger", () => {
 	test("captures info messages", () => {
@@ -135,3 +135,164 @@ describe("createLogger(json mode)", () => {
 		}
 	});
 });
+
+describe("parseTraceparent", () => {
+	test("parses a valid W3C traceparent header", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
+			),
+		).toEqual({
+			traceId: "0af7651916cd43dd8448eb211c80319c",
+			spanId: "b7ad6b7169203331",
+		});
+	});
+
+	test("returns null for a null header", () => {
+		expect(parseTraceparent(null)).toBeNull();
+	});
+
+	test("returns null when there are too few segments", () => {
+		expect(
+			parseTraceparent("00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331"),
+		).toBeNull();
+	});
+
+	test("returns null when there are too many segments", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01-extra",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for non-hex characters", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319z-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null when trace-id is too short", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null when span-id is too short", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b716920333-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null when trace-id is all zeros", () => {
+		expect(
+			parseTraceparent(
+				"00-00000000000000000000000000000000-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for version ff", () => {
+		expect(
+			parseTraceparent(
+				"ff-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("accepts forward-compatible versions like 01", () => {
+		expect(
+			parseTraceparent(
+				"01-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01",
+			),
+		).toEqual({
+			traceId: "0af7651916cd43dd8448eb211c80319c",
+			spanId: "b7ad6b7169203331",
+		});
+	});
+
+	test("returns null for empty string", () => {
+		expect(parseTraceparent("")).toBeNull();
+	});
+
+	test("returns null for whitespace-only header", () => {
+		expect(parseTraceparent("   ")).toBeNull();
+	});
+
+	test("returns null for lone dashes", () => {
+		expect(parseTraceparent("---")).toBeNull();
+	});
+
+	test("returns null for trailing hyphen (5 segments)", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01-",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for uppercase hex in trace-id", () => {
+		expect(
+			parseTraceparent(
+				"00-0AF7651916CD43DD8448EB211C80319C-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for uppercase hex in span-id", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-B7AD6B7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("accepts all-zero span-id", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-0000000000000000-01",
+			),
+		).toEqual({
+			traceId: "0af7651916cd43dd8448eb211c80319c",
+			spanId: "0000000000000000",
+		});
+	});
+
+	test("returns null for malformed flags (non-hex)", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-zz",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for malformed flags (wrong length)", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-012",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for too-long trace-id (33 hex chars)", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c0-b7ad6b7169203331-01",
+			),
+		).toBeNull();
+	});
+
+	test("returns null for too-long span-id (17 hex chars)", () => {
+		expect(
+			parseTraceparent(
+				"00-0af7651916cd43dd8448eb211c80319c-b7ad6b71692033310-01",
+			),
+		).toBeNull();
+	});
+});

src/utils/logger.ts

@@ -57,6 +57,32 @@ function makeLogger(bindings: Record<string, unknown>, json: boolean): Logger {
 	};
 }
 
+// ── W3C traceparent ─────────────────────────────────────────────────────────
+
+const HEX_RE = /^[0-9a-f]+$/;
+const ZERO_TRACE_ID = "00000000000000000000000000000000";
+
+export function parseTraceparent(
+	header: string | null,
+): { traceId: string; spanId: string } | null {
+	if (header == null) return null;
+	const segments = header.split("-");
+	if (segments.length !== 4) return null;
+	const [version, traceId, spanId, flags] = segments as [
+		string,
+		string,
+		string,
+		string,
+	];
+	if (version.length !== 2 || !HEX_RE.test(version)) return null;
+	if (version === "ff") return null;
+	if (traceId.length !== 32 || !HEX_RE.test(traceId)) return null;
+	if (traceId === ZERO_TRACE_ID) return null;
+	if (spanId.length !== 16 || !HEX_RE.test(spanId)) return null;
+	if (flags.length !== 2 || !HEX_RE.test(flags)) return null;
+	return { traceId, spanId };
+}
+
 // ── Test logger ─────────────────────────────────────────────────────────────
 
 interface LogEntry {