diff --git a/apps/connect/src/worker.test.ts b/apps/connect/src/worker.test.ts index ca536b6ce0..d7b5a0e5f3 100644 --- a/apps/connect/src/worker.test.ts +++ b/apps/connect/src/worker.test.ts @@ -180,6 +180,7 @@ const mockHandleAssignMachineLabel = vi.mocked(handleAssignMachineLabel); /** A resolved server row; overrides let a test tweak one field. */ function resolvedServer( over: Partial<{ + credentialHash: string | null; lastSeenAt: Date | null; userId: string; }> = {}, @@ -189,7 +190,8 @@ function resolvedServer( userId: over.userId ?? OWNER, server: { id: "srv1", - credentialHash: "abc", + credentialHash: + over.credentialHash === undefined ? "abc" : over.credentialHash, revokedAt: null, lastSeenAt: over.lastSeenAt ?? null, }, @@ -426,6 +428,102 @@ describe("gate tunnel authentication", () => { expect(captured[0].headers.get("x-bb-cloud-dev-host")).toBeNull(); }); + it("returns a request-correlated 500 when Durable Object dispatch fails", async () => { + const credential = "bbcred_server_secret"; + const digest = await crypto.subtle.digest( + "SHA-256", + new TextEncoder().encode(credential), + ); + const hash = [...new Uint8Array(digest)] + .map((byte) => byte.toString(16).padStart(2, "0")) + .join(""); + mockResolveLabel.mockResolvedValue( + resolvedServer({ credentialHash: hash }), + ); + const upstreamError = Object.assign(new Error("DO unavailable"), { + remote: true, + retryable: true, + overloaded: false, + }); + const { env, ctx, captured } = makeEnv(() => Promise.reject(upstreamError)); + const errorLog = vi.spyOn(console, "error").mockImplementation(() => {}); + + try { + const response = await worker.fetch( + visitorRequest("sawyer.getbb.app", "/__tunnel?v=1", { + headers: { + authorization: `Bearer ${credential}`, + "cf-ray": "incident-ray", + upgrade: "websocket", + }, + }), + env as never, + ctx, + ); + + expect(response.status).toBe(500); + const requestId = response.headers.get("x-bb-request-id"); + expect(requestId).toMatch(/^[0-9a-f-]{36}$/u); + expect(await response.text()).toContain(`request ${requestId}`); + expect(captured[0].headers.get("x-bb-request-id")).toBe(requestId); + const logLine = String(errorLog.mock.calls[0]?.[0]); + expect(JSON.parse(logLine)).toMatchObject({ + event: "tunnel_dial_failed", + requestId, + cfRay: "incident-ray", + label: "sawyer", + ownerKind: "server", + ownerId: "srv1", + stage: "durable_object_dispatch", + errorName: "Error", + errorMessage: "DO unavailable", + remote: true, + retryable: true, + overloaded: false, + }); + expect(logLine).not.toContain(credential); + } finally { + errorLog.mockRestore(); + } + }); + + it("correlates a fresh D1 resolution failure without dispatching to the DO", async () => { + mockResolveLabel.mockRejectedValue(new Error("D1 unavailable")); + const { env, ctx, captured } = makeEnv(() => new Response("origin")); + const errorLog = vi.spyOn(console, "error").mockImplementation(() => {}); + + try { + const response = await worker.fetch( + visitorRequest("sawyer.getbb.app", "/__tunnel?v=1", { + headers: { + authorization: "Bearer not-logged", + "cf-ray": "d1-ray", + upgrade: "websocket", + }, + }), + env as never, + ctx, + ); + + expect(response.status).toBe(500); + expect(captured).toHaveLength(0); + const requestId = response.headers.get("x-bb-request-id"); + expect(JSON.parse(String(errorLog.mock.calls[0]?.[0]))).toMatchObject({ + event: "tunnel_dial_failed", + requestId, + cfRay: "d1-ray", + label: "sawyer", + ownerKind: null, + ownerId: null, + stage: "resolve_label", + errorMessage: "D1 unavailable", + }); + expect(String(errorLog.mock.calls[0]?.[0])).not.toContain("not-logged"); + } finally { + errorLog.mockRestore(); + } + }); + it("dials immediately after a negative resolve and label assignment", async () => { const credential = "bbcm_new_machine"; const digest = await crypto.subtle.digest( diff --git a/apps/connect/src/worker.ts b/apps/connect/src/worker.ts index 25accdbfcf..1b6e24d886 100644 --- a/apps/connect/src/worker.ts +++ b/apps/connect/src/worker.ts @@ -10,6 +10,7 @@ import { parseCookie, markMachineSeen, resolveLabel, + type ResolvedLabel, verifyMachineCredentialDetails, verifySessionCookie, } from "./session.js"; @@ -55,6 +56,63 @@ function text(body: string, status: number): Response { }); } +const TUNNEL_REQUEST_ID_HEADER = "x-bb-request-id"; + +type TunnelDialFailureStage = + | "resolve_label" + | "credential_hash" + | "durable_object_binding" + | "durable_object_dispatch"; + +function errorBoolean(error: unknown, property: string): boolean | null { + if (typeof error !== "object" || error === null) return null; + try { + const value = Reflect.get(error, property); + return typeof value === "boolean" ? value : null; + } catch { + return null; + } +} + +/** Log a tunnel failure without including the Authorization credential. */ +function tunnelDialFailure(args: { + request: Request; + requestId: string; + label: string; + ownerKind: "server" | "machine" | null; + ownerId: string | null; + stage: TunnelDialFailureStage; + error: unknown; +}): Response { + console.error( + JSON.stringify({ + event: "tunnel_dial_failed", + requestId: args.requestId, + cfRay: args.request.headers.get("cf-ray"), + label: args.label, + ownerKind: args.ownerKind, + ownerId: args.ownerId, + stage: args.stage, + errorName: args.error instanceof Error ? args.error.name : null, + errorMessage: + args.error instanceof Error ? args.error.message : String(args.error), + remote: errorBoolean(args.error, "remote"), + retryable: errorBoolean(args.error, "retryable"), + overloaded: errorBoolean(args.error, "overloaded"), + }), + ); + return new Response( + `bb connect: tunnel handshake failed (request ${args.requestId})\n`, + { + status: 500, + headers: { + "content-type": "text/plain; charset=utf-8", + [TUNNEL_REQUEST_ID_HEADER]: args.requestId, + }, + }, + ); +} + // Matches the bb dashboard's visual language (Inter, --canvas/--ink tokens, // dark primary button, bb logo) since this plain worker can't bundle React. export function dashboardSignInUrl(appUrl: string, returnTo: string): string { @@ -334,21 +392,36 @@ export default { // avoids both stale credentials and a cached negative immediately after a // machine label is assigned. const isTunnelDial = url.pathname === "/__tunnel"; - const resolved = await resolveLabel( - label, - db, - isTunnelDial ? { fresh: true } : undefined, - ); + const tunnelRequestId = isTunnelDial ? crypto.randomUUID() : null; + let resolved: ResolvedLabel | null; + try { + resolved = await resolveLabel( + label, + db, + isTunnelDial ? { fresh: true } : undefined, + ); + } catch (error) { + if (tunnelRequestId === null) throw error; + return tunnelDialFailure({ + request, + requestId: tunnelRequestId, + label, + ownerKind: null, + ownerId: null, + stage: "resolve_label", + error, + }); + } if (!resolved) return text(`bb connect: no server for "${label}"\n`, 404); // Server routing stays exactly as on main (the bare label). Machine labels // are new and use ownership-generation identity from their first dial. const routingKey = resolved.kind === "machine" ? resolved.routingKey : label; - const stub = env.TUNNEL_DO.get(env.TUNNEL_DO.idFromName(routingKey)); // Tunnel client connection — bare label only (share hosts are visitor-facing). if (url.pathname === "/__tunnel") { + const requestId = tunnelRequestId ?? crypto.randomUUID(); if (target !== null) return text("bb connect: not found\n", 404); const auth = request.headers.get("authorization") ?? ""; const credential = auth.startsWith("Bearer ") ? auth.slice(7) : ""; @@ -362,24 +435,43 @@ export default { 403, ); } - if ((await sha256Hex(credential)) !== owner.credentialHash) { - return text("bb connect: invalid credential\n", 401); - } - const forward = new URL(request.url); - forward.searchParams.delete("serverId"); - forward.searchParams.delete("machineId"); - if (resolved.kind === "server") { - forward.searchParams.set("serverId", owner.id); - } else { - forward.searchParams.set("machineId", owner.id); + let stage: TunnelDialFailureStage = "credential_hash"; + try { + if ((await sha256Hex(credential)) !== owner.credentialHash) { + return text("bb connect: invalid credential\n", 401); + } + const forward = new URL(request.url); + forward.searchParams.delete("serverId"); + forward.searchParams.delete("machineId"); + if (resolved.kind === "server") { + forward.searchParams.set("serverId", owner.id); + } else { + forward.searchParams.set("machineId", owner.id); + } + const headers = new Headers(request.headers); + stripCloudDevHeader(headers); + headers.set(TUNNEL_REQUEST_ID_HEADER, requestId); + stage = "durable_object_binding"; + const stub = env.TUNNEL_DO.get(env.TUNNEL_DO.idFromName(routingKey)); + stage = "durable_object_dispatch"; + return await stub.fetch( + new Request(new Request(forward, request), { headers }), + ); + } catch (error) { + return tunnelDialFailure({ + request, + requestId, + label, + ownerKind: resolved.kind, + ownerId: owner.id, + stage, + error, + }); } - const headers = new Headers(request.headers); - stripCloudDevHeader(headers); - return stub.fetch( - new Request(new Request(forward, request), { headers }), - ); } + const stub = env.TUNNEL_DO.get(env.TUNNEL_DO.idFromName(routingKey)); + // Reserve the /__ namespace: never proxy internal paths from outside. if (url.pathname.startsWith("/__")) return text("bb connect: not found\n", 404); diff --git a/plugins/connect/src/tunnel-lifecycle.test.ts b/plugins/connect/src/tunnel-lifecycle.test.ts index 4d709a954e..5862f75f4d 100644 --- a/plugins/connect/src/tunnel-lifecycle.test.ts +++ b/plugins/connect/src/tunnel-lifecycle.test.ts @@ -94,6 +94,8 @@ function createTunnelFixture() { describe("ConnectTunnel socket lifecycle", () => { afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); fakeWebSockets.instances.length = 0; fakeWebSockets.options.length = 0; }); @@ -195,32 +197,95 @@ describe("ConnectTunnel socket lifecycle", () => { } }); - it("retries an HTTP rejection without waiting for close", async () => { - vi.useFakeTimers(); - const { fakeHost, tunnel } = createTunnelFixture(); - - try { - await tunnel.start(); - const socket = fakeWebSockets.instances[0]!; - const response = { statusCode: 500, resume: vi.fn() }; - - socket.emit("unexpected-response", {}, response); - - expect(response.resume).toHaveBeenCalledOnce(); - expect(tunnel.status().lastError).toBe("tunnel rejected: HTTP 500"); - const nextRetryAt = tunnel.status().nextRetryAt; - expect(nextRetryAt).not.toBeNull(); - - await vi.advanceTimersByTimeAsync(nextRetryAt! - Date.now()); - - expect(fakeWebSockets.instances).toHaveLength(2); - expect(tunnel.status().nextRetryAt).toBeNull(); - } finally { - tunnel.stop(); - vi.useRealTimers(); - await fakeHost.harness.dispose(); - } - }); + it.each([429, 500])( + "retries a transient HTTP %i rejection without waiting for close", + async (statusCode) => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-08-20T18:23:28.000Z")); + vi.spyOn(Math, "random").mockReturnValue(0.5); + const { fakeHost, tunnel } = createTunnelFixture(); + + try { + await tunnel.start(); + const socket = fakeWebSockets.instances[0]!; + const response = { + statusCode, + headers: { + "cf-ray": "incident-ray", + "x-bb-request-id": `request-${statusCode}`, + }, + resume: vi.fn(), + }; + + socket.emit("unexpected-response", {}, response); + + expect(response.resume).toHaveBeenCalledOnce(); + expect(tunnel.status().lastError).toBe( + `tunnel rejected: HTTP ${statusCode} (request request-${statusCode})`, + ); + expect(tunnel.status().nextRetryAt).toBe(Date.now() + 1_800); + const rejectionLog = fakeHost.harness.logEntries.find((entry) => + entry.message.includes('"event":"tunnel_handshake_rejected"'), + ); + expect(JSON.parse(rejectionLog?.message ?? "{}")).toMatchObject({ + event: "tunnel_handshake_rejected", + attemptId: "connect-1", + statusCode, + cfRay: "incident-ray", + requestId: `request-${statusCode}`, + retryInMs: 1_800, + }); + + socket.emit("close", 1006, Buffer.from("late close")); + await vi.advanceTimersByTimeAsync(1_799); + expect(fakeWebSockets.instances).toHaveLength(1); + await vi.advanceTimersByTimeAsync(1); + expect(fakeWebSockets.instances).toHaveLength(2); + expect(tunnel.status().nextRetryAt).toBeNull(); + + fakeWebSockets.instances[1]!.emit("open"); + expect(tunnel.status()).toMatchObject({ + state: "connected", + lastError: null, + nextRetryAt: null, + }); + } finally { + tunnel.stop(); + await fakeHost.harness.dispose(); + } + }, + ); + + it.each([401, 403])( + "stops retrying after credential rejection HTTP %i", + async (statusCode) => { + vi.useFakeTimers(); + const { clearCredential, fakeHost, tunnel } = createTunnelFixture(); + + try { + await tunnel.start(); + const resume = vi.fn(); + fakeWebSockets.instances[0]!.emit( + "unexpected-response", + {}, + { statusCode, headers: {}, resume }, + ); + + expect(resume).toHaveBeenCalledOnce(); + expect(tunnel.status()).toMatchObject({ + state: "disconnected", + paired: false, + nextRetryAt: null, + }); + await vi.advanceTimersByTimeAsync(30_000); + expect(fakeWebSockets.instances).toHaveLength(1); + expect(clearCredential).toHaveBeenCalledOnce(); + } finally { + tunnel.stop(); + await fakeHost.harness.dispose(); + } + }, + ); it("schedules one retry when rejection is followed by close", async () => { vi.useFakeTimers(); diff --git a/plugins/connect/src/tunnel.ts b/plugins/connect/src/tunnel.ts index c8ec2ab097..b31d257cac 100644 --- a/plugins/connect/src/tunnel.ts +++ b/plugins/connect/src/tunnel.ts @@ -45,6 +45,18 @@ import type { ConnectStateName, ConnectStatus } from "./types.js"; const DISCONNECT_TIMEOUT_MS = 5_000; const TUNNEL_HANDSHAKE_TIMEOUT_MS = 15_000; +const RECONNECT_JITTER_RATIO = 0.2; + +/** Keep reconnects under the shared backoff cap while spreading simultaneous dials. */ +function jitterReconnectDelay(delayMs: number): number { + const multiplier = + 1 - RECONNECT_JITTER_RATIO + Math.random() * RECONNECT_JITTER_RATIO; + return Math.max(1, Math.round(delayMs * multiplier)); +} + +function responseHeader(value: string | string[] | undefined): string | null { + return Array.isArray(value) ? (value[0] ?? null) : (value ?? null); +} async function notifyCloudOfDisconnect( credential: ConnectCredential, @@ -101,6 +113,7 @@ export class ConnectTunnel { private nextRetryAt: number | null = null; private shareRetryTimer: ReturnType | undefined; private shareActivationEpoch = 0; + private connectionAttempt = 0; constructor(private readonly options: ConnectTunnelOptions) {} @@ -439,8 +452,9 @@ export class ConnectTunnel { if (!credential || this.stopped) return; const tunnelUrl = tunnelUrlForServer(credential.serverUrl); + const attemptId = `connect-${++this.connectionAttempt}`; this.options.log.info( - `tunnel connecting to ${tunnelUrl} (origin ${this.options.getLoopbackBaseUrl()})`, + `tunnel connecting attemptId=${attemptId} url=${tunnelUrl} origin=${this.options.getLoopbackBaseUrl()}`, ); let tunnel: NodeWebSocket; try { @@ -463,9 +477,9 @@ export class ConnectTunnel { let retryScheduled = false; let handshakeDeadline: ReturnType | undefined; - const scheduleReconnect = (detail: string): void => { + const scheduleReconnect = (detail: string): number | null => { if (retryScheduled || this.stopped || this.tunnel !== tunnel) { - return; + return null; } retryScheduled = true; clearTimeout(handshakeDeadline); @@ -474,7 +488,9 @@ export class ConnectTunnel { this.session = undefined; this.remoteClients = 0; const stable = connectedAt ? Date.now() - connectedAt : 0; - const delay = this.backoff.nextDelayAfterClose(stable); + const delay = jitterReconnectDelay( + this.backoff.nextDelayAfterClose(stable), + ); if (this.lastError === null) { this.lastError = `can't reach ${connectApexHost(credential.serverUrl)} — connection closed`; } @@ -488,6 +504,7 @@ export class ConnectTunnel { this.openTunnel(); }, delay); this.publish(); + return delay; }; // `ws`'s handshakeTimeout is a socket idle timeout: a peer that drips @@ -510,7 +527,7 @@ export class ConnectTunnel { this.connected = true; this.lastError = null; this.nextRetryAt = null; - this.options.log.info("tunnel connected"); + this.options.log.info(`tunnel connected attemptId=${attemptId}`); this.session = new TunnelSession({ tunnel, log: this.options.log, @@ -534,8 +551,25 @@ export class ConnectTunnel { this.credentialRejected(statusCode); return; } - this.lastError = `tunnel rejected: HTTP ${statusCode}`; - scheduleReconnect(this.lastError); + const requestId = responseHeader(res.headers?.["x-bb-request-id"]); + const cfRay = responseHeader(res.headers?.["cf-ray"]); + const correlation = requestId + ? ` (request ${requestId})` + : cfRay + ? ` (CF Ray ${cfRay})` + : ""; + this.lastError = `tunnel rejected: HTTP ${statusCode}${correlation}`; + const retryInMs = scheduleReconnect(this.lastError); + this.options.log.warn( + JSON.stringify({ + event: "tunnel_handshake_rejected", + attemptId, + statusCode, + cfRay, + requestId, + retryInMs, + }), + ); tunnel.terminate(); }); tunnel.on("error", (e: Error) => { @@ -548,10 +582,19 @@ export class ConnectTunnel { e, connectApexHost(credential.serverUrl), ); + this.options.log.warn( + JSON.stringify({ + event: "tunnel_transport_error", + attemptId, + errorName: e.name, + errorMessage: e.message, + }), + ); + this.publish(); }); tunnel.on("close", (code: number, reason: Buffer) => { scheduleReconnect( - `tunnel closed (code ${code}${reason.length > 0 ? `, ${reason.toString()}` : ""})`, + `tunnel closed attemptId=${attemptId} (code ${code}${reason.length > 0 ? `, ${reason.toString()}` : ""})`, ); }); }