From 8f9bdbd5fd14d62c286b86f8294a7a7ad894c0dc Mon Sep 17 00:00:00 2001 From: lyon Date: Sat, 20 Jun 2026 01:16:45 +0800 Subject: [PATCH] fix: harden workbench trace timeout observability --- internal/cloud/server-workbench-http.ts | 132 +++++++++++++----- internal/cloud/web-performance.test.ts | 49 ++++++- internal/cloud/web-performance.ts | 12 ++ web/hwlab-cloud-web/src/api/client.ts | 25 +++- .../src/utils/workbench-performance.ts | 13 +- 5 files changed, 185 insertions(+), 46 deletions(-) diff --git a/internal/cloud/server-workbench-http.ts b/internal/cloud/server-workbench-http.ts index a7664aab..f2caddad 100644 --- a/internal/cloud/server-workbench-http.ts +++ b/internal/cloud/server-workbench-http.ts @@ -21,45 +21,49 @@ const DEFAULT_SESSION_LIST_LIMIT = 20; const MAX_PAGE_LIMIT = 100; const DEFAULT_WORKBENCH_SSE_HEARTBEAT_MS = 15000; export async function handleWorkbenchReadModelHttp(request, response, url, options = {}) { - const perf = options.backendPerformance; - const auth = perf ? await perf.measure("workbench_auth", () => authenticateWorkbenchRead(request, response, options)) : await authenticateWorkbenchRead(request, response, options); - if (!auth) return; + try { + const perf = options.backendPerformance; + const auth = perf ? await perf.measure("workbench_auth", () => authenticateWorkbenchRead(request, response, options)) : await authenticateWorkbenchRead(request, response, options); + if (!auth) return; - if (url.pathname === "/v1/workbench/sessions") { - if (request.method !== "GET") return methodNotAllowed(response, "GET"); - await (perf ? perf.measure("workbench_session_list", () => handleWorkbenchSessionList(response, url, options, auth.actor)) : handleWorkbenchSessionList(response, url, options, auth.actor)); - return; + if (url.pathname === "/v1/workbench/sessions") { + if (request.method !== "GET") return methodNotAllowed(response, "GET"); + await (perf ? perf.measure("workbench_session_list", () => handleWorkbenchSessionList(response, url, options, auth.actor)) : handleWorkbenchSessionList(response, url, options, auth.actor)); + return; + } + + const sessionMessagesMatch = url.pathname.match(/^\/v1\/workbench\/sessions\/([^/]+)\/messages$/u); + if (sessionMessagesMatch) { + if (request.method !== "GET") return methodNotAllowed(response, "GET"); + await (perf ? perf.measure("workbench_message_page", () => handleWorkbenchMessagePage(response, url, options, auth.actor, decodeURIComponent(sessionMessagesMatch[1]))) : handleWorkbenchMessagePage(response, url, options, auth.actor, decodeURIComponent(sessionMessagesMatch[1]))); + return; + } + + const sessionMatch = url.pathname.match(/^\/v1\/workbench\/sessions\/([^/]+)$/u); + if (sessionMatch) { + if (request.method !== "GET") return methodNotAllowed(response, "GET"); + await (perf ? perf.measure("workbench_session_detail", () => handleWorkbenchSessionDetail(response, options, auth.actor, decodeURIComponent(sessionMatch[1]))) : handleWorkbenchSessionDetail(response, options, auth.actor, decodeURIComponent(sessionMatch[1]))); + return; + } + + const turnMatch = url.pathname.match(/^\/v1\/workbench\/turns\/([^/]+)$/u); + if (turnMatch) { + if (request.method !== "GET") return methodNotAllowed(response, "GET"); + await (perf ? perf.measure("workbench_turn_snapshot", () => handleWorkbenchTurnSnapshot(response, url, options, auth.actor, decodeURIComponent(turnMatch[1]))) : handleWorkbenchTurnSnapshot(response, url, options, auth.actor, decodeURIComponent(turnMatch[1]))); + return; + } + + const traceEventsMatch = url.pathname.match(/^\/v1\/workbench\/traces\/([^/]+)\/events$/u); + if (traceEventsMatch) { + if (request.method !== "GET") return methodNotAllowed(response, "GET"); + await (perf ? perf.measure("workbench_trace_events", () => handleWorkbenchTraceEventPage(response, url, options, auth.actor, decodeURIComponent(traceEventsMatch[1]))) : handleWorkbenchTraceEventPage(response, url, options, auth.actor, decodeURIComponent(traceEventsMatch[1]))); + return; + } + + sendJson(response, 404, workbenchError("workbench_route_not_found", "Workbench read model route is not implemented.", { route: url.pathname })); + } catch (error) { + handleWorkbenchReadModelFailure(response, url, options, error); } - - const sessionMessagesMatch = url.pathname.match(/^\/v1\/workbench\/sessions\/([^/]+)\/messages$/u); - if (sessionMessagesMatch) { - if (request.method !== "GET") return methodNotAllowed(response, "GET"); - await (perf ? perf.measure("workbench_message_page", () => handleWorkbenchMessagePage(response, url, options, auth.actor, decodeURIComponent(sessionMessagesMatch[1]))) : handleWorkbenchMessagePage(response, url, options, auth.actor, decodeURIComponent(sessionMessagesMatch[1]))); - return; - } - - const sessionMatch = url.pathname.match(/^\/v1\/workbench\/sessions\/([^/]+)$/u); - if (sessionMatch) { - if (request.method !== "GET") return methodNotAllowed(response, "GET"); - await (perf ? perf.measure("workbench_session_detail", () => handleWorkbenchSessionDetail(response, options, auth.actor, decodeURIComponent(sessionMatch[1]))) : handleWorkbenchSessionDetail(response, options, auth.actor, decodeURIComponent(sessionMatch[1]))); - return; - } - - const turnMatch = url.pathname.match(/^\/v1\/workbench\/turns\/([^/]+)$/u); - if (turnMatch) { - if (request.method !== "GET") return methodNotAllowed(response, "GET"); - await (perf ? perf.measure("workbench_turn_snapshot", () => handleWorkbenchTurnSnapshot(response, url, options, auth.actor, decodeURIComponent(turnMatch[1]))) : handleWorkbenchTurnSnapshot(response, url, options, auth.actor, decodeURIComponent(turnMatch[1]))); - return; - } - - const traceEventsMatch = url.pathname.match(/^\/v1\/workbench\/traces\/([^/]+)\/events$/u); - if (traceEventsMatch) { - if (request.method !== "GET") return methodNotAllowed(response, "GET"); - await (perf ? perf.measure("workbench_trace_events", () => handleWorkbenchTraceEventPage(response, url, options, auth.actor, decodeURIComponent(traceEventsMatch[1]))) : handleWorkbenchTraceEventPage(response, url, options, auth.actor, decodeURIComponent(traceEventsMatch[1]))); - return; - } - - sendJson(response, 404, workbenchError("workbench_route_not_found", "Workbench read model route is not implemented.", { route: url.pathname })); } export async function handleWorkbenchRealtimeHttp(request, response, url, options = {}) { @@ -1024,6 +1028,60 @@ function canActorReadOwner(ownerUserId, actor) { return ownerUserId === actor.id; } +function handleWorkbenchReadModelFailure(response, url, options = {}, error) { + const classified = classifyWorkbenchReadModelFailure(error); + const route = workbenchReadRouteTemplate(url?.pathname ?? "/v1/workbench"); + logWorkbenchReadModelFailure(options.logger ?? console, { + event: "workbench_read_model_route_failed", + ok: false, + route, + statusCode: classified.statusCode, + errorCode: classified.code, + errorName: error?.name ?? "Error", + message: error instanceof Error ? error.message : String(error ?? "unknown"), + valuesRedacted: true + }); + if (response.headersSent || response.destroyed) return; + sendJson(response, classified.statusCode, workbenchError(classified.code, classified.message, { route, errorName: error?.name ?? "Error" })); +} + +function classifyWorkbenchReadModelFailure(error) { + const message = String(error?.message ?? error ?? ""); + const code = String(error?.code ?? "").toLowerCase(); + if (/timeout|connection terminated|terminating connection|econnreset|econnrefused|etimedout/iu.test(message) || /timeout|econnreset|econnrefused|etimedout/u.test(code)) { + return { + statusCode: 503, + code: "workbench_read_model_store_unavailable", + message: "Workbench read model store is temporarily unavailable." + }; + } + return { + statusCode: 500, + code: "workbench_read_model_failed", + message: "Workbench read model failed." + }; +} + +function workbenchReadRouteTemplate(pathname) { + const path = String(pathname ?? ""); + if (path === "/v1/workbench/sessions") return path; + if (/^\/v1\/workbench\/sessions\/[^/]+\/messages$/u.test(path)) return "/v1/workbench/sessions/:id/messages"; + if (/^\/v1\/workbench\/sessions\/[^/]+$/u.test(path)) return "/v1/workbench/sessions/:id"; + if (/^\/v1\/workbench\/turns\/[^/]+$/u.test(path)) return "/v1/workbench/turns/:id"; + if (/^\/v1\/workbench\/traces\/[^/]+\/events$/u.test(path)) return "/v1/workbench/traces/:id/events"; + return path || "/v1/workbench"; +} + +function logWorkbenchReadModelFailure(logger, payload) { + try { + const line = JSON.stringify(payload); + if (typeof logger?.error === "function") logger.error(line); + else if (typeof logger?.warn === "function") logger.warn(line); + } catch { + // Read-model failure logging must not affect response generation. + } +} + function methodNotAllowed(response, allowed) { sendJson(response, 405, workbenchError("method_not_allowed", `Use ${allowed} for this Workbench read model route.`)); } diff --git a/internal/cloud/web-performance.test.ts b/internal/cloud/web-performance.test.ts index 494df843..4aad735d 100644 --- a/internal/cloud/web-performance.test.ts +++ b/internal/cloud/web-performance.test.ts @@ -5,7 +5,7 @@ import assert from "node:assert/strict"; import { test } from "bun:test"; import { createCloudApiServer } from "./server.ts"; -import { createWebPerformanceStore, webPerformanceRouteTemplate } from "./web-performance.ts"; +import { createWebPerformanceStore, emitWorkbenchUiOtelSpans, webPerformanceRouteTemplate } from "./web-performance.ts"; test("web performance store aggregates browser-perceived durations as Prometheus histograms", () => { const store = createWebPerformanceStore({ env: { HWLAB_METRICS_NAMESPACE: "hwlab-v02", HWLAB_GITOPS_TARGET: "v02" } }); @@ -202,6 +202,53 @@ test("web performance store accepts Workbench UI lifecycle events without high-c assert.doesNotMatch(text, /ses_secret|trc_secret|ui_secret|0123456789abcdef|sessionId|traceId|otelTraceId|prompt|api key/iu); }); +test("Workbench UI OTel spans include timeout activity diagnostics without raw trace ids", async () => { + const calls: any[] = []; + const originalFetch = globalThis.fetch; + globalThis.fetch = async (_url: string | URL | Request, init?: RequestInit) => { + calls.push(JSON.parse(String(init?.body ?? "{}"))); + return new Response(null, { status: 200 }); + }; + try { + const result = await emitWorkbenchUiOtelSpans({ + schemaVersion: "hwlab-web-performance-v2", + page: "/workbench/sessions/ses_secret", + events: [{ + kind: "workbench_ui_event", + eventType: "api_request", + loadingScope: "api", + state: "request", + reason: "api_request", + route: "/v1/workbench/turns/trc_secret", + method: "GET", + status: 0, + outcome: "timeout", + valueMs: 8001, + uiTraceId: "ui_secret", + otelTraceId: "0123456789abcdef0123456789abcdef", + timeoutName: "workbench turn", + activityWaitingFor: "code-agent", + activityLastEventLabel: "realtime:heartbeat", + activityIdleMs: 13042, + traceId: "trc_secret" + }] + } as Record, { OTEL_EXPORTER_OTLP_TRACES_ENDPOINT: "http://otel.example/v1/traces" }); + + assert.equal(result.submitted, 1); + assert.equal(calls.length, 1); + const span = calls[0].resourceSpans[0].scopeSpans[0].spans[0]; + const attrs = Object.fromEntries(span.attributes.map((item: any) => [item.key, item.value.stringValue ?? Number(item.value.intValue) ?? item.value.boolValue])); + assert.equal(attrs["http.route"], "/v1/workbench/turns/:id"); + assert.equal(attrs["workbench.ui.timeout_name"], "workbench turn"); + assert.equal(attrs["workbench.ui.activity_waiting_for"], "code-agent"); + assert.equal(attrs["workbench.ui.activity_last_event_label"], "realtime:heartbeat"); + assert.equal(attrs["workbench.ui.activity_idle_ms"], 13042); + assert.doesNotMatch(JSON.stringify(calls[0]), /trc_secret|ses_secret|prompt|api key/iu); + } finally { + globalThis.fetch = originalFetch; + } +}); + test("web performance store drops unsupported Workbench labels and counts series limit drops", () => { const store = createWebPerformanceStore({ env: { HWLAB_METRICS_NAMESPACE: "hwlab-v03", HWLAB_GITOPS_TARGET: "v03" }, maxSeries: 1 }); const first = store.record({ diff --git a/internal/cloud/web-performance.ts b/internal/cloud/web-performance.ts index bb17aa88..d94cce99 100644 --- a/internal/cloud/web-performance.ts +++ b/internal/cloud/web-performance.ts @@ -112,6 +112,10 @@ interface WebPerformanceEvent { startedAtEpochMs?: unknown; endedAtEpochMs?: unknown; errorName?: unknown; + timeoutName?: unknown; + activityWaitingFor?: unknown; + activityLastEventLabel?: unknown; + activityIdleMs?: unknown; } interface NormalizedPerformanceEvent { @@ -664,6 +668,10 @@ function normalizeWorkbenchUiOtelSpan(rawEvent: unknown, payload: WebPerformance const sessionHash = sanitizeOtelAttribute(input.sessionHash, 80); const traceHash = sanitizeOtelAttribute(input.traceHash, 80); const errorName = sanitizeOtelAttribute(input.errorName, 80); + const timeoutName = sanitizeOtelAttribute(input.timeoutName, 80); + const activityWaitingFor = sanitizeOtelAttribute(input.activityWaitingFor, 80); + const activityLastEventLabel = sanitizeOtelAttribute(input.activityLastEventLabel, 120); + const activityIdleMs = Math.min(Math.max(finiteNumber(input.activityIdleMs, NaN), 0), 3_600_000); return { name: ["workbench", eventType, scope, state].filter((part) => part && part !== "unknown").join("."), uiTraceId, @@ -686,6 +694,10 @@ function normalizeWorkbenchUiOtelSpan(rawEvent: unknown, payload: WebPerformance "workbench.ui.session_hash": sessionHash, "workbench.ui.trace_hash": traceHash, "workbench.ui.error_name": errorName, + "workbench.ui.timeout_name": timeoutName, + "workbench.ui.activity_waiting_for": activityWaitingFor, + "workbench.ui.activity_last_event_label": activityLastEventLabel, + ...(Number.isFinite(activityIdleMs) ? { "workbench.ui.activity_idle_ms": Math.trunc(activityIdleMs) } : {}), "workbench.ui.values_printed": false, "http.route": route, "http.request.method": normalizeMethod(input.method), diff --git a/web/hwlab-cloud-web/src/api/client.ts b/web/hwlab-cloud-web/src/api/client.ts index bdc97f9c..1d41deca 100644 --- a/web/hwlab-cloud-web/src/api/client.ts +++ b/web/hwlab-cloud-web/src/api/client.ts @@ -71,15 +71,28 @@ export async function fetchJson(path: string, options: ApiRequestOptions = {} }); const payload = await response.json().catch(() => null) as T | null; recordApiTiming({ route: path, method: options.method, status: response.status, startedAt, outcome: response.ok ? "ok" : "http_error" }); - recordWorkbenchApiRequest({ route: path, method: options.method, status: response.status, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: response.ok ? "ok" : "http_error" }); + recordWorkbenchApiRequest({ route: path, method: options.method, status: response.status, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: response.ok ? "ok" : "http_error", timeoutName: options.timeoutName }); return { ok: response.ok, status: response.status, data: payload, error: response.ok ? null : errorMessage(payload, `HTTP ${response.status}`) }; } catch (error) { const outcome = error instanceof DOMException && error.name === "AbortError" ? "timeout" : "network_error"; + const activity = inactivityRef.current; recordApiTiming({ route: path, method: options.method, status: 0, startedAt, outcome }); - recordWorkbenchApiRequest({ route: path, method: options.method, status: 0, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome }); + recordWorkbenchApiRequest({ + route: path, + method: options.method, + status: 0, + startedAtEpochMs: startedAt, + endedAtEpochMs: Date.now(), + outcome, + timeoutName: options.timeoutName, + activityIdleMs: activity?.idleMs, + activityWaitingFor: activity?.waitingFor, + activityLastEventLabel: activity?.lastEventLabel, + errorName: error instanceof Error ? error.name : undefined + }); if (error instanceof DOMException && error.name === "AbortError") { - if (inactivityRef.current) { - const detail = inactivityRef.current; + if (activity) { + const detail = activity; return { ok: false, status: 0, data: null, error: `${options.timeoutName ?? path} 超过 ${timeoutMs}ms 无新活动（idle ${Math.round(detail.idleMs / 1000)}s；waitingFor=${detail.waitingFor ?? "unknown"}；lastEventLabel=${detail.lastEventLabel ?? "none"}）` }; } return { ok: false, status: 0, data: null, error: `${options.timeoutName ?? path} 超时` }; @@ -96,11 +109,11 @@ export async function fetchText(path: string, options: ApiRequestOptions = {}): const response = await fetch(path, { ...options, credentials: options.credentials ?? "same-origin" }); const text = await response.text(); recordApiTiming({ route: path, method: options.method, status: response.status, startedAt, outcome: response.ok ? "ok" : "http_error" }); - recordWorkbenchApiRequest({ route: path, method: options.method, status: response.status, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: response.ok ? "ok" : "http_error" }); + recordWorkbenchApiRequest({ route: path, method: options.method, status: response.status, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: response.ok ? "ok" : "http_error", timeoutName: options.timeoutName }); return { ok: response.ok, status: response.status, data: text, error: response.ok ? null : `HTTP ${response.status}` }; } catch (error) { recordApiTiming({ route: path, method: options.method, status: 0, startedAt, outcome: "network_error" }); - recordWorkbenchApiRequest({ route: path, method: options.method, status: 0, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: "network_error" }); + recordWorkbenchApiRequest({ route: path, method: options.method, status: 0, startedAtEpochMs: startedAt, endedAtEpochMs: Date.now(), outcome: "network_error", timeoutName: options.timeoutName, errorName: error instanceof Error ? error.name : undefined }); return { ok: false, status: 0, data: null, error: error instanceof Error ? error.message : String(error) }; } } diff --git a/web/hwlab-cloud-web/src/utils/workbench-performance.ts b/web/hwlab-cloud-web/src/utils/workbench-performance.ts index 8dab8d8d..a0914513 100644 --- a/web/hwlab-cloud-web/src/utils/workbench-performance.ts +++ b/web/hwlab-cloud-web/src/utils/workbench-performance.ts @@ -4,7 +4,7 @@ import type { ChatMessage, TraceEvent } from "@/types"; type WorkbenchEventKind = "workbench_journey" | "workbench_event_phase" | "workbench_backend_event_visible" | "workbench_ui_event"; -type WorkbenchOutcome = "ok" | "timeout" | "error" | "dropped" | "stale" | "partial" | "empty" | "network" | "unknown"; +type WorkbenchOutcome = "ok" | "timeout" | "error" | "dropped" | "stale" | "partial" | "empty" | "network" | "denied" | "unknown"; type WorkbenchLoadingScope = "workbench" | "session_list" | "session_detail" | "api" | "sse" | "page"; type WorkbenchUiState = "enter" | "exit" | "request" | "connect" | "open" | "message" | "close" | "error" | "sample"; type WorkbenchUiReason = "hydrate" | "select_session" | "create_session" | "api_request" | "sse_connect" | "sse_open" | "sse_error" | "sse_close" | "pagehide" | "visibility_hidden" | "unknown"; @@ -41,6 +41,10 @@ interface WorkbenchPerformanceEvent { startedAtEpochMs?: number; endedAtEpochMs?: number; errorName?: string; + timeoutName?: string; + activityWaitingFor?: string | null; + activityLastEventLabel?: string | null; + activityIdleMs?: number; } interface TraceEventTimingInput { @@ -169,7 +173,7 @@ export function recordWorkbenchLoadingState(input: { scope: WorkbenchLoadingScop enqueueWorkbenchUiEvent({ eventType: "loading_state", loadingScope: input.scope, state: "exit", reason: previous.reason, route: previous.route, valueMs, startedAtEpochMs: previous.startEpochMs, endedAtEpochMs: nowEpoch, sessionHash: previous.sessionHash, traceHash: previous.traceHash, outcome: "ok" }); } -export function recordWorkbenchApiRequest(input: { route: string; method?: string; status?: number; startedAtEpochMs: number; endedAtEpochMs?: number; outcome?: string | null }): void { +export function recordWorkbenchApiRequest(input: { route: string; method?: string; status?: number; startedAtEpochMs: number; endedAtEpochMs?: number; outcome?: string | null; timeoutName?: string | null; errorName?: string | null; activityWaitingFor?: string | null; activityLastEventLabel?: string | null; activityIdleMs?: number | null }): void { if (!isWorkbenchPage()) return; const route = safeText(input.route); if (!route || route.startsWith("/v1/web-performance")) return; @@ -185,6 +189,11 @@ export function recordWorkbenchApiRequest(input: { route: string; method?: strin status: input.status, statusClass: statusClass(input.status), outcome: normalizeUiOutcome(input.outcome), + timeoutName: input.timeoutName ? safeText(input.timeoutName).slice(0, 80) : undefined, + errorName: input.errorName ? safeText(input.errorName).slice(0, 80) : undefined, + activityWaitingFor: input.activityWaitingFor ? safeText(input.activityWaitingFor).slice(0, 80) : undefined, + activityLastEventLabel: input.activityLastEventLabel ? safeText(input.activityLastEventLabel).slice(0, 120) : undefined, + activityIdleMs: Number.isFinite(input.activityIdleMs ?? NaN) ? Math.max(0, Math.round(Number(input.activityIdleMs))) : undefined, valueMs: Math.max(0, endedAtEpochMs - input.startedAtEpochMs), startedAtEpochMs: input.startedAtEpochMs, endedAtEpochMs