diff --git a/docs/observability/op-catalog.generated.json b/docs/observability/op-catalog.generated.json index 2d550fcaa8..8d58ec37ce 100644 --- a/docs/observability/op-catalog.generated.json +++ b/docs/observability/op-catalog.generated.json @@ -626,6 +626,12 @@ "site": "packages/keiko-server/src/observability/server-logger.ts:180", "package": "keiko-server" }, + { + "op": "chat.turn.started", + "category": "gateway", + "site": "packages/keiko-server/src/chat-handlers.ts:1687", + "package": "keiko-server" + }, { "op": "embedding.memory.failed", "category": "embedding", diff --git a/docs/qa/package-coverage-baseline.json b/docs/qa/package-coverage-baseline.json index f81af9a6b0..3c30a706ab 100644 --- a/docs/qa/package-coverage-baseline.json +++ b/docs/qa/package-coverage-baseline.json @@ -8,7 +8,7 @@ "keiko-cli": { "files": 44, "uncoveredFiles": 0, - "uncoveredLines": 387, + "uncoveredLines": 385, "totalLines": 4880, "coverage": { "lines": 92.11, @@ -234,15 +234,15 @@ } }, "keiko-server": { - "files": 580, + "files": 581, "uncoveredFiles": 0, - "uncoveredLines": 4516, - "totalLines": 56260, + "uncoveredLines": 4503, + "totalLines": 56309, "coverage": { - "lines": 91.98, - "statements": 89.27, - "branches": 81.89, - "functions": 94.86 + "lines": 92, + "statements": 89.3, + "branches": 81.91, + "functions": 94.91 } }, "keiko-tools": { @@ -261,10 +261,10 @@ "files": 419, "uncoveredFiles": 3, "uncoveredLines": 2967, - "totalLines": 39452, + "totalLines": 39455, "coverage": { "lines": 92.48, - "statements": 89.52, + "statements": 89.53, "branches": 81.8, "functions": 91.28 } diff --git a/packages/keiko-server/src/atlassian/syncRoutes.test.ts b/packages/keiko-server/src/atlassian/syncRoutes.test.ts index 0b18cc43aa..e5db41a78a 100644 --- a/packages/keiko-server/src/atlassian/syncRoutes.test.ts +++ b/packages/keiko-server/src/atlassian/syncRoutes.test.ts @@ -685,3 +685,37 @@ describe("Confluence sync — request validation fail-closed", () => { ); }); }); + +describe("Confluence sync — governed (agent-initiated) start correlation", () => { + it("threads the request's own correlation id into an authority-denied governed start instead of minting one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope in handleStartAtlassianConnectorSync — the governed denial record must reuse it, + // not a disconnected randomUUID(). An authority referencing a runId the server-side registry + // never issued denies fast (authority-invalid) without needing a real envelope setup. + const port = createInMemoryConfluenceFixture({ baseUrl: BASE_URL, spaces: [] }); + const { deps, credential } = depsFor(port); + const ctx = { + ...ctxFor( + "POST", + { authRef: credential.authRef }, + { + spaceKeys: ["ENG"], + authority: { + runId: "unregistered-agent-run", + envelopeDigest: "0".repeat(64), + workspaceRoot: "/nonexistent/workspace", + }, + }, + ), + correlationId: "req-governed-thread-01", + }; + + const result = await handleStartAtlassianConnectorSync(ctx, deps); + + expect(result.status).toBe(200); + expect(result.body).toMatchObject({ + disposition: "denied", + correlationId: "req-governed-thread-01", + }); + }); +}); diff --git a/packages/keiko-server/src/atlassian/syncRoutes.ts b/packages/keiko-server/src/atlassian/syncRoutes.ts index ae41a7ff7d..d62e19f5d0 100644 --- a/packages/keiko-server/src/atlassian/syncRoutes.ts +++ b/packages/keiko-server/src/atlassian/syncRoutes.ts @@ -384,10 +384,10 @@ async function startSyncGoverned( credential: AtlassianCredentialMetadata, body: StartSyncBody, authority: AtlassianActionAuthorityContext, + correlationId: string, ): Promise { const actionType = SYNC_ACTION_TYPE_FOR_PROVIDER[credential.provider]; const connectorId = connectorIdForAuthRef(credential.authRef); - const correlationId = randomUUID(); const targetRef = syncScopeTargetRef(body); const outcome = decideGovernedAtlassianAction(actionType, authority, deps); const denied = (reasonCode: AtlassianConnectorActivityReasonCode): RouteResult => @@ -428,7 +428,16 @@ export function handleStartAtlassianConnectorSync( const credential = requireAtlassianCredential(ctx, guard); const body = validateStartSyncBody(await readJsonObject(ctx.req), credential.provider); if (body.authority !== undefined) { - return startSyncGoverned(deps, guard, credential, body, body.authority); + // Threads the request's own correlation id (ADR-0173 D5 / g12) into the governed-start + // denial/pending-approval/allowed records instead of a disconnected mint. + return startSyncGoverned( + deps, + guard, + credential, + body, + body.authority, + ctx.correlationId ?? randomUUID(), + ); } // Direct human-triggered start: human-approved by construction (ADR-0129; ADR-0128 D5) — // recorded as `allowed` + `human-initiated` on the run's activity record. diff --git a/packages/keiko-server/src/atlassian/writeActionRoutes.test.ts b/packages/keiko-server/src/atlassian/writeActionRoutes.test.ts index 12b935497b..cb35ede758 100644 --- a/packages/keiko-server/src/atlassian/writeActionRoutes.test.ts +++ b/packages/keiko-server/src/atlassian/writeActionRoutes.test.ts @@ -1185,3 +1185,30 @@ describe("write-action route — clear-field validation (KEIKO-0319)", () => { expect(result.status).toBe(400); }); }); + +describe("write-action route — governed action correlation", () => { + it("threads the request's own correlation id into a policy-denied response instead of minting one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope in handleExecuteAtlassianConnectorAction — the governed-action denial record must + // reuse it, not a disconnected randomUUID(). An envelope with no write scope denies fast + // (policy-denied) without needing a provider round-trip. + const guard = guardWith({ count: 0, requests: [] }); + const deniedAuthority = registerEnvelope("autonomous-delivery", []); + const result = (await handleExecuteAtlassianConnectorAction( + { + ...ctx( + { action: ACTION_REQUESTS["transition-issue"], authority: deniedAuthority }, + { authRef: JIRA_AUTH_REF }, + ), + correlationId: "req-write-thread-01", + }, + deps(guard, "autonomous-delivery"), + )) as { status: number; body: Record }; + + expect(result.status).toBe(200); + expect(result.body).toMatchObject({ + disposition: "denied", + correlationId: "req-write-thread-01", + }); + }); +}); diff --git a/packages/keiko-server/src/atlassian/writeActionRoutes.ts b/packages/keiko-server/src/atlassian/writeActionRoutes.ts index ce159dd898..54dfd480f2 100644 --- a/packages/keiko-server/src/atlassian/writeActionRoutes.ts +++ b/packages/keiko-server/src/atlassian/writeActionRoutes.ts @@ -690,9 +690,9 @@ function governedActionResult( credential: AtlassianCredentialMetadata, authority: AtlassianActionAuthorityContext, plan: GovernedActionPlan, + correlationId: string, ): Promise | RouteResult { const connectorId = connectorIdForAuthRef(credential.authRef); - const correlationId = randomUUID(); const denied = (reasonCode: AtlassianConnectorActivityReasonCode): RouteResult => deniedAtlassianActionResult({ connectorId, @@ -785,11 +785,14 @@ export function handleExecuteAtlassianConnectorAction( throw invalid("authority must carry runId, envelopeDigest, and workspaceRoot"); } const input = validateGovernedActionInput(body.action, credential.provider); + // Threads the request's own correlation id (ADR-0173 D5 / g12) into the governed-action + // denial/pending-approval/allowed records instead of a disconnected mint. return governedActionResult( deps, credential, authority, actionPlanFor(guard, credential, input), + ctx.correlationId ?? randomUUID(), ); }); } diff --git a/packages/keiko-server/src/browser-routes.test.ts b/packages/keiko-server/src/browser-routes.test.ts index 6658f4be5f..d0570fee37 100644 --- a/packages/keiko-server/src/browser-routes.test.ts +++ b/packages/keiko-server/src/browser-routes.test.ts @@ -14,8 +14,10 @@ import { createRunRegistry } from "./runs.js"; import { createUiServer, UI_HOST } from "./server.js"; import { EventEmitter } from "node:events"; import type { ServerResponse } from "node:http"; -import { openBrowserSseStream } from "./browser.js"; +import { handleBrowserEvents, openBrowserSseStream } from "./browser.js"; import type { SseBackpressureSignal } from "./sse-write.js"; +import type { RouteContext } from "./routes.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; import { BrowserToolError, type BrowserEventEmitter, @@ -821,3 +823,48 @@ describe("openBrowserSseStream backpressure (KEIKO-0142)", () => { expect(fake.writes).toHaveLength(writesAfterClose); }); }); + +describe("handleBrowserEvents backpressure correlation (ADR-0173 D5 / g12)", () => { + it("threads the request's own correlation id into the backpressure diagnostic instead of minting one", () => { + const fake = makeFakeSseRes(); + fake.writeReturns = false; // rejects the ready frame -> immediate backpressure kill. + const manager = new FakeBrowserSessionManager(); + manager.opened.push("session-thread"); + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (entry) => { + records.push(entry); + }, + }; + const baseDeps: UiHandlerDeps = { + config: undefined, + configPresent: false, + evidenceStore: { + put: (): string => "", + list: (): readonly string[] => [], + get: (): undefined => undefined, + delete: (): undefined => undefined, + }, + env: process.env, + redactor: buildRedactor({}), + registry: createRunRegistry(), + modelPortFactory: (): undefined => undefined, + store: createInMemoryUiStore(), + browser: manager, + diagnostics, + }; + const ctx: RouteContext = { + req: { on: (): void => undefined } as unknown as RouteContext["req"], + res: fake.res, + params: { sessionId: "session-thread" }, + url: new URL("http://127.0.0.1/api/browser/sessions/session-thread/events"), + correlationId: "req-browser-thread-01", + }; + + handleBrowserEvents(ctx, baseDeps); + + expect(records).toHaveLength(1); + expect(records[0]?.source).toBe("sse.browser.backpressure"); + expect(records[0]?.correlationId).toBe("req-browser-thread-01"); + }); +}); diff --git a/packages/keiko-server/src/browser.ts b/packages/keiko-server/src/browser.ts index 156a662b57..5cfc6fbd60 100644 --- a/packages/keiko-server/src/browser.ts +++ b/packages/keiko-server/src/browser.ts @@ -260,12 +260,14 @@ export function handleBrowserEvents(ctx: RouteContext, deps: UiHandlerDeps): Han if (!guard.hasSession(sessionId)) { return { status: 404, body: errorBody("SESSION_NOT_FOUND", "Browser session not found.") }; } + // Threads the request's own correlation id (ADR-0173 D5 / g12) so a later backpressure kill + // joins back to the request that opened this stream instead of a disconnected mint. openBrowserSseStream( ctx.res, guard, sessionId, deps.redactor, - sseBackpressureReporter(deps, "browser"), + sseBackpressureReporter(deps, "browser", ctx.correlationId), ); ctx.req.on("close", () => { ctx.res.end(); diff --git a/packages/keiko-server/src/chat-compaction-evidence.test.ts b/packages/keiko-server/src/chat-compaction-evidence.test.ts index bac6cea3f7..da216504b5 100644 --- a/packages/keiko-server/src/chat-compaction-evidence.test.ts +++ b/packages/keiko-server/src/chat-compaction-evidence.test.ts @@ -425,6 +425,13 @@ describe("chat compaction evidence wiring (ADR-0057 D3)", () => { expect(records[0]?.message).toBe("Audit or evidence persistence failed."); expect(records[0]?.errorClass).toMatch(/^[A-Z][A-Za-z0-9]*$/); expect(records[0]?.correlationId).toMatch(/^[A-Za-z0-9._-]{8,128}$/); + // ADR-0173 D5 / g12: the failure's correlationId is THIS attempt's own runId (same + // derivation the successful-persist tests above pin), not a disconnected `randomUUID()` — + // an operator can join the failure back to the compaction attempt it belongs to. Before the + // fix this was a random UUID (with dashes) and never matched the runId shape below. + expect(records[0]?.correlationId).toBe( + `chat-${sha256Hex("chat-compaction-diagnostic").slice(0, 16)}-t4`, + ); expect(JSON.stringify(records)).not.toContain(SECRET); expect(consoleWarn).not.toHaveBeenCalled(); } finally { diff --git a/packages/keiko-server/src/chat-compaction-evidence.ts b/packages/keiko-server/src/chat-compaction-evidence.ts index 8bfc04ce2e..b413e3f107 100644 --- a/packages/keiko-server/src/chat-compaction-evidence.ts +++ b/packages/keiko-server/src/chat-compaction-evidence.ts @@ -11,6 +11,7 @@ import { resolveCostClass } from "@oscharko-dev/keiko-model-gateway"; import { sha256Hex } from "@oscharko-dev/keiko-security"; import type { ContextCompactionRecord } from "@oscharko-dev/keiko-contracts"; import { randomUUID } from "node:crypto"; +import { isValidCorrelationId } from "./correlation.js"; import type { UiHandlerDeps } from "./deps.js"; import { currentAuditRedactString, currentRedactionSecrets } from "./deps.js"; import { @@ -49,11 +50,16 @@ export function persistChatCompactionEvidence( return; } const record = input.compaction; + // Computed before the try so a persistence failure can still report under it (ADR-0173 D5 / + // g12): this run's own runId already ties the diagnostic back to the SAME compaction evidence + // attempt an operator would otherwise have to guess at from a disconnected mint. + let runId: string | undefined; try { const chatIdHash = sha256Hex(input.chatId); + runId = compactionRunId(chatIdHash, input.messageCount); persistCompactionEvidence( { - runId: compactionRunId(chatIdHash, input.messageCount), + runId, modelId: input.modelId, records: [record], startedAt: input.startedAt, @@ -75,10 +81,11 @@ export function persistChatCompactionEvidence( // Best-effort stays best-effort — the send is unaffected — but the failure is no longer a // `console.warn` carrying the raw error object on a channel production never overrode. It goes to // the server's single redacted diagnostic sink so a compaction-evidence gap is observable. + const correlationId = runId !== undefined && isValidCorrelationId(runId) ? runId : randomUUID(); emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "chat.compaction.evidence", source: "chat-compaction-evidence", error, diff --git a/packages/keiko-server/src/chat-compaction-model-summary.test.ts b/packages/keiko-server/src/chat-compaction-model-summary.test.ts index a61fcf6353..9e4d859465 100644 --- a/packages/keiko-server/src/chat-compaction-model-summary.test.ts +++ b/packages/keiko-server/src/chat-compaction-model-summary.test.ts @@ -1,3 +1,4 @@ +import { readFileSync } from "node:fs"; import { afterEach, describe, expect, it, vi } from "vitest"; import { CONTEXT_ENGINEERING_SCHEMA_VERSION, @@ -13,12 +14,14 @@ import { import { sha256Hex } from "@oscharko-dev/keiko-security"; import { createDefaultChatCapability, + type GatewayCallRequest, type GatewayConfig, type GatewayRequest, type NormalizedResponse, } from "@oscharko-dev/keiko-model-gateway"; import type { ModelPort } from "@oscharko-dev/keiko-harness"; import type { UiHandlerDeps } from "./deps.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; import type { ChatMessage } from "./store/index.js"; import { enrichChatCompactionWithModelSummary } from "./chat-compaction-model-summary.js"; @@ -113,6 +116,7 @@ function deps( store: EvidenceStore, model: ModelPort | undefined, supportsResponseFormat = true, + diagnostics?: ServerDiagnosticSink, ): UiHandlerDeps { return { config: gatewayConfig(supportsResponseFormat), @@ -121,6 +125,7 @@ function deps( env: {}, redactor, modelPortFactory: () => model, + diagnostics, } as unknown as UiHandlerDeps; } @@ -198,6 +203,14 @@ function neverResolvingModel(): ModelPort { }; } +function rejectingModel(): ModelPort { + return { + call(): Promise { + return Promise.reject(new Error("summary model transport failed")); + }, + }; +} + function defaultEnrichmentInput( messageCount = 2, ): Parameters[1] { @@ -260,6 +273,21 @@ describe("enrichChatCompactionWithModelSummary", () => { expectStructuredSummaryPersisted(persisted); }); + // ADR-0173 D5: this best-effort background summarization has no live HTTP request in scope, so + // the chat's own (internally-minted, opaque) id is the stable correlation key stamped into the + // model's GatewayCallRequest.logContext. + it("stamps the chat id into the model gateway call's logContext", async () => { + const store = createInMemoryEvidenceStore(); + const calls: GatewayRequest[] = []; + await enrichChatCompactionWithModelSummary( + deps(store, structuredSummaryModel(calls)), + defaultEnrichmentInput(), + ); + + const request = requireFirstRequest(calls); + expect((request as GatewayCallRequest).logContext?.correlationId).toBe(CHAT_ID); + }); + it("keeps a safe legacy text fallback when the model lacks response-format support", async () => { const store = createInMemoryEvidenceStore(); const calls: GatewayRequest[] = []; @@ -403,6 +431,44 @@ describe("enrichChatCompactionWithModelSummary", () => { expect(persisted.content).toBe(""); }); + // ADR-0173 D5 g25 — a scheduled-enrichment call failure used to reach only a bare `console.warn` + // (see the source-grep pin below); background summarization has no live REQUEST correlation id + // in scope, so the chat's own id — already the stable job key `callModelWithTimeout` labels its + // own call with — is the join key this diagnostic carries instead. + it("routes a model-call failure through the diagnostic sink, keyed by chatId", async () => { + const store = createInMemoryEvidenceStore(); + const events: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (record): void => { + events.push(record); + }, + }; + + await enrichChatCompactionWithModelSummary( + deps(store, rejectingModel(), true, diagnostics), + defaultEnrichmentInput(9), + ); + + expect(events).toHaveLength(1); + const [event] = events; + if (event === undefined) throw new Error("expected a diagnostic record"); + expect(event.correlationId).toBe(CHAT_ID); + expect(event.operation).toBe("chat.compaction.summary"); + expect(event.source).toBe("chat.compaction.model-summary"); + expect(event.errorClass).toBe("Error"); + // The diagnostic is additive: the turn still gets a usable fallback summary either way. + const persisted = requireModelSummary(store, 9); + expect(persisted.failureReason).toBe("model-unavailable"); + }); + + it("no longer logs a scheduled-enrichment failure through console.warn", () => { + const source = readFileSync( + new URL("./chat-compaction-model-summary.ts", import.meta.url), + "utf8", + ); + expect(source).not.toContain("console.warn("); + }); + it("accepts a structured summary needing no safety redaction despite cosmetic whitespace", async () => { const store = createInMemoryEvidenceStore(); const calls: GatewayRequest[] = []; diff --git a/packages/keiko-server/src/chat-compaction-model-summary.ts b/packages/keiko-server/src/chat-compaction-model-summary.ts index bc255bf907..8da2fe82fa 100644 --- a/packages/keiko-server/src/chat-compaction-model-summary.ts +++ b/packages/keiko-server/src/chat-compaction-model-summary.ts @@ -23,6 +23,7 @@ import { persistChatCompactionEvidence, type ChatCompactionEvidenceInput, } from "./chat-compaction-evidence.js"; +import { emitServerDiagnostic, serverDiagnosticFromError } from "./diagnostics-log.js"; const MODEL_SUMMARY_TIMEOUT_MS = 15_000; const MAX_SOURCE_TURNS = 16; @@ -154,7 +155,7 @@ export async function enrichChatCompactionWithModelSummary( const modelSummary = model === undefined ? failureModelSummary(record, input.modelId, "unavailable", "model-unavailable") - : await buildModelSummary(model, deps.redactor, input, record, prompt, responseMode); + : await buildModelSummary(model, deps, input, record, prompt, responseMode); if (modelSummary !== undefined) { persistChatCompactionEvidence(deps, { ...input, @@ -162,22 +163,31 @@ export async function enrichChatCompactionWithModelSummary( }); } } catch (error) { - logSummaryFailure(error); + logSummaryFailure(deps, input.chatId, error); } } async function buildModelSummary( model: ModelPort, - redactor: Redactor, + deps: UiHandlerDeps, input: ChatCompactionModelSummaryInput, record: ContextCompactionRecord, prompt: string, responseMode: ModelSummaryResponseMode, ): Promise { - const result = await callModelWithTimeout(model, input.modelId, prompt, responseMode); + // Background best-effort summarization has no live request correlation id in scope; the chat's + // own id is the stable job key an operator greps by, mirroring the `jobId`-as-correlationId + // convention background jobs elsewhere in the BFF already use (ADR-0173 D5). + const result = await callModelWithTimeout( + model, + input.modelId, + prompt, + responseMode, + input.chatId, + ); return result.kind === "response" - ? modelSummaryFromResponse(record, input.modelId, result.response, redactor, responseMode) - : modelSummaryFromCallFailure(record, input.modelId, result); + ? modelSummaryFromResponse(record, input.modelId, result.response, deps.redactor, responseMode) + : modelSummaryFromCallFailure(deps, input.chatId, record, input.modelId, result); } function modelSummaryFromResponse( @@ -222,6 +232,8 @@ function modelSummaryFromPayload( } function modelSummaryFromCallFailure( + deps: UiHandlerDeps, + correlationId: string, record: ContextCompactionRecord, modelId: string, result: Exclude, @@ -229,7 +241,7 @@ function modelSummaryFromCallFailure( if (result.kind === "timed-out") { return failureModelSummary(record, modelId, "timed-out", "timed-out"); } - logSummaryFailure(result.error); + logSummaryFailure(deps, correlationId, result.error); return failureModelSummary(record, modelId, "unavailable", "model-unavailable"); } @@ -238,6 +250,7 @@ async function callModelWithTimeout( modelId: string, prompt: string, responseMode: ModelSummaryResponseMode, + correlationId: string, ): Promise { const controller = new AbortController(); let timer: ReturnType | undefined; @@ -263,6 +276,7 @@ async function callModelWithTimeout( ...(responseMode === "structured" ? { responseFormat: MODEL_SUMMARY_RESPONSE_FORMAT } : {}), + logContext: { correlationId }, }, controller.signal, ), @@ -663,10 +677,19 @@ function failureModelSummary( }); } -function logSummaryFailure(error: unknown): void { - // eslint-disable-next-line no-console - console.warn( - "chat-compaction-model-summary: enrichment failed (best-effort, send unaffected)", - error, +// Replaces a bare `console.warn` (ADR-0173 D5 g25): a best-effort background enrichment failure +// (send unaffected — the compaction record itself already persisted) is still an operator-visible +// event, not a silent one. `correlationId` is the chat id (see `buildModelSummary` above): this +// background job has no live request id in scope, so the chat's own id is the stable join key. +function logSummaryFailure(deps: UiHandlerDeps, correlationId: string, error: unknown): void { + emitServerDiagnostic( + deps.diagnostics, + serverDiagnosticFromError({ + correlationId, + operation: "chat.compaction.summary", + source: "chat.compaction.model-summary", + error, + redact: (message) => String(deps.redactor(message)), + }), ); } diff --git a/packages/keiko-server/src/chat-handlers.test.ts b/packages/keiko-server/src/chat-handlers.test.ts index 2d2ca3dec0..dd2a02e845 100644 --- a/packages/keiko-server/src/chat-handlers.test.ts +++ b/packages/keiko-server/src/chat-handlers.test.ts @@ -1,19 +1,34 @@ -import { mkdirSync, mkdtempSync, realpathSync, rmSync } from "node:fs"; +import { mkdirSync, mkdtempSync, readFileSync, realpathSync, rmSync } from "node:fs"; import type { IncomingMessage, ServerResponse } from "node:http"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { Readable } from "node:stream"; -import { describe, expect, it, vi } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { MAX_DESKTOP_CHAT_CLIENT_TURN_ID_CHARS } from "@oscharko-dev/keiko-contracts/bff-wire"; -import { parseGatewayConfig } from "@oscharko-dev/keiko-model-gateway"; import { + parseGatewayConfig, + type GatewayConfig, + type NormalizedResponse, +} from "@oscharko-dev/keiko-model-gateway"; +import type { ModelPort } from "@oscharko-dev/keiko-harness"; +import { + chatTurnShapeFields, handleCreateDesktopChat, handleSendDesktopChat, parseClientTurnId, parseExpectedGroundingScopeIdentity, } from "./chat-handlers.js"; -import { buildUiHandlerDeps, type UiHandlerDeps } from "./deps.js"; +import { buildRedactor, buildUiHandlerDeps, type UiHandlerDeps } from "./deps.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; +import { + createBufferedServerLogSink, + createServerLogger, + resetServerLogger, + setServerLogger, +} from "./observability/index.js"; import type { RouteContext } from "./routes.js"; +import { createRunRegistry } from "./runs.js"; +import { createInMemoryUiStore } from "./store/index.js"; const VALID_GROUNDING_SCOPE_IDENTITY = `gsi-v1:${"a".repeat(64)}`; const INVALID_CLIENT_TURN_ID = { @@ -324,3 +339,327 @@ describe("desktop chat production gateway reuse", () => { } }); }); + +// ADR-0173 D5 g9 — `chatTurnShapeFields` is the exact production formula `chat.turn.started` +// logs; these tests derive their expectations by calling it directly rather than restating the +// counting logic as a second copy that could drift from it (AGENTS.md §7). +describe("chatTurnShapeFields", () => { + it("counts a 3-message turn by role and totals a single image attachment", () => { + const messages = [{ role: "system" }, { role: "user" }, { role: "assistant" }]; + const attachments = [ + { kind: "image" as const, mimeType: "image/png", sizeBytes: 40_000 }, + { kind: "document" as const, mimeType: "application/pdf", sizeBytes: 12_000 }, + ]; + + expect(chatTurnShapeFields(messages, attachments)).toEqual({ + messageCount: 3, + roleCounts: { system: 1, user: 1, assistant: 1, tool: 0 }, + toolCount: 0, + imageAttachmentCount: 1, + imageAttachmentBytes: 40_000, + }); + }); + + it("sums bytes across multiple image attachments and ignores an unrecognised role", () => { + const messages = [{ role: "system" }, { role: "tool" }, { role: "unknown-role" }]; + const attachments = [ + { kind: "image" as const, mimeType: "image/png", sizeBytes: 1_000 }, + { kind: "image" as const, mimeType: "image/jpeg", sizeBytes: 2_500 }, + ]; + + const fields = chatTurnShapeFields(messages, attachments); + expect(fields.messageCount).toBe(3); + expect(fields.roleCounts).toEqual({ system: 1, user: 0, assistant: 0, tool: 1 }); + expect(fields.toolCount).toBe(1); + expect(fields.imageAttachmentCount).toBe(2); + expect(fields.imageAttachmentBytes).toBe(3_500); + }); + + it("returns zeroed counts for an empty turn", () => { + expect(chatTurnShapeFields([], [])).toEqual({ + messageCount: 0, + roleCounts: { system: 0, user: 0, assistant: 0, tool: 0 }, + toolCount: 0, + imageAttachmentCount: 0, + imageAttachmentBytes: 0, + }); + }); +}); + +function turnShapeGatewayConfig(modelId: string): GatewayConfig { + return { + // `listConfiguredCapabilities` cross-references `capabilities` against `providers` by + // `modelId` (`model-selection.ts`) — a capability with no matching provider entry is + // filtered out of the registry, so `modelCapabilityRegistry` would see this model as + // "not chat-capable" without one, even though this test never dials out to it. + providers: [ + { + modelId, + baseUrl: "https://provider.example.invalid/v1", + apiKey: "unused-test-key", + timeoutMs: 5_000, + maxRetries: 0, + retryBaseDelayMs: 1, + }, + ], + circuitBreaker: { failureThreshold: 5, cooldownMs: 1_000, halfOpenProbes: 1 }, + capabilities: [ + { + id: modelId, + kind: "chat", + contextWindow: 64_000, + maxOutputTokens: 4_096, + toolCalling: false, + structuredOutput: false, + streaming: true, + supportsImageInput: false, + supportsDocumentInput: false, + workflowEligible: false, + costClass: "medium", + latencyClass: "standard", + throughputHint: "test", + preferredUseCases: [], + knownLimitations: [], + }, + ], + }; +} + +function turnShapeModel(): ModelPort { + return { + call(request): Promise { + return Promise.resolve({ + modelId: request.modelId, + content: "Hallo!", + finishReason: "stop", + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "turn-shape-test", + promptTokens: 3, + completionTokens: 2, + latencyMs: 5, + costClass: "low", + }, + }); + }, + }; +} + +describe("chat.turn.started", () => { + afterEach(() => { + resetServerLogger(); + }); + + it("logs messageCount/roleCounts once per turn, keyed to the request correlation id", async () => { + const sink = createBufferedServerLogSink(); + setServerLogger(createServerLogger({ sink, level: "info" })); + const modelId = "turn-shape-chat"; + const root = mkdtempSync(join(realpathSync(tmpdir()), "keiko-chat-turn-shape-")); + const projectPath = join(root, "repo"); + try { + mkdirSync(projectPath); + const store = createInMemoryUiStore(); + store.createProject(projectPath, "repo"); + const chat = store.createChat(projectPath, "Turn shape", modelId); + const deps: UiHandlerDeps = { + config: turnShapeGatewayConfig(modelId), + configPresent: true, + evidenceStore: { + put: () => "", + list: () => [], + get: () => undefined, + delete: () => undefined, + }, + env: {}, + redactor: buildRedactor({}), + registry: createRunRegistry(), + modelPortFactory: () => turnShapeModel(), + store, + }; + // A prior completed turn — sent through the SAME production path, not hand-seeded into the + // store — so the second turn's assembled prompt carries 4 messages: the fixed system + // prompt, the prior user+assistant pair, and the current user message being sent. The exact + // "3-message" formula case is covered precisely by chatTurnShapeFields above; this send only + // needs a real, non-trivial shape to prove the wiring counts what the assembled prompt + // actually contains, not a restated expectation. + const priorResult = await handleSendDesktopChat( + { + ...requestContext({ + chatId: chat.id, + projectPath, + modelId, + content: "What is on the roadmap?", + }), + correlationId: "turn-shape-prior", + }, + deps, + ); + if (priorResult.status !== 200) { + throw new Error( + `expected the seeded prior turn to succeed: ${JSON.stringify(priorResult)}`, + ); + } + const result = await handleSendDesktopChat( + { + ...requestContext({ chatId: chat.id, projectPath, modelId, content: "Hello there" }), + correlationId: "turn-shape-correlation-1", + }, + deps, + ); + expect(result.status).toBe(200); + const events = sink.events.filter( + (event) => + event.op === "chat.turn.started" && event.correlationId === "turn-shape-correlation-1", + ); + expect(events).toHaveLength(1); + const [event] = events; + if (event === undefined) throw new Error("expected a chat.turn.started event"); + expect(event.category).toBe("gateway"); + expect(event.extra).toEqual({ + messageCount: 4, + roleCounts: { system: 1, user: 2, assistant: 1, tool: 0 }, + toolCount: 0, + imageAttachmentCount: 0, + imageAttachmentBytes: 0, + }); + } finally { + rmSync(root, { recursive: true, force: true }); + } + }); +}); + +// ADR-0173 D5 g25 — the buffered `/api/desktop/chat` path used to map a GatewayError straight to +// an HTTP body with no operator diagnostic at all, unlike the SSE `/api/desktop/chat/stream` path +// (`chat-stream-handlers.test.ts` pins that side). This is the fails-before proof for the shared +// symmetry fix: before it, `events` below stayed empty on a RateLimitError. +describe("desktopChatErrorResult gateway diagnostic symmetry", () => { + it("emits the same diagnostic shape as the streaming path on a RateLimitError", async () => { + const fixture = await createGatewayBreakerFixture(); + try { + const events: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (record): void => { + events.push(record); + }, + }; + const deps: UiHandlerDeps = { ...fixture.deps, diagnostics }; + const fetchSpy = vi.fn(() => + Promise.resolve( + new Response(JSON.stringify({ error: { message: "slow down" } }), { + status: 429, + headers: { "content-type": "application/json", "retry-after": "2" }, + }), + ), + ); + vi.stubGlobal("fetch", fetchSpy); + + const result = await handleSendDesktopChat( + { + ...requestContext({ + chatId: fixture.chatId, + projectPath: fixture.projectPath, + modelId: "breaker-chat", + content: "please respond", + }), + correlationId: "rate-limit-correlation-1", + }, + deps, + ); + + expect(gatewayErrorCode(result)).toBe("GATEWAY_RATE_LIMIT"); + expect(result.status).toBe(503); + expect(events).toHaveLength(1); + const [event] = events; + if (event === undefined) throw new Error("expected a diagnostic record"); + expect(event.correlationId).toBe("rate-limit-correlation-1"); + expect(event.operation).toBe("POST /api/desktop/chat"); + expect(event.source).toBe("chat.send"); + expect(event.errorClass).toBe("RateLimitError"); + } finally { + vi.unstubAllGlobals(); + await disposeGatewayBreakerFixture(fixture); + } + }); +}); + +// ADR-0173 D5 g25 — scheduling wrapper around `enrichChatCompactionWithModelSummary` +// (`chat-handlers.ts`'s own `logCompactionSummaryFailure`, mirroring `recordPostCommitMemoryFailure` +// at chat-handlers.ts:1444-1452). `enrichChatCompactionWithModelSummary` already absorbs every +// failure it can reach internally (see chat-compaction-model-summary.test.ts), so this wrapper's +// own catch is exercised here by mocking that import — the only way to reach it without relying on +// an internal implementation detail of the mocked module. +describe("logCompactionSummaryFailure", () => { + afterEach(() => { + vi.doUnmock("./chat-compaction-model-summary.js"); + vi.resetModules(); + }); + + it("routes a scheduled-enrichment rejection through the diagnostic sink instead of console.warn", async () => { + // `chat-handlers.js` (and its static import of `chat-compaction-model-summary.js`) is already + // cached from this file's top-level imports; the cache must be cleared BEFORE re-importing, + // or the fresh import below would resolve to the same already-loaded, unmocked module graph. + vi.resetModules(); + vi.doMock("./chat-compaction-model-summary.js", () => ({ + enrichChatCompactionWithModelSummary: (): Promise => + Promise.reject(new Error("scheduled enrichment blew up")), + })); + const { recordChatCompaction } = await import("./chat-handlers.js"); + const events: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (record): void => { + events.push(record); + }, + }; + const deps = { + evidenceStore: { + put: () => "", + list: () => [], + get: () => undefined, + delete: () => undefined, + }, + env: {}, + redactor: (value: unknown): unknown => value, + diagnostics, + } as unknown as UiHandlerDeps; + + recordChatCompaction(deps, { + compaction: { + laneId: "history-summary", + reason: "exceeded effective input budget", + itemsBefore: 2, + itemsAfter: 1, + tokensBefore: 100, + tokensAfter: 20, + preservedFacts: [], + decisions: [], + }, + request: { chatId: "chat-scheduling-failure-1" }, + modelId: "scheduling-failure-model", + messageCount: 1, + startedAt: Date.now(), + historyPrefix: [], + correlationId: "scheduling-failure-correlation-1", + } as never); + + // The failure surfaces via a detached `setImmediate` + a rejected promise's `.catch`; give + // both a turn of the event loop to run before asserting. + await new Promise((resolve) => setImmediate(resolve)); + await new Promise((resolve) => setImmediate(resolve)); + + const scheduled = events.filter( + (event) => event.operation === "chat.compaction.summary.scheduled", + ); + expect(scheduled).toHaveLength(1); + const [event] = scheduled; + if (event === undefined) throw new Error("expected a diagnostic record"); + expect(event.correlationId).toBe("scheduling-failure-correlation-1"); + expect(event.source).toBe("chat.compaction.model-summary"); + expect(event.errorClass).toBe("Error"); + }); + + it("no longer logs a scheduled-enrichment failure through console.warn", () => { + const source = readFileSync(new URL("./chat-handlers.ts", import.meta.url), "utf8"); + expect(source).not.toContain("console.warn("); + }); +}); diff --git a/packages/keiko-server/src/chat-handlers.ts b/packages/keiko-server/src/chat-handlers.ts index 6d4a12bf03..8078d52ded 100644 --- a/packages/keiko-server/src/chat-handlers.ts +++ b/packages/keiko-server/src/chat-handlers.ts @@ -127,7 +127,14 @@ import { embedAndStoreMemory } from "./memory-embedding.js"; import { recordMemoryAudit } from "./memory-audit-handler.js"; import { recordAutoAcceptedMemoryCaptureDecision } from "./memory-capture-audit.js"; import { scheduleMemorySalienceCapture } from "./memory-salience.js"; -import { contentFreeErrorClass, emitServerDiagnostic } from "./diagnostics-log.js"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; +import { + contentFreeErrorClass, + emitServerDiagnostic, + serverDiagnosticFromError, +} from "./diagnostics-log.js"; +import { emitGatewayErrorDiagnostic } from "./gateway-error-diagnostic.js"; +import { getServerLogger } from "./observability/index.js"; import { assertUsableAssistantContent, isLegacyEmptyAssistantPlaceholder, @@ -356,12 +363,31 @@ function gatewayErrorStatus(error: GatewayError): number { return 502; } -function gatewayErrorResult(error: GatewayError, deps: UiHandlerDeps): RouteResult { +// ADR-0173 D5 g25 — every GatewayError this path maps to a response also reaches the redacted +// operator diagnostic sink, the same symmetry `chat-stream-handlers.ts`'s SSE path already had. +// `emitDiagnostic` defaults on for the normal (response-returning) callers below and is turned off +// by the ONE caller that already emitted its own broader diagnostic for this exact error a moment +// earlier and calls back in purely to reuse the code/message mapping (`chat-stream-handlers.ts`'s +// `errorEvent`) — without it that caller would double-log the same failure. +function gatewayErrorResult( + error: GatewayError, + deps: UiHandlerDeps, + correlationId: string | undefined, + emitDiagnostic: boolean, +): RouteResult { + if (emitDiagnostic) { + emitGatewayErrorDiagnostic(deps, error, correlationId, "POST /api/desktop/chat", "chat.send"); + } const status = gatewayErrorStatus(error); return { status, body: errorBody(error.code, redactErrorMessage(error.message, deps)) }; } -export function desktopChatErrorResult(error: unknown, deps: UiHandlerDeps): RouteResult { +export function desktopChatErrorResult( + error: unknown, + deps: UiHandlerDeps, + correlationId?: string, + emitDiagnostic = true, +): RouteResult { if (error instanceof ConversationAttachmentStoreError) { return { status: 409, @@ -369,7 +395,7 @@ export function desktopChatErrorResult(error: unknown, deps: UiHandlerDeps): Rou }; } if (error instanceof GatewayError) { - return gatewayErrorResult(error, deps); + return gatewayErrorResult(error, deps, correlationId, emitDiagnostic); } if (error instanceof UiStoreError) { return { @@ -1135,11 +1161,23 @@ export function maybeRunChatAutoMaintenance( vault: MemoryVaultStore, state: AutoMaintenanceState = memoryMaintenanceCursor, nowMs: number = Date.now(), + // The triggering chat request's own correlation id, when known (ADR-0173 D5 / g12). This pass + // is genuinely background-originated (opportunistic, rate-limited, may run well after the turn + // that triggered it), so it mints its own id below rather than reusing the request's outright — + // but a known request id still rides as `parentCorrelationId` so an operator can join this + // pass's diagnostics back to the request that opportunistically triggered it. + requestCorrelationId?: string, ): void { if (deps.env.KEIKO_MEMORY_AUTO_MAINTAIN === "0") return; if (!isMaintenanceDue(state.lastRunAtMs, nowMs)) return; + // Minted ONCE here, at the start of this maintenance pass, rather than inside each helper's own + // catch block: the retention-policy read, the autonomy-mode read, and the maintenance sweep + // itself are three separate failure points of the SAME pass, and used to mint three disconnected + // ids — making it impossible for an operator to tell they came from one invocation (ADR-0173 D5 + // / g12). + const correlationId = randomUUID(); const multipliers = memorySemanticizationMultipliers(deps.env); - const retention = resolveMemoryRetentionPolicy(deps); + const retention = resolveMemoryRetentionPolicy(deps, correlationId); // A malformed retention setting disables only the retention phase. The resolver already emits a // diagnostic; promotion, consolidation, supersession, and fade must keep running so one invalid // optional setting cannot silently suspend all pre-existing vault maintenance. @@ -1147,17 +1185,20 @@ export function maybeRunChatAutoMaintenance( maybeRunAutoMaintenance(vault, memoryMaintenanceAuditSink(deps), state, { nowMs, enabled: true, - autonomyMode: resolveMaintenanceAutonomyMode(deps), + autonomyMode: resolveMaintenanceAutonomyMode(deps, correlationId), ...(multipliers !== undefined ? { decayHalfLifeMultiplierByType: multipliers } : {}), ...(retentionPolicy !== undefined ? { retentionPolicy } : {}), onFailure: (error): void => { emitServerDiagnostic(deps.diagnostics, { - correlationId: randomUUID(), + correlationId, timestamp: new Date(Date.now()).toISOString(), operation: "chat.memory.auto-maintenance", source: "chat.memory.maintenance", errorClass: contentFreeErrorClass(error), message: "chat-memory-auto-maintenance-failed", + ...(requestCorrelationId === undefined + ? {} + : { parentCorrelationId: requestCorrelationId }), }); }, }); @@ -1584,6 +1625,71 @@ export function buildGatewayAssembly( return selected; } +// ADR-0173 D5 g9 — the INPUT shape of a chat turn, never its content: how many messages the +// assembled prompt carries (split by role) and how many image attachments rode along (count + +// bytes). Logged once, at the point the assembled prompt and the parsed attachments are both +// already in hand, so an agent reconstructing a defect from the activity log can tell "a +// 40-message context with two images" from "a bare one-line question" without ever seeing a +// token of either. Deliberately NOT the speculative JSON shape-skeleton feature (positional +// locator tuples over the request/response bodies) — that stays a documented forward guardrail, +// not built here (final-design.md Decisions Log D14). +const CHAT_TURN_ROLES = ["system", "user", "assistant", "tool"] as const; +type ChatTurnRole = (typeof CHAT_TURN_ROLES)[number]; +const CHAT_TURN_ROLE_SET: ReadonlySet = new Set(CHAT_TURN_ROLES); + +export interface ChatTurnShapeFields { + readonly messageCount: number; + readonly roleCounts: Readonly>; + // Denormalized copy of roleCounts.tool: a scalar an agent can grep for directly, without + // descending into the nested extra.roleCounts object. + readonly toolCount: number; + readonly imageAttachmentCount: number; + readonly imageAttachmentBytes: number; +} + +// Exported so its co-located test derives its expectations by calling this exact production +// formula (AGENTS.md §7) rather than restating the counting logic as a second copy that could +// drift from it. +export function chatTurnShapeFields( + messages: readonly { readonly role: string }[], + attachments: readonly ConversationAttachment[], +): ChatTurnShapeFields { + const roleCounts: Record = { system: 0, user: 0, assistant: 0, tool: 0 }; + for (const message of messages) { + if (CHAT_TURN_ROLE_SET.has(message.role)) { + roleCounts[message.role as ChatTurnRole] += 1; + } + } + let imageAttachmentCount = 0; + let imageAttachmentBytes = 0; + for (const attachment of attachments) { + if (attachment.kind === "image") { + imageAttachmentCount += 1; + imageAttachmentBytes += attachment.sizeBytes; + } + } + return { + messageCount: messages.length, + roleCounts, + toolCount: roleCounts.tool, + imageAttachmentCount, + imageAttachmentBytes, + }; +} + +function logChatTurnStarted( + correlationId: string | undefined, + messages: readonly { readonly role: string }[], + attachments: readonly ConversationAttachment[], +): void { + getServerLogger().info({ + category: "gateway", + op: "chat.turn.started", + correlationId, + extra: { ...chatTurnShapeFields(messages, attachments) }, + }); +} + export interface ChatCompactionTurn { readonly compaction: ConversationCompactionOutcome["compaction"]; readonly request: SendDesktopChatRequest; @@ -1591,6 +1697,10 @@ export interface ChatCompactionTurn { readonly messageCount: number; readonly startedAt: number; readonly historyPrefix: readonly ChatMessage[]; + // ADR-0173 D5 g25 — the request's correlation id, carried through so a scheduled-enrichment + // failure (logged well after the response left, from inside a detached setImmediate) still + // joins back to the request that triggered it instead of standing alone in the activity log. + readonly correlationId: string | undefined; } // ADR-0057 D3: best-effort persist of the turn's compaction record AFTER the response completes. @@ -1607,13 +1717,14 @@ export function recordChatCompaction(deps: UiHandlerDeps, turn: ChatCompactionTu finishedAt: Date.now(), } satisfies ChatCompactionEvidenceInput; persistChatCompactionEvidence(deps, input); - scheduleCompactionModelSummary(deps, input, turn.historyPrefix); + scheduleCompactionModelSummary(deps, input, turn.historyPrefix, turn.correlationId); } function scheduleCompactionModelSummary( deps: UiHandlerDeps, input: ChatCompactionEvidenceInput, historyPrefix: readonly ChatMessage[], + correlationId: string | undefined, ): void { if ( input.compaction === undefined || @@ -1625,7 +1736,7 @@ function scheduleCompactionModelSummary( const handle = setImmediate(() => { void enrichChatCompactionWithModelSummary(deps, { ...input, historyPrefix }) .catch((error: unknown) => { - logCompactionSummaryFailure(error); + logCompactionSummaryFailure(deps, correlationId, error); }) .finally(() => { pendingCompactionSummaries -= 1; @@ -1634,9 +1745,25 @@ function scheduleCompactionModelSummary( handle.unref(); } -function logCompactionSummaryFailure(error: unknown): void { - // eslint-disable-next-line no-console - console.warn("chat-compaction-model-summary: scheduled enrichment failed", error); +// Replaces a bare `console.warn` (ADR-0173 D5 g25): the scheduled enrichment runs detached from +// the request/response cycle, so its own internal try/catch (`enrichChatCompactionWithModelSummary`) +// already routes the ordinary failure paths to a diagnostic — this outer catch only fires for a +// failure that escapes THAT guard, and must not go back to being invisible. +function logCompactionSummaryFailure( + deps: UiHandlerDeps, + correlationId: string | undefined, + error: unknown, +): void { + emitServerDiagnostic( + deps.diagnostics, + serverDiagnosticFromError({ + correlationId: correlationId ?? UNKNOWN_CORRELATION_ID, + operation: "chat.compaction.summary.scheduled", + source: "chat.compaction.model-summary", + error, + redact: (message) => String(deps.redactor(message)), + }), + ); } function buildRegenerateGatewayAssembly( @@ -1796,6 +1923,7 @@ async function resolveBufferedMemory( prepared: PreparedDesktopChatSend, admitted: AdmittedTurnHandle, abortSignal: AbortSignal, + correlationId: string | undefined, ): Promise { const { request, memoryContext } = prepared; let memory: ConversationMemoryResultWire; @@ -1807,7 +1935,9 @@ async function resolveBufferedMemory( } catch (error) { const cancelled = requestSignalAborted(abortSignal); settleRejectedDesktopChatTurn(deps, prepared, admitted, cancelled ? "cancelled" : "failed"); - return cancelled ? requestCancelledResult() : desktopChatErrorResult(error, deps); + return cancelled + ? requestCancelledResult() + : desktopChatErrorResult(error, deps, correlationId); } // Cancellation that lands during retrieval must be settled HERE, before assembly and the // provider call — this is still pre-provider, so a legacy row is discarded rather than @@ -1854,6 +1984,7 @@ async function persistModelChatTurn( deps: UiHandlerDeps, prepared: PreparedDesktopChatSend, abortSignal: AbortSignal, + correlationId: string | undefined, ): Promise { const { request } = prepared; // ADR-0057 D3: pin the pre-user-message count BEFORE createUserMessage stores the turn, so the @@ -1867,11 +1998,14 @@ async function persistModelChatTurn( abortSignal, messageCountBeforeTurn, startedAt, + correlationId, ); } catch (error) { const cancelled = requestSignalAborted(abortSignal); failDesktopChatTurn(deps, request, cancelled ? "cancelled" : "failed"); - return cancelled ? requestCancelledResult() : desktopChatErrorResult(error, deps); + return cancelled + ? requestCancelledResult() + : desktopChatErrorResult(error, deps, correlationId); } } @@ -1881,6 +2015,7 @@ async function executeBufferedModelTurn( abortSignal: AbortSignal, messageCountBeforeTurn: number, startedAt: number, + correlationId: string | undefined, ): Promise { const { request, modelId } = prepared; const outcome = admitBufferedModelTurn(deps, prepared); @@ -1888,21 +2023,22 @@ async function executeBufferedModelTurn( const { admitted, executionAdmission } = outcome; const { userMessage } = admitted; const gatewayTurn = captureGatewayTurnSnapshot(deps, request, userMessage); - const memory = await resolveBufferedMemory(deps, prepared, admitted, abortSignal); + const memory = await resolveBufferedMemory(deps, prepared, admitted, abortSignal, correlationId); if (isRouteResult(memory)) return memory; - const assembly = assemblyWithConversationImages( - deps, - request, - modelId, - buildGatewayAssembly(deps, request, memory, modelId, gatewayTurn), - ); + const baseAssembly = buildGatewayAssembly(deps, request, memory, modelId, gatewayTurn); + // Logged from the base assembly, BEFORE image content parts are spliced in: image delivery can + // still fail its own (unrelated) authority/session check below, and this shape evidence must + // exist either way. Splicing only augments the final message's contentParts, never message + // count or role — so the counted shape is identical from either assembly. + logChatTurnStarted(correlationId, baseAssembly.messages, request.attachments); + const assembly = assemblyWithConversationImages(deps, request, modelId, baseAssembly); const model = bufferedModelAtProviderBoundary(deps, modelId, executionAdmission); if (isRouteResult(model)) { settleRejectedDesktopChatTurn(deps, prepared, admitted); return model; } const response = await model.call( - { modelId, messages: assembly.messages, stream: false }, + { modelId, messages: assembly.messages, stream: false, logContext: { correlationId } }, abortSignal, ); const cancelledAfterCall = bufferedTurnCancellationResult(deps, prepared, abortSignal); @@ -1918,6 +2054,7 @@ async function executeBufferedModelTurn( messageCount: messageCountBeforeTurn, startedAt, historyPrefix: gatewayHistoryPrefix(gatewayTurn), + correlationId, }, ); } @@ -1929,6 +2066,7 @@ interface BufferedCompactionContext { readonly messageCount: number; readonly startedAt: number; readonly historyPrefix: readonly ChatMessage[]; + readonly correlationId: string | undefined; } async function finalizeAndRecordBufferedTurn( @@ -1948,6 +2086,7 @@ async function finalizeAndRecordBufferedTurn( messageCount: compaction.messageCount, startedAt: compaction.startedAt, historyPrefix: compaction.historyPrefix, + correlationId: compaction.correlationId, }); } return finalized; @@ -2298,7 +2437,7 @@ export async function handleSendDesktopChat( () => { const current = validateCurrentDesktopChatSend(parsed, deps); if (isRouteResult(current)) return current; - return persistModelChatTurn(deps, current, cancellation.signal); + return persistModelChatTurn(deps, current, cancellation.signal, ctx.correlationId); }, ); return result === CHAT_TURN_WAIT_CANCELLED ? requestCancelledResult() : result; @@ -2683,6 +2822,7 @@ async function persistRegeneratedChatTurn( deps: UiHandlerDeps, prepared: PreparedDesktopChatRegenerate, signal: AbortSignal, + correlationId: string | undefined, ): Promise { const { chat, modelId, memoryRequest, executionAdmission } = prepared; try { @@ -2698,7 +2838,10 @@ async function persistRegeneratedChatTurn( if (model === undefined) { return { status: 400, body: errorBody("NO_MODEL", "No model provider is configured.") }; } - const response = await model.call({ modelId, messages, stream: false }, signal); + const response = await model.call( + { modelId, messages, stream: false, logContext: { correlationId } }, + signal, + ); if (requestSignalAborted(signal)) return requestCancelledResult(); const redactedContent = deps.redactor(response.content) as string; assertUsableAssistantContent(redactedContent, modelId); @@ -2720,7 +2863,9 @@ async function persistRegeneratedChatTurn( }, }; } catch (error) { - return signal.aborted ? requestCancelledResult() : desktopChatErrorResult(error, deps); + return signal.aborted + ? requestCancelledResult() + : desktopChatErrorResult(error, deps, correlationId); } } @@ -2741,7 +2886,7 @@ export async function handleRegenerateDesktopChat( const current = prepareDesktopChatRegenerateRequest(prepared.request, deps); return isRouteResult(current) ? current - : persistRegeneratedChatTurn(deps, current, cancellation.signal); + : persistRegeneratedChatTurn(deps, current, cancellation.signal, ctx.correlationId); }, ); return result === CHAT_TURN_WAIT_CANCELLED ? requestCancelledResult() : result; diff --git a/packages/keiko-server/src/chat-stream-handlers.test.ts b/packages/keiko-server/src/chat-stream-handlers.test.ts index fb2c02ac2e..6bba03c8b9 100644 --- a/packages/keiko-server/src/chat-stream-handlers.test.ts +++ b/packages/keiko-server/src/chat-stream-handlers.test.ts @@ -36,6 +36,7 @@ import type { RuntimeGatewayConfig } from "./deps.js"; import { createInMemoryUiStore, type UiStore } from "./store/index.js"; import type { ModelPort } from "@oscharko-dev/keiko-harness"; import type { + GatewayCallRequest, GatewayConfig, GatewayRequest, GatewayStreamChunk, @@ -284,7 +285,7 @@ function deferred(): { interface StreamingModel { readonly model: ModelPort; - readonly recorded: { request: GatewayRequest | undefined }; + readonly recorded: { request: GatewayCallRequest | undefined }; readonly calls: { count: number }; } @@ -292,13 +293,13 @@ interface StreamingModel { // terminal done chunk. `onFirstDelta` (used by the cancel test) runs after the first delta is yielded // so the test can abort the controller deterministically before the done chunk arrives. function streamingModel(content: string, onFirstDelta?: () => void): StreamingModel { - const recorded: { request: GatewayRequest | undefined } = { request: undefined }; + const recorded: { request: GatewayCallRequest | undefined } = { request: undefined }; const calls = { count: 0 }; const model: ModelPort = { call(): Promise { return Promise.resolve(normalizedResponse(content)); }, - async *callStream(request: GatewayRequest): AsyncGenerator { + async *callStream(request: GatewayCallRequest): AsyncGenerator { calls.count += 1; recorded.request = request; yield { type: "delta", token: "hi" }; @@ -2842,6 +2843,29 @@ describe("desktop chat SSE streaming handler", () => { expect(JSON.stringify(record)).not.toContain("boom-unexpected-mid-stream"); }); + // ADR-0173 D5: the streaming call site (streamAndPersist) must stamp the request's correlation id + // into GatewayCallRequest.logContext, mirroring the buffered path, so a gateway retry line for a + // streamed turn joins the same trail as the rest of the request. + it("threads the request correlation id into the streaming model gateway call's logContext", async () => { + const chatId = seedChat(); + const streaming = streamingModel("hi"); + const res = captureRes(); + const ctx: RouteContext = { + ...routeContext( + makeReq({ chatId, projectPath: projectDir, modelId: CHAT_MODEL, content: "hello" }), + res.res, + ), + correlationId: "cid-stream-logcontext-000001", + }; + + await handleSendDesktopChatStream(ctx, deps(streaming.model)); + + expect(streaming.calls.count).toBe(1); + expect(streaming.recorded.request?.logContext?.correlationId).toBe( + "cid-stream-logcontext-000001", + ); + }); + it("persists the user message but NO assistant message when the stream is cancelled", async () => { const chatId = seedChat(); // captureResWithEvents is required here so the res.on("close") listener registered by diff --git a/packages/keiko-server/src/chat-stream-handlers.ts b/packages/keiko-server/src/chat-stream-handlers.ts index f13dcca567..99ab4434f2 100644 --- a/packages/keiko-server/src/chat-stream-handlers.ts +++ b/packages/keiko-server/src/chat-stream-handlers.ts @@ -17,7 +17,8 @@ import { type RouteContext, type RouteResult, } from "./routes.js"; -import { emitServerDiagnostic, serverDiagnosticFromError } from "./diagnostics-log.js"; +import { emitGatewayErrorDiagnostic } from "./gateway-error-diagnostic.js"; +import type { ConversationCompactionOutcome } from "./conversation-compaction.js"; import type { UiHandlerDeps } from "./deps.js"; import type { ChatMessage } from "./store/index.js"; import { ensureOnDemandConversationReadiness } from "./gateway-readiness.js"; @@ -116,15 +117,12 @@ function reportStreamIteratorCleanupFailure( deps: UiHandlerDeps, error: unknown, ): void { - emitServerDiagnostic( - deps.diagnostics, - serverDiagnosticFromError({ - correlationId: ctx.correlationId ?? "unknown", - operation: "POST /api/desktop/chat/stream", - source: "chat.stream.iterator-cleanup", - error, - redact: (message) => String(deps.redactor(message)), - }), + emitGatewayErrorDiagnostic( + deps, + error, + ctx.correlationId, + "POST /api/desktop/chat/stream", + "chat.stream.iterator-cleanup", ); } @@ -264,15 +262,12 @@ function errorEvent( deps: UiHandlerDeps, correlationId: string | undefined, ): { code: string; message: string; correlationId?: string } { - emitServerDiagnostic( - deps.diagnostics, - serverDiagnosticFromError({ - correlationId: correlationId ?? "unknown", - operation: "POST /api/desktop/chat/stream", - source: "chat.stream", - error, - redact: (message) => String(deps.redactor(message)), - }), + emitGatewayErrorDiagnostic( + deps, + error, + correlationId, + "POST /api/desktop/chat/stream", + "chat.stream", ); const withId = (payload: { code: string; @@ -284,7 +279,9 @@ function errorEvent( } => (correlationId === undefined ? payload : { ...payload, correlationId }); let result; try { - result = desktopChatErrorResult(error, deps); + // emitDiagnostic: false — the diagnostic for this exact error was already emitted above; this + // call is reused purely for its redacted code/message mapping (#154), not as a second response. + result = desktopChatErrorResult(error, deps, correlationId, false); } catch { return withId({ code: "INTERNAL", message: "An unexpected error occurred." }); } @@ -314,7 +311,7 @@ async function streamAndPersist( admitted: AdmittedDesktopChatStream, controller: AbortController, ): Promise { - const { prepared, callStream, userMessage, gatewayTurn, messageCountBeforeTurn } = admitted; + const { prepared, callStream, userMessage, gatewayTurn } = admitted; const { request, modelId, memoryContext } = prepared; const startedAt = Date.now(); const memory = admitted.memory ?? (await resolveMemory(deps, request, memoryContext)); @@ -328,7 +325,10 @@ async function streamAndPersist( modelId, buildGatewayAssembly(deps, request, memory, modelId, gatewayTurn), ); - const stream = callStream({ modelId, messages: assembly.messages }, controller.signal); + const stream = callStream( + { modelId, messages: assembly.messages, logContext: { correlationId: ctx.correlationId } }, + controller.signal, + ); const termination: StreamTermination = { backpressure: false }; const turn = await streamConversation(ctx, deps, stream, controller, termination); if (turn === undefined || requestIsAborted(controller.signal)) { @@ -349,13 +349,28 @@ async function streamAndPersist( failCancelledStreamTurn(ctx, deps, request, true); return; } + finalizeStreamedTurn(ctx, deps, payload, assembly.compaction, admitted, startedAt); +} + +// Split out of streamAndPersist to keep it within the line budget: records the compaction evidence +// for this turn and writes the terminal SSE `done` frame the client is waiting on. +function finalizeStreamedTurn( + ctx: RouteContext, + deps: UiHandlerDeps, + payload: DesktopChatSendResponse, + compaction: ConversationCompactionOutcome["compaction"], + admitted: AdmittedDesktopChatStream, + startedAt: number, +): void { + const { prepared, gatewayTurn, messageCountBeforeTurn } = admitted; recordChatCompaction(deps, { - compaction: assembly.compaction, - request, - modelId, + compaction, + request: prepared.request, + modelId: prepared.modelId, messageCount: messageCountBeforeTurn, startedAt, historyPrefix: gatewayHistoryPrefix(gatewayTurn), + correlationId: ctx.correlationId, }); writeTerminalFrame(ctx, sseMessage({ event: "done", data: payload })); } @@ -371,7 +386,11 @@ export async function handleSendDesktopChatStream( if (activeChatStreams >= maxActiveChatStreams()) { return { status: 429, - body: errorBody("TOO_MANY_STREAMS", "Too many concurrent chat streams; retry buffered."), + body: errorBody( + "TOO_MANY_STREAMS", + "Too many concurrent chat streams; retry buffered.", + ctx.correlationId, + ), }; } activeChatStreams += 1; @@ -397,10 +416,14 @@ type DesktopChatStreamPreparation = | { readonly kind: "outcome"; readonly outcome: HandlerOutcome } | { readonly kind: "replay"; readonly response: DesktopChatSendResponse }; -function streamingUnsupportedOutcome(): RouteResult { +function streamingUnsupportedOutcome(correlationId: string | undefined): RouteResult { return { status: 400, - body: errorBody("STREAMING_UNSUPPORTED", "Streaming is not available for this model."), + body: errorBody( + "STREAMING_UNSUPPORTED", + "Streaming is not available for this model.", + correlationId, + ), }; } @@ -453,6 +476,7 @@ function resolveDesktopChatStreamCall( prepared: PreparedDesktopChatSend, executionAdmission: DesktopChatExecutionAdmission, deps: UiHandlerDeps, + correlationId: string | undefined, ): StreamCall | RouteResult { const invalidExecution = validateDesktopChatProviderBoundary( prepared.modelId, @@ -462,7 +486,7 @@ function resolveDesktopChatStreamCall( if (invalidExecution !== undefined) return invalidExecution; const model = deps.modelPortFactory(prepared.modelId); return model?.callStream === undefined - ? streamingUnsupportedOutcome() + ? streamingUnsupportedOutcome(correlationId) : model.callStream.bind(model); } @@ -520,6 +544,7 @@ interface DesktopChatStreamExecutionPreflight { function preflightDesktopChatStreamExecution( prepared: PreparedDesktopChatSend, deps: UiHandlerDeps, + correlationId: string | undefined, ): DesktopChatStreamExecutionPreflight | RouteResult { const legacyExecutionAdmission = prepared.request.clientTurnId === undefined @@ -539,7 +564,7 @@ function preflightDesktopChatStreamExecution( const probed = legacyExecutionAdmission === undefined ? undefined - : resolveDesktopChatStreamCall(prepared, legacyExecutionAdmission, deps); + : resolveDesktopChatStreamCall(prepared, legacyExecutionAdmission, deps, correlationId); if (probed !== undefined && typeof probed !== "function") return probed; return { legacyExecutionAdmission, @@ -556,6 +581,7 @@ async function prepareDesktopChatProviderStream( legacyCall: StreamCall | undefined, controller: AbortController, admitted: AdmittedTurnHandle, + correlationId: string | undefined, ): Promise | RouteResult> { let memory: AdmittedDesktopChatStream["memory"]; try { @@ -573,13 +599,14 @@ async function prepareDesktopChatProviderStream( if (cancelled) { return { status: 499, body: errorBody("REQUEST_CANCELLED", "Request was cancelled.") }; } - return desktopChatErrorResult(error, deps); + return desktopChatErrorResult(error, deps, correlationId); } if (requestIsAborted(controller.signal)) { settleRejectedDesktopChatTurn(deps, prepared, admitted, "cancelled"); return { status: 499, body: errorBody("REQUEST_CANCELLED", "Request was cancelled.") }; } - const callStream = legacyCall ?? resolveDesktopChatStreamCall(prepared, executionAdmission, deps); + const callStream = + legacyCall ?? resolveDesktopChatStreamCall(prepared, executionAdmission, deps, correlationId); if (typeof callStream === "function") return { callStream, memory }; settleRejectedDesktopChatTurn(deps, prepared, admitted); return callStream; @@ -594,7 +621,7 @@ async function runAdmittedDesktopChatStream( ): Promise { const prepared = validateCurrentDesktopChatSend(start.parsed, deps); if ("status" in prepared) return prepared; - const preflight = preflightDesktopChatStreamExecution(prepared, deps); + const preflight = preflightDesktopChatStreamExecution(prepared, deps, ctx.correlationId); if ("status" in preflight) return preflight; const messageCountBeforeTurn = deps.store.countMessages(prepared.request.chatId); const admission = admitDesktopChatTurn(deps, prepared); @@ -613,6 +640,7 @@ async function runAdmittedDesktopChatStream( preflight.legacyCall, controller, admission, + ctx.correlationId, ); if ("status" in provider) return provider; const gatewayTurn = captureGatewayTurnSnapshot(deps, prepared.request, admission.userMessage); diff --git a/packages/keiko-server/src/coding-context/codingContextRoutes.test.ts b/packages/keiko-server/src/coding-context/codingContextRoutes.test.ts index 685344edcc..aa6635c99e 100644 --- a/packages/keiko-server/src/coding-context/codingContextRoutes.test.ts +++ b/packages/keiko-server/src/coding-context/codingContextRoutes.test.ts @@ -551,4 +551,22 @@ describe("coding context pack route", () => { expect(typeof error.correlationId).toBe("string"); expect(JSON.stringify(result.body)).not.toContain("secret endpoint detail"); }); + + it("threads the request's own correlation id into the upstream-failure response instead of minting one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope here — the failure record and the response body must reuse it, not a disconnected + // randomUUID(). Before the fix the response correlationId never matched ctx.correlationId. + const failingPort: GitHubCodeContextApiPort = { + readJson: () => Promise.reject(new Error("secret endpoint detail must not leak")), + }; + const ctx = { ...ctxFor(packRequest()), correlationId: "req-thread-0123456789" }; + const result = await handleCodingContextPack( + ctx, + depsFor({ codingContextGitHubPort: failingPort }), + ); + + expect(result.status).toBe(502); + const error = bodyOf(result).error as Record; + expect(error.correlationId).toBe("req-thread-0123456789"); + }); }); diff --git a/packages/keiko-server/src/coding-context/codingContextRoutes.ts b/packages/keiko-server/src/coding-context/codingContextRoutes.ts index 182674b190..aaa2acfcf0 100644 --- a/packages/keiko-server/src/coding-context/codingContextRoutes.ts +++ b/packages/keiko-server/src/coding-context/codingContextRoutes.ts @@ -331,7 +331,9 @@ export async function handleCodingContextPack( } catch (error) { // Port failures stay opaque: content-free code + correlation id only. The // connector layer never places endpoints, credentials, or bodies on errors. - const correlationId = randomUUID(); + // Threads the request's own correlation id (ADR-0173 D5 / g12) rather than minting a + // disconnected one — this IS the request whose failure is being reported. + const correlationId = ctx.correlationId ?? randomUUID(); emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ diff --git a/packages/keiko-server/src/coding-sidecar-gateway.test.ts b/packages/keiko-server/src/coding-sidecar-gateway.test.ts index b091201125..f9b8b1544c 100644 --- a/packages/keiko-server/src/coding-sidecar-gateway.test.ts +++ b/packages/keiko-server/src/coding-sidecar-gateway.test.ts @@ -5,6 +5,7 @@ import { describe, expect, it, vi } from "vitest"; import { ProviderError, resolveCodingSafeSidecarGatewayProfile, + type GatewayCallRequest, type GatewayConfig, type GatewayRequest, type GatewayStreamChunk, @@ -13,6 +14,7 @@ import { type NormalizedResponse, } from "@oscharko-dev/keiko-model-gateway"; import { buildRedactor, type UiHandlerDeps } from "./deps.js"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; import { createOpenCodeGatewayReadinessRegistry, @@ -1629,6 +1631,51 @@ describe("coding-sidecar gateway", () => { expect(JSON.stringify(streamRecords)).not.toContain("upstream reset"); }); + // Regression: a mid-stream failure with no request correlation id in scope used to fall back to + // the bare literal `"unknown"` (7 characters), which fails `isValidCorrelationId`'s 8-character + // floor and was silently rewritten by `emitServerDiagnostic`'s sanitizer to the "hostile value" + // marker `"invalid-correlation-id"` — misreporting an honestly-absent id as a malformed one. The + // fallback is now the shape-valid sentinel `UNKNOWN_CORRELATION_ID`, which survives the sanitizer + // unchanged. This test fails against the old bare-`"unknown"` fallback. + it("falls back the stream-failure correlation id to the unknown-id sentinel, never the invalid-id marker", async () => { + const diagnostics = { record: vi.fn<(record: ServerDiagnosticRecord) => void>() }; + const stream = async function* (): AsyncGenerator { + await Promise.resolve(); + yield { type: "delta", token: "partial" }; + throw Object.assign(new Error("upstream reset"), { code: "GATEWAY_TRANSPORT" }); + }; + const response = mockResponse({ captureBody: true }); + const context: RouteContext = { + ...authenticatedContext({ + model: "coding", + stream: true, + messages: [{ role: "user", content: "mid-stream failure, no correlation id" }], + tools: modelVisibleTools(), + }), + res: response.res, + }; + const deps = { + ...runtimeGatewayDeps( + () => ({ ok: true, binding: { runId: "run-stream-failure-no-corr" } }), + undefined, + createOpenCodeGatewayReadinessRegistry(), + (): (() => AsyncIterable) => (): AsyncIterable => + stream(), + ), + diagnostics, + } as UiHandlerDeps; + + const result = await handleCodingSidecarGatewayChatCompletions(context, deps); + + expect(result).toBe(STREAMING); + const streamRecords = diagnostics.record.mock.calls + .map(([entry]) => entry) + .filter((entry) => entry.source === "coding-sidecar-gateway.stream"); + expect(streamRecords).toHaveLength(1); + expect(streamRecords[0]?.correlationId).toBe(UNKNOWN_CORRELATION_ID); + expect(streamRecords[0]?.correlationId).not.toBe("invalid-correlation-id"); + }); + it("counts only each new UTF-8 stream delta instead of re-encoding accumulated output", async () => { const firstToken = "gateway-delta-one-α"; const secondToken = "gateway-delta-two-β"; @@ -2176,6 +2223,39 @@ describe("coding-sidecar gateway", () => { expect(JSON.stringify(result.body)).not.toContain("provider-secret"); }); + // ADR-0173 D5: the buffered chat completion request built for the gateway must carry the HTTP + // request's correlation id in GatewayCallRequest.logContext, so a gateway retry/circuit-breaker + // line for this call joins the same trail as the sidecar request that triggered it. + it("threads the request correlation id into the Gateway double's GatewayCallRequest.logContext", async () => { + const seenRequests: GatewayCallRequest[] = []; + const deps = depsValue( + configValue(provider(), capability()), + ( + _config: GatewayConfig, + modelId: string, + ): ((request: GatewayCallRequest) => Promise) => { + return (request: GatewayCallRequest): Promise => { + seenRequests.push(request); + return Promise.resolve(assistantResponse(modelId)); + }; + }, + ); + const context: RouteContext = { + ...routeContext({ + model: "azure-coding-model", + messages: [{ role: "user", content: "continue" }], + }), + correlationId: "sidecar-corr-logcontext-0001", + }; + + const result = await handleCodingSidecarGatewayChatCompletions(context, deps); + + assertRouteResult(result); + expect(result.status).toBe(200); + expect(seenRequests).toHaveLength(1); + expect(seenRequests[0]?.logContext?.correlationId).toBe("sidecar-corr-logcontext-0001"); + }); + it("returns BAD_REQUEST for malformed OpenAI-compatible tools", async () => { const deps = depsValue(configValue(provider(), capability())); const result = await handleCodingSidecarGatewayChatCompletions( diff --git a/packages/keiko-server/src/coding-sidecar-gateway.ts b/packages/keiko-server/src/coding-sidecar-gateway.ts index 3d9b99b10a..5a76f46fe9 100644 --- a/packages/keiko-server/src/coding-sidecar-gateway.ts +++ b/packages/keiko-server/src/coding-sidecar-gateway.ts @@ -2,6 +2,7 @@ import { randomUUID } from "node:crypto"; import { resolveCodingSafeSidecarGatewayProfile, type Gateway, + type GatewayCallRequest, type GatewayConfig, type GatewayRequest, type GatewayStreamChunk, @@ -24,6 +25,7 @@ import { } from "./deps.js"; import { OPENCODE_RUNTIME_MODEL_ALIAS } from "./coding-runtime/opencodeLaunchProfile.js"; import { hasExactOpenCodeVisibleToolContract } from "./coding-runtime/opencodeToolSchemas.js"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; import { emitServerDiagnostic, serverDiagnosticFromError } from "./diagnostics-log.js"; import { readJsonObject } from "./files.js"; import { STREAMING, errorBody, type RouteContext, type RouteResult } from "./routes.js"; @@ -356,7 +358,8 @@ function buildChatRequest( modelAlias: string, cancellationSignal: AbortSignal, maxOutputTokens: number, -): GatewayRequest { + correlationId: string | undefined, +): GatewayCallRequest { return { modelId: modelAlias, messages: parsed.messages, @@ -365,6 +368,7 @@ function buildChatRequest( ...(parsed.top_p === undefined ? {} : { topP: parsed.top_p }), cancellationSignal, maxOutputTokens, + logContext: { correlationId }, }; } @@ -642,7 +646,7 @@ function emitGatewayFailureDiagnostic( emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: ctx.correlationId ?? "unknown", + correlationId: ctx.correlationId ?? UNKNOWN_CORRELATION_ID, operation: CODING_SIDECAR_GATEWAY_ROUTE, source: "coding-sidecar-gateway.chat", error, @@ -668,7 +672,7 @@ function emitGatewayStreamFailureDiagnostic( emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: ctx.correlationId ?? "unknown", + correlationId: ctx.correlationId ?? UNKNOWN_CORRELATION_ID, operation: CODING_SIDECAR_GATEWAY_ROUTE, source: "coding-sidecar-gateway.stream", error, @@ -742,7 +746,7 @@ function emitGatewayToolContractDiagnostic( if (tools === undefined) code = "CODING_GATEWAY_TOOL_CONTRACT_MISSING"; else if (tools.length === 0) code = "CODING_GATEWAY_TOOL_CONTRACT_EMPTY"; emitServerDiagnostic(deps.diagnostics, { - correlationId: ctx.correlationId ?? "unknown", + correlationId: ctx.correlationId ?? UNKNOWN_CORRELATION_ID, timestamp: new Date(Date.now()).toISOString(), operation: CODING_SIDECAR_GATEWAY_ROUTE, source: "coding-sidecar-gateway.tool-contract", @@ -781,7 +785,7 @@ function noteToolAdoptionGap( if (!hasToolAdoptionGapFingerprint(messages)) return; if (gatewayReadinessRegistry(deps)?.noteAdoptionGapDiagnosed(runId) === false) return; emitServerDiagnostic(deps.diagnostics, { - correlationId: ctx.correlationId ?? "unknown", + correlationId: ctx.correlationId ?? UNKNOWN_CORRELATION_ID, timestamp: new Date(Date.now()).toISOString(), operation: CODING_SIDECAR_GATEWAY_ROUTE, source: "coding-sidecar-gateway.tool-adoption", @@ -914,7 +918,13 @@ async function executeGatewayChat( ): Promise { const { modelAlias, maxOutputTokens, upstreamStreamingSupported } = delivery; const cancellation = gatewayRequestCancellation(ctx, deps, binding.config, modelAlias, runId); - const request = buildChatRequest(parsed, modelAlias, cancellation.signal, maxOutputTokens); + const request = buildChatRequest( + parsed, + modelAlias, + cancellation.signal, + maxOutputTokens, + ctx.correlationId, + ); let bufferedStream: BufferedOpenAiStreamSession | undefined; try { if (parsed.stream && upstreamStreamingSupported) { diff --git a/packages/keiko-server/src/correlation-threading.e2e.test.ts b/packages/keiko-server/src/correlation-threading.e2e.test.ts new file mode 100644 index 0000000000..9d4681cf39 --- /dev/null +++ b/packages/keiko-server/src/correlation-threading.e2e.test.ts @@ -0,0 +1,683 @@ +// Wave 3 ACCEPTANCE TEST (epic #3233, ADR-0173 D5, final-design.md §7) — proves, against the REAL +// `createUiServer` route handler (never a bare handler function call), that ONE correlation id +// threads end to end: from an inbound HTTP/WS header, through the BFF, through the model gateway's +// own activity-log lines, and back onto the response — and that a forced provider failure's +// redacted diagnostic record and the gateway's own retry line carry that id plus the provider- +// detail fields g26 added. Where an assertion cannot pass because the wiring g26/g9 promises is +// not (yet) built, the assertion is left exactly as specified — never weakened — so a fix makes it +// go green rather than a rewrite making it agree with the gap. +// +// Doubles used throughout are either a hand-rolled fake `ModelPort` (a bare object implementing the +// port) or a REAL `Gateway` instance wired with a fake `ProviderAdapter` / `createScriptedGatewayFetch` +// (ADR-0173 §7.3) — never a mocked HTTP layer — so the gateway's own logging code actually runs. + +import { mkdirSync, mkdtempSync, rmSync, realpathSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import type { Server } from "node:http"; +import type { AddressInfo } from "node:net"; +import { afterEach, describe, expect, it } from "vitest"; +import { WebSocket } from "ws"; + +import { GatewayModelPort, type ModelPort } from "@oscharko-dev/keiko-harness"; +import { + Gateway, + createScriptedGatewayClock, + createScriptedGatewayFetch, + type GatewayConfig, + type GatewayReplayScriptEntry, + type ModelProviderConfig, + type NormalizedResponse, + type ProviderAdapter, + type RealtimeNegotiationOutcome, +} from "@oscharko-dev/keiko-model-gateway"; +import { RateLimitError } from "@oscharko-dev/keiko-security/errors/gateway"; + +import { buildRedactor, createRunRegistry, type UiHandlerDeps } from "./index.js"; +import { createInMemoryUiStore, type UiStore } from "./store/index.js"; +import { createUiServer, UI_HOST } from "./server.js"; +import { buildCspHeader } from "./csp.js"; +import { CORRELATION_HEADER } from "./correlation.js"; +import { VOICE_LIVE_TRANSCRIBE_PATH } from "./voice-live-dictation.js"; +import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; +import { + createBufferedServerLogSink, + createServerLogger, + resetServerLogger, + setServerLogger, + type BufferedServerLogSink, + type ServerLogEvent, +} from "./observability/index.js"; +import { closeUiTestServer, startUiTestServer } from "./ui-test-server/_support.js"; + +const OFFER_SDP = + "v=0\r\no=- 1 1 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\nm=audio 9 UDP/TLS/RTP/SAVPF 111\r\na=sendonly\r\n"; + +// ─── Shared config/double builders ────────────────────────────────────────────── + +function bffGatewayConfig(modelId: string, supportsImageInput = false): GatewayConfig { + return { + providers: [ + { + modelId, + baseUrl: "https://bff-provider.example.invalid/v1", + apiKey: "unused-bff-test-key", + timeoutMs: 5_000, + maxRetries: 0, + retryBaseDelayMs: 1, + }, + ], + circuitBreaker: { failureThreshold: 5, cooldownMs: 1_000, halfOpenProbes: 1 }, + capabilities: [ + { + id: modelId, + kind: "chat", + contextWindow: 64_000, + maxOutputTokens: 4_096, + toolCalling: true, + structuredOutput: true, + streaming: true, + supportsImageInput, + supportsDocumentInput: false, + workflowEligible: false, + costClass: "medium", + latencyClass: "standard", + throughputHint: "test", + preferredUseCases: [], + knownLimitations: [], + }, + ], + }; +} + +function gatewayProvider(overrides: Partial = {}): ModelProviderConfig { + return { + modelId: "gw-model", + baseUrl: "https://provider.example.invalid/v1", + apiKey: "gw-test-secret-key-1234567890ab", + timeoutMs: 30_000, + maxRetries: 0, + retryBaseDelayMs: 1, + ...overrides, + }; +} + +function gatewayLevelConfig(providers: readonly ModelProviderConfig[]): GatewayConfig { + return { + providers: [...providers], + circuitBreaker: { failureThreshold: 5, cooldownMs: 1_000, halfOpenProbes: 1 }, + }; +} + +function okResponse(modelId: string, content: string): NormalizedResponse { + return { + modelId, + content, + finishReason: "stop", + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "gw-test-request", + promptTokens: 3, + completionTokens: 2, + latencyMs: 4, + costClass: "low", + }, + }; +} + +function fakeAdapter(impl: ProviderAdapter["call"]): ProviderAdapter { + return { call: impl }; +} + +function okChatBody(content: string): unknown { + return { + choices: [{ message: { role: "assistant", content }, finish_reason: "stop" }], + usage: { prompt_tokens: 3, completion_tokens: 1 }, + }; +} + +function minimalDeps(overrides: Partial): UiHandlerDeps { + return { + config: undefined, + configPresent: false, + evidenceStore: { put: () => "", list: () => [], get: () => undefined, delete: () => undefined }, + env: {}, + redactor: buildRedactor({}), + registry: createRunRegistry(), + modelPortFactory: () => undefined, + store: createInMemoryUiStore(), + ...overrides, + }; +} + +// Seeds exactly ONE prior turn that contributes exactly ONE gateway message: a legacy (no +// client_turn_id) user/assistant pair whose assistant half is the exact legacy-empty-response +// placeholder `usableGatewayMessages` (conversation-gateway.ts) drops via +// `isLegacyEmptyAssistantPlaceholder`. The store's scan layer (messages.ts's +// `scanLegacyGatewayRow`) still counts the pair as ONE eligible history unit, but only the user +// half survives into the assembled prompt — giving a real, production-path-derived odd total +// (system + priorUser + currentUser = 3) instead of guessing at internal counting rules. +function seedLegacyPriorTurn(store: UiStore, chatId: string): void { + const seededAt = Date.now() - 60_000; + const base = { + chatId, + runId: undefined, + workflowId: undefined, + workflowStatus: undefined, + shortResult: undefined, + taskType: undefined, + }; + store.createMessage({ ...base, role: "user", content: "Earlier question", timestamp: seededAt }); + store.createMessage({ + ...base, + role: "assistant", + content: "The model returned an empty response.", + timestamp: seededAt + 1_000, + }); +} + +// ─── Server lifecycle ─────────────────────────────────────────────────────────── + +let activeServer: Server | undefined; +const tempDirs: string[] = []; + +afterEach(async () => { + resetServerLogger(); + if (activeServer !== undefined) { + await closeUiTestServer(activeServer); + activeServer = undefined; + } + for (const dir of tempDirs.splice(0)) { + rmSync(dir, { recursive: true, force: true }); + } +}); + +function tempProjectDir(prefix: string): string { + const root = mkdtempSync(join(realpathSync(tmpdir()), prefix)); + tempDirs.push(root); + const projectPath = join(root, "repo"); + mkdirSync(projectPath); + return projectPath; +} + +async function boot( + handlerDeps: UiHandlerDeps, + activityLog?: BufferedServerLogSink, +): Promise { + const staticRoot = mkdtempSync(join(realpathSync(tmpdir()), "keiko-correlation-static-")); + tempDirs.push(staticRoot); + const started = await startUiTestServer({ + staticRoot, + csp: buildCspHeader([]), + handlerDeps, + ...(activityLog === undefined ? {} : { activityLog }), + }); + activeServer = started.server; + return started.port; +} + +function baseUrl(port: number): string { + return `http://${UI_HOST}:${String(port)}`; +} + +function jsonHeaders(correlationId: string): Record { + return { + "Content-Type": "application/json", + "X-Keiko-CSRF": "1", + [CORRELATION_HEADER]: correlationId, + }; +} + +// `startUiTestServer` (used by `boot` above) binds an ephemeral port by mutating its +// `UiServerDeps.port` field AFTER `createUiServer` has already run — fine for the HTTP path, +// which re-reads `deps.port` on every request, but NOT for the voice planes: `createUiServer` +// captures `deps.port` BY VALUE, once, into `createVoicePlanes(deps.port, handlerDeps)` at +// construction time, so a WS upgrade's own `isAllowedHost` check would keep comparing against the +// port-0 snapshot forever and hard-reject every upgrade with a 404. Mirrors +// voice-control-ws.test.ts's own `boot()`: probe an ephemeral port, close that throwaway server, +// then construct the REAL server with the correct port already baked in. +async function bootForVoice(handlerDeps: UiHandlerDeps): Promise { + const staticRoot = mkdtempSync(join(realpathSync(tmpdir()), "keiko-correlation-voice-static-")); + tempDirs.push(staticRoot); + const csp = buildCspHeader([]); + const probe = createUiServer({ staticRoot, csp, port: 0, handlerDeps }); + const port = await new Promise((resolve) => { + probe.listen(0, UI_HOST, () => { + resolve((probe.address() as AddressInfo).port); + }); + }); + await new Promise((resolve) => { + probe.close(() => { + resolve(); + }); + }); + const listening = createUiServer({ staticRoot, csp, port, handlerDeps }); + activeServer = listening; + await new Promise((resolve) => { + listening.listen(port, UI_HOST, resolve); + }); + return port; +} + +// Polls the buffered sink instead of assuming synchronous availability: `gateway.*`/`chat.turn.*` +// lines are written before the response leaves, but the `http`/`request` line is written from +// `res.on("close")`, which can fire a tick after `fetch()`'s promise settles (AGENTS.md §9 — await +// a condition instead of sleeping). +async function waitForEvent( + sink: BufferedServerLogSink, + predicate: (event: ServerLogEvent) => boolean, + timeoutMs = 2_000, +): Promise { + const deadline = Date.now() + timeoutMs; + for (;;) { + const found = sink.events.find(predicate); + if (found !== undefined) { + return found; + } + if (Date.now() > deadline) { + throw new Error("timed out waiting for the expected activity log event"); + } + await new Promise((resolve) => setTimeout(resolve, 10)); + } +} + +// ─── WS helpers (mirrors voice-control-ws.test.ts's proven `connect`/`expectOpen`) ───────────── + +interface WsClient { + readonly opened: boolean; + readonly ws?: WebSocket; + readonly next?: () => Promise>; +} + +function connectWs( + port: number, + options: { readonly path: string; readonly headers?: Record }, +): Promise { + const headers: Record = { + Origin: `http://${UI_HOST}:${String(port)}`, + ...(options.headers ?? {}), + }; + return new Promise((resolve) => { + const ws = new WebSocket(`ws://${UI_HOST}:${String(port)}${options.path}`, { headers }); + const queue: Record[] = []; + const waiters: ((message: Record) => void)[] = []; + ws.on("message", (data: Buffer) => { + const message = JSON.parse(data.toString("utf8")) as Record; + const waiter = waiters.shift(); + if (waiter !== undefined) { + waiter(message); + } else { + queue.push(message); + } + }); + const next = (): Promise> => { + const queued = queue.shift(); + if (queued !== undefined) { + return Promise.resolve(queued); + } + return new Promise((resolveMessage) => waiters.push(resolveMessage)); + }; + ws.once("open", () => { + resolve({ opened: true, ws, next }); + }); + ws.once("unexpected-response", () => { + ws.terminate(); + resolve({ opened: false }); + }); + ws.once("error", () => { + resolve({ opened: false }); + }); + }); +} + +interface OpenWsClient { + readonly ws: WebSocket; + readonly next: () => Promise>; +} + +function expectOpen(client: WsClient): OpenWsClient { + if (!client.opened || client.ws === undefined || client.next === undefined) { + throw new Error("expected the WebSocket upgrade to be accepted"); + } + return { ws: client.ws, next: client.next }; +} + +function voiceRealtimeConfig(): GatewayConfig { + return { + providers: [ + { + modelId: "keiko-realtime-e2e", + baseUrl: "https://realtime.example.invalid", + apiKey: "rt-e2e-secret-token-1234567890", + timeoutMs: 1_000, + maxRetries: 0, + retryBaseDelayMs: 10, + }, + ], + circuitBreaker: { failureThreshold: 5, cooldownMs: 1_000, halfOpenProbes: 1 }, + capabilities: [ + { + id: "keiko-realtime-e2e", + kind: "voice", + contextWindow: 0, + maxOutputTokens: 0, + toolCalling: false, + structuredOutput: false, + streaming: false, + supportsImageInput: false, + supportsDocumentInput: false, + supportsSpeechInput: true, + supportsRealtimeVoice: true, + realtimeTranscriptionModel: "configured-realtime-transcription", + voiceProviderLocality: "azure-foundry", + workflowEligible: false, + costClass: "low", + latencyClass: "fast", + throughputHint: "azure foundry realtime", + preferredUseCases: ["Conversation"], + knownLimitations: [], + }, + ], + }; +} + +function liveSessionCreate(): string { + return JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-e2e-1", + seq: 0, + direction: "client-to-host", + kind: "session.create", + idempotencyKey: "idem-e2e-1", + requestedProfile: "full-realtime", + negotiationMode: "proxied-sdp", + }); +} + +function offerFrame(seq: number): string { + return JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-e2e-1", + seq, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }); +} + +// ─── (1) desktop chat turn — one correlation id end to end (ADR-0173 D5 §7.1, §7.4) ───────────── + +describe("desktop chat turn — one correlation id end to end", () => { + it("threads a client-supplied X-Keiko-Correlation-Id onto the http line, gateway.chat.completed, and the response header", async () => { + const sink = createBufferedServerLogSink(); + setServerLogger(createServerLogger({ sink, level: "info" })); + + const modelId = "correlation-thread-model"; + const projectPath = tempProjectDir("keiko-correlation-thread-"); + const store = createInMemoryUiStore(); + store.createProject(projectPath, "repo"); + const chat = store.createChat(projectPath, "Thread", modelId); + + const gateway = new Gateway(gatewayLevelConfig([gatewayProvider({ modelId })]), { + adapter: fakeAdapter(() => Promise.resolve(okResponse(modelId, "hello there"))), + clock: createScriptedGatewayClock(), + log: sink, + }); + const modelPort: ModelPort = new GatewayModelPort(gateway); + + const port = await boot( + minimalDeps({ + config: bffGatewayConfig(modelId), + configPresent: true, + store, + modelPortFactory: () => modelPort, + }), + sink, + ); + + const correlationId = "e2e-correlation-thread-0001"; + const res = await fetch(`${baseUrl(port)}/api/desktop/chat`, { + method: "POST", + headers: jsonHeaders(correlationId), + body: JSON.stringify({ chatId: chat.id, projectPath, modelId, content: "Hello" }), + }); + + expect(res.status).toBe(200); + expect(res.headers.get("x-keiko-correlation-id")).toBe(correlationId); + + const httpLine = await waitForEvent( + sink, + (event) => + event.category === "http" && + event.op === "request" && + event.correlationId === correlationId, + ); + expect(httpLine.op).toBe("request"); + + const completed = await waitForEvent(sink, (event) => event.op === "gateway.chat.completed"); + expect(completed.correlationId).toBe(correlationId); + }); +}); + +// ─── (2a) forced RateLimitError — diagnostic record field wiring (ADR-0173 D5 g26) ────────────── + +describe("forced RateLimitError — diagnostic record field wiring", () => { + it("keeps the request's correlation id on the diagnostic record and carries retryAfterMs/httpStatus", async () => { + const modelId = "rate-limit-diagnostic-model"; + const projectPath = tempProjectDir("keiko-correlation-ratelimit-"); + const store = createInMemoryUiStore(); + store.createProject(projectPath, "repo"); + const chat = store.createChat(projectPath, "Rate limited", modelId); + + const diagnostics: ServerDiagnosticRecord[] = []; + const rateLimitedModel: ModelPort = { + call: () => Promise.reject(new RateLimitError("provider rate limited", 4_000)), + }; + + const port = await boot( + minimalDeps({ + config: bffGatewayConfig(modelId), + configPresent: true, + store, + modelPortFactory: () => rateLimitedModel, + diagnostics: { record: (record): void => void diagnostics.push(record) }, + }), + ); + + const correlationId = "e2e-correlation-ratelimit-0001"; + const res = await fetch(`${baseUrl(port)}/api/desktop/chat`, { + method: "POST", + headers: jsonHeaders(correlationId), + body: JSON.stringify({ + chatId: chat.id, + projectPath, + modelId, + content: "Trigger a rate limit", + }), + }); + + expect(res.status).toBe(503); + expect(diagnostics).toHaveLength(1); + const [record] = diagnostics; + expect(record).toBeDefined(); + expect(record?.correlationId).toBe(correlationId); + + // g26 (final-design.md §2, ServerDiagnosticRecord v2): httpStatus/retryAfterMs are derived + // through `describeError` → `providerErrorDetail()` (keiko-model-gateway/resilience.ts), the + // SAME instanceof-based derivation `gateway.retry.*` lines use. `httpStatus` is read off BOTH + // `ProviderError` and `RateLimitError`: a rate-limited call is always HTTP 429 by definition, + // so this diagnostic record carries httpStatus=429 alongside retryAfterMs — a replay-script + // consumer (`GatewayReplayAttempt.httpStatus`) never has to infer the status from + // `errorKind === GATEWAY_RATE_LIMIT`. + const detail = record as unknown as { + readonly httpStatus?: number; + readonly retryAfterMs?: number; + }; + expect(detail.retryAfterMs).toBe(4_000); + expect(detail.httpStatus).toBe(429); + }); +}); + +// ─── (2b) scripted 429-then-200 — gateway.retry.scheduled field wiring (ADR-0173 D5 g26, §7.3) ── + +describe("scripted 429-then-200 retry — gateway.retry.scheduled field wiring", () => { + it("recovers via the real retry path and carries the request's correlation id + httpStatus=429 onto gateway.retry.scheduled", async () => { + const modelId = "retry-recovery-model"; + const projectPath = tempProjectDir("keiko-correlation-retry-"); + const store = createInMemoryUiStore(); + store.createProject(projectPath, "repo"); + const chat = store.createChat(projectPath, "Retry recovery", modelId); + + const sharedClock = createScriptedGatewayClock(); + const script: readonly GatewayReplayScriptEntry[] = [ + { + status: 429, + headers: { "retry-after": "1" }, + bodyJson: { error: { message: "slow down" } }, + latencyMs: 0, + }, + { status: 200, bodyJson: okChatBody("recovered"), latencyMs: 0 }, + ]; + const fetchImpl = createScriptedGatewayFetch(script, sharedClock); + const sink = createBufferedServerLogSink(); + const gateway = new Gateway( + gatewayLevelConfig([gatewayProvider({ modelId, maxRetries: 1, retryBaseDelayMs: 1 })]), + { clock: sharedClock, fetchImpl, log: sink, random: (): number => 0.5 }, + ); + const modelPort: ModelPort = new GatewayModelPort(gateway); + + const port = await boot( + minimalDeps({ + config: bffGatewayConfig(modelId), + configPresent: true, + store, + modelPortFactory: () => modelPort, + }), + ); + + const correlationId = "e2e-correlation-retry-0001"; + const res = await fetch(`${baseUrl(port)}/api/desktop/chat`, { + method: "POST", + headers: jsonHeaders(correlationId), + body: JSON.stringify({ chatId: chat.id, projectPath, modelId, content: "Please recover" }), + }); + + expect(res.status).toBe(200); + const scheduled = await waitForEvent(sink, (event) => event.op === "gateway.retry.scheduled"); + expect(scheduled.correlationId).toBe(correlationId); + // g26: resilience.ts's providerErrorDetail() reads httpStatus off a RateLimitError instance + // too, deliberately — the 429 response mapped here to RateLimitError + // (packages/keiko-model-gateway/src/openai-adapter.ts, response.status === 429) is always HTTP + // 429 by definition, so the scheduled retry line carries httpStatus=429 alongside the + // provider-supplied retryAfterMs, instead of forcing a consumer to infer the status from + // errorKind === GATEWAY_RATE_LIMIT. + expect(scheduled.extra?.httpStatus).toBe(429); + expect(scheduled.extra?.retryAfterMs).toBe(1_000); + }); +}); + +// ─── (3) chat.turn.started shape fields (ADR-0173 D5 g9) ──────────────────────────────────────── + +describe("chat.turn.started shape fields — 3-message turn with one image attachment", () => { + it("logs messageCount=3, imageAttachmentCount=1, keyed to the request correlation id", async () => { + const sink = createBufferedServerLogSink(); + setServerLogger(createServerLogger({ sink, level: "info" })); + + const modelId = "turn-shape-image-model"; + const projectPath = tempProjectDir("keiko-correlation-turnshape-"); + const store = createInMemoryUiStore(); + store.createProject(projectPath, "repo"); + const chat = store.createChat(projectPath, "Turn shape", modelId); + seedLegacyPriorTurn(store, chat.id); + + const gateway = new Gateway(gatewayLevelConfig([gatewayProvider({ modelId })]), { + adapter: fakeAdapter(() => Promise.resolve(okResponse(modelId, "looked at it"))), + clock: createScriptedGatewayClock(), + log: sink, + }); + const modelPort: ModelPort = new GatewayModelPort(gateway); + + const port = await boot( + minimalDeps({ + config: bffGatewayConfig(modelId, true), + configPresent: true, + store, + modelPortFactory: () => modelPort, + }), + sink, + ); + + const correlationId = "e2e-correlation-turnshape-0001"; + // `chat.turn.started` is logged from the BASE assembly, before image content parts are + // spliced in (chat-handlers.ts's own comment on `logChatTurnStarted`'s call site) — so it is + // written even though this send goes on to be refused at the UNRELATED image-delivery- + // authority gate a few lines later (no `attachmentAuthority`/`attachmentIntent` supplied here; + // that gate is a distinct security check this test does not exercise). The response status is + // therefore deliberately not asserted here — only the shape fields the gateway op carries. + await fetch(`${baseUrl(port)}/api/desktop/chat`, { + method: "POST", + headers: jsonHeaders(correlationId), + body: JSON.stringify({ + chatId: chat.id, + projectPath, + modelId, + content: "Look at this", + attachments: [{ kind: "image", mimeType: "image/png", sizeBytes: 1_024 }], + }), + }); + + const started = await waitForEvent( + sink, + (event) => event.op === "chat.turn.started" && event.correlationId === correlationId, + ); + expect(started.category).toBe("gateway"); + expect(started.extra).toMatchObject({ messageCount: 3, imageAttachmentCount: 1 }); + }); +}); + +// ─── (4) voice live-dictation WS upgrade — one correlation id across two diagnostics (g15) ────── + +describe("voice live-dictation WS upgrade — one correlation id across two diagnostics", () => { + it("carries the client-supplied X-Keiko-Correlation-Id onto two successive negotiation-failure diagnostics", async () => { + const diagnostics: ServerDiagnosticRecord[] = []; + const port = await bootForVoice( + minimalDeps({ + config: voiceRealtimeConfig(), + configPresent: true, + diagnostics: { record: (record): void => void diagnostics.push(record) }, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }), + ); + + const correlationId = "e2e-correlation-voice-0001"; + const { ws: socket, next } = expectOpen( + await connectWs(port, { + path: VOICE_LIVE_TRANSCRIBE_PATH, + headers: { [CORRELATION_HEADER]: correlationId }, + }), + ); + + socket.send(liveSessionCreate()); + await next(); // session.created + await next(); // capability.offer + + socket.send(offerFrame(1)); + await next(); // media.track.state negotiating + const firstFailure = await next(); + await next(); // media.track.state ended + + socket.send(offerFrame(2)); + await next(); // media.track.state negotiating + const secondFailure = await next(); + await next(); // media.track.state ended + + expect(firstFailure.correlationId).toBe(correlationId); + expect(secondFailure.correlationId).toBe(correlationId); + expect(diagnostics).toHaveLength(2); + expect(diagnostics[0]?.correlationId).toBe(correlationId); + expect(diagnostics[1]?.correlationId).toBe(correlationId); + socket.close(); + }); +}); diff --git a/packages/keiko-server/src/correlation.ts b/packages/keiko-server/src/correlation.ts index 5ee8ea2f6d..593429f2a9 100644 --- a/packages/keiko-server/src/correlation.ts +++ b/packages/keiko-server/src/correlation.ts @@ -29,6 +29,16 @@ export function newCorrelationId(): string { return randomUUID(); } +// A fixed, shape-valid stand-in for "no correlation id was known at this call site" — as opposed to +// a hostile or malformed one (see `diagnostics-log.ts`'s `INVALID_CORRELATION_ID_MARKER`, which +// covers that case). A `ServerDiagnosticRecord.correlationId` is required, so a caller with none in +// scope needs SOME value rather than an omission; several call sites used the bare literal +// `"unknown"` for this, but at 7 characters it always fails `isValidCorrelationId` itself and was +// silently rewritten to the sanitizer's own marker — making an honestly-absent id indistinguishable +// from a hostile one. This constant already satisfies the shape, so it survives the sanitizer and +// keeps its own distinct meaning. +export const UNKNOWN_CORRELATION_ID = "unknown-correlation-id"; + // Resolves the correlation id for a request: reuse a well-formed client-supplied id (UI -> server // continuity) or mint a fresh one. Never throws. export function resolveCorrelationId(req: IncomingMessage): string { diff --git a/packages/keiko-server/src/desktop-chat-handlers.test.ts b/packages/keiko-server/src/desktop-chat-handlers.test.ts index e7877d0236..c67536516c 100644 --- a/packages/keiko-server/src/desktop-chat-handlers.test.ts +++ b/packages/keiko-server/src/desktop-chat-handlers.test.ts @@ -14,8 +14,8 @@ import { createInMemoryUiStore, type UiStore } from "./store/index.js"; import { startUiTestServer } from "./ui-test-server/_support.js"; import type { ModelPort } from "@oscharko-dev/keiko-harness"; import type { + GatewayCallRequest, GatewayConfig, - GatewayRequest, NormalizedResponse, } from "@oscharko-dev/keiko-model-gateway"; import { createMemoryVault, type MemoryVaultStore } from "@oscharko-dev/keiko-memory-vault"; @@ -41,7 +41,7 @@ let staticRoot: string; let tmp: string; let projectDir: string; let store: UiStore; -let seenRequests: GatewayRequest[]; +let seenRequests: GatewayCallRequest[]; function fakeModel(content: string): ModelPort { return { @@ -678,6 +678,35 @@ describe("desktop chat routes", () => { expect(persistedRoles).toEqual(expect.arrayContaining(["user", "assistant"])); }); + // ADR-0173 D5 (BFF -> gateway correlation threading): the client-supplied request correlation id + // must reach the Gateway double's GatewayCallRequest.logContext, not just the response header, so + // a gateway retry/circuit-breaker line for this call joins the same trail as the HTTP request. + it("threads the request correlation id into the model gateway call's logContext", async () => { + const createRes = await fetch(`${base()}/api/desktop/chats`, { + method: "POST", + headers: POST_JSON_HEADERS, + body: JSON.stringify({ projectPath: projectDir, modelId: CHAT_MODEL }), + }); + const created = (await createRes.json()) as { chat: { id: string } }; + const correlationId = "test-correlation-id-send-0001"; + + const sendRes = await fetch(`${base()}/api/desktop/chat`, { + method: "POST", + headers: { ...POST_JSON_HEADERS, "X-Keiko-Correlation-Id": correlationId }, + body: JSON.stringify({ + chatId: created.chat.id, + projectPath: projectDir, + modelId: CHAT_MODEL, + content: "Say hello with correlation", + }), + }); + + expect(sendRes.status).toBe(200); + expect(sendRes.headers.get("X-Keiko-Correlation-Id")).toBe(correlationId); + expect(seenRequests).toHaveLength(1); + expect(seenRequests[0]?.logContext?.correlationId).toBe(correlationId); + }); + it("admits a long canonical final atomically and rejects content beyond the UTF-8 hard cap", async () => { const createRes = await fetch(`${base()}/api/desktop/chats`, { method: "POST", @@ -1365,6 +1394,52 @@ describe("desktop chat routes", () => { expect(store.listMessages(chat.id).map((message) => message.id)).toContain(assistant.id); }); + // ADR-0173 D5: the regenerate path builds a fresh model.call site distinct from the send path + // (chat-handlers.ts persistRegeneratedChatTurn) — it must thread the request correlation id too. + it("threads the request correlation id into the regenerate model gateway call", async () => { + await restartWithDeps(deps(fakeModel("regenerated with correlation"))); + const chat = store.createChat(projectDir, "regen correlation", CHAT_MODEL); + store.createMessage({ + chatId: chat.id, + role: "user", + content: "original question", + timestamp: 1, + runId: undefined, + workflowId: undefined, + workflowStatus: undefined, + shortResult: undefined, + taskType: undefined, + }); + const assistant = store.createMessage({ + chatId: chat.id, + role: "assistant", + content: "stale answer", + timestamp: 2, + runId: undefined, + workflowId: undefined, + workflowStatus: undefined, + shortResult: undefined, + taskType: undefined, + }); + const correlationId = "test-correlation-id-regen-0001"; + + const res = await fetch(`${base()}/api/desktop/chat/regenerate`, { + method: "POST", + headers: { ...POST_JSON_HEADERS, "X-Keiko-Correlation-Id": correlationId }, + body: JSON.stringify({ + chatId: chat.id, + projectPath: projectDir, + modelId: CHAT_MODEL, + assistantMessageId: assistant.id, + }), + }); + + expect(res.status).toBe(200); + expect(res.headers.get("X-Keiko-Correlation-Id")).toBe(correlationId); + expect(seenRequests).toHaveLength(1); + expect(seenRequests[0]?.logContext?.correlationId).toBe(correlationId); + }); + it("rejects regeneration of a closed chat without model work or message mutation", async () => { const chat = store.createChat(projectDir, "closed regeneration", CHAT_MODEL); store.createMessage({ diff --git a/packages/keiko-server/src/editor/completionRoutes.ts b/packages/keiko-server/src/editor/completionRoutes.ts index b8d8066485..6d7691efee 100644 --- a/packages/keiko-server/src/editor/completionRoutes.ts +++ b/packages/keiko-server/src/editor/completionRoutes.ts @@ -99,7 +99,10 @@ export interface EditorCompletionRouteOptions { } // Default chat seam: route the elected model through the Model Gateway, server-side only. -function defaultChatFactoryFor(deps: UiHandlerDeps): CompletionChatFactory { +function defaultChatFactoryFor( + deps: UiHandlerDeps, + correlationId: string | undefined, +): CompletionChatFactory { return (_config, modelId): ModelChatFn => { const gateway = currentGateway(deps); if (gateway === undefined) throw new TypeError("Model gateway is unavailable."); @@ -111,6 +114,7 @@ function defaultChatFactoryFor(deps: UiHandlerDeps): CompletionChatFactory { { role: "user", content: chatRequest.user }, ], cancellationSignal: chatSignal, + logContext: { correlationId }, }); return { content: response.content, usage: response.usage }; }; @@ -649,7 +653,7 @@ export async function handleEditorCompletion( root.realRoot, signal, deps, - options.chatFactory ?? defaultChatFactoryFor(deps), + options.chatFactory ?? defaultChatFactoryFor(deps, ctx.correlationId), options.tokenBudget ?? sharedEditorModelTokenBudget, options.now ?? Date.now, ); diff --git a/packages/keiko-server/src/editor/inlineCompletionRoutes.ts b/packages/keiko-server/src/editor/inlineCompletionRoutes.ts index cd77c93765..976f93cdd8 100644 --- a/packages/keiko-server/src/editor/inlineCompletionRoutes.ts +++ b/packages/keiko-server/src/editor/inlineCompletionRoutes.ts @@ -111,7 +111,10 @@ export interface EditorInlineCompletionRouteOptions { const sharedRateLimiter: InlineCompletionRateLimiter = createInlineCompletionRateLimiter(); // Default chat seam: route the elected model through the Model Gateway, server-side only. -function defaultChatFactoryFor(deps: UiHandlerDeps): InlineCompletionChatFactory { +function defaultChatFactoryFor( + deps: UiHandlerDeps, + correlationId: string | undefined, +): InlineCompletionChatFactory { return (_config, modelId): ModelChatFn => { const gateway = currentGateway(deps); if (gateway === undefined) throw new TypeError("Model gateway is unavailable."); @@ -123,6 +126,7 @@ function defaultChatFactoryFor(deps: UiHandlerDeps): InlineCompletionChatFactory { role: "user", content: chatRequest.user }, ], cancellationSignal: chatSignal, + logContext: { correlationId }, }); return { content: response.content, usage: response.usage }; }; @@ -504,7 +508,7 @@ async function runInlineModelTier( deps, selection, modelId, - chatFactory: options.chatFactory ?? defaultChatFactoryFor(deps), + chatFactory: options.chatFactory ?? defaultChatFactoryFor(deps, correlationId), config, nowMs: now(), tokenBudget, diff --git a/packages/keiko-server/src/editor/localHistory/localHistoryCapture.test.ts b/packages/keiko-server/src/editor/localHistory/localHistoryCapture.test.ts index 0805c4f0a3..87502d4116 100644 --- a/packages/keiko-server/src/editor/localHistory/localHistoryCapture.test.ts +++ b/packages/keiko-server/src/editor/localHistory/localHistoryCapture.test.ts @@ -109,4 +109,34 @@ describe("captureEditorLocalHistorySafely", () => { expect(JSON.stringify(diagnostics)).not.toContain(secretValue); expect(JSON.stringify(diagnostics)).not.toContain(secretContent); }); + + // ADR-0173 D5 / g12: a capture failure that happens inside a request must carry THAT request's + // own correlation id, not a disconnected `local-history-` mint, so an operator can join it + // back to the rest of the request's trail. Before the fix, `correlationId` threading did not + // exist on this function at all, so this assertion fails against the pre-fix signature (the + // extra field was silently ignored and a fresh `local-history-` id was always minted instead). + it("threads the caller's own correlation id into a capture failure instead of minting one", () => { + const diagnostics: ServerDiagnosticRecord[] = []; + const secretValue = "wJalrXUtnFEMI/K7MDENG/bPxRfiCYEXAMPLEKEY"; + const secretContent = `AWS_SECRET_ACCESS_KEY=${secretValue}\n`; + const requestCorrelationId = "req-abc12345"; + + const result = captureEditorLocalHistorySafely({ + deps: deps(diagnostics), + realRoot: root, + relativePath: "src/app.ts", + absolutePath: join(root, "src", "app.ts"), + content: secretContent, + origin: "user-save", + nowMs: 3_000, + correlationId: requestCorrelationId, + }); + + expect(result).toMatchObject({ + status: "suppressed", + correlationId: requestCorrelationId, + }); + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]?.correlationId).toBe(requestCorrelationId); + }); }); diff --git a/packages/keiko-server/src/editor/localHistory/localHistoryCapture.ts b/packages/keiko-server/src/editor/localHistory/localHistoryCapture.ts index 1cffa45681..814d602175 100644 --- a/packages/keiko-server/src/editor/localHistory/localHistoryCapture.ts +++ b/packages/keiko-server/src/editor/localHistory/localHistoryCapture.ts @@ -66,8 +66,12 @@ export function emitEditorLocalHistoryCaptureFailure( origin: EditorLocalHistoryOrigin, error: unknown, nowMs = Date.now(), + // Threads the request's own correlation id (ADR-0173 D5 / g12) when the caller has one in + // scope, so this failure — and the client-visible protection payload it returns the id on — + // joins the SAME id as the rest of the request's trail instead of a disconnected mint. + requestCorrelationId?: string, ): string { - const correlationId = `local-history-${randomUUID()}`; + const correlationId = requestCorrelationId ?? `local-history-${randomUUID()}`; emitServerDiagnostic(deps.diagnostics, { correlationId, timestamp: new Date(nowMs).toISOString(), @@ -123,6 +127,8 @@ export function captureEditorLocalHistorySafely(input: { readonly content: string; readonly origin: EditorLocalHistoryOrigin; readonly nowMs?: number | undefined; + // The request's own correlation id (ADR-0173 D5 / g12), when the caller has one in scope. + readonly correlationId?: string | undefined; }): EditorLocalHistoryCaptureProtection { if (input.deps.editorLocalHistoryStore === undefined) { const error = new EditorLocalHistoryError( @@ -135,6 +141,7 @@ export function captureEditorLocalHistorySafely(input: { input.origin, error, input.nowMs, + input.correlationId, ); return degradedProtection(error, correlationId); } @@ -155,6 +162,7 @@ export function captureEditorLocalHistorySafely(input: { input.origin, error, input.nowMs, + input.correlationId, ); return protectionForCaptureFailure(error, correlationId); } diff --git a/packages/keiko-server/src/editor/patchApplyRoutes.test.ts b/packages/keiko-server/src/editor/patchApplyRoutes.test.ts index 8adfef0c86..59805b2a48 100644 --- a/packages/keiko-server/src/editor/patchApplyRoutes.test.ts +++ b/packages/keiko-server/src/editor/patchApplyRoutes.test.ts @@ -281,6 +281,36 @@ describe("POST /api/editor/patch-apply — explicit decision (AC1)", () => { expect(evidenceStore.list()).toHaveLength(2); }); + it("threads the request's own correlation id into a local-history capture failure instead of minting one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope in handleEditorPatchApply — a local-history capture failure during the apply must + // reuse it via ApplyContext.correlationId, not a disconnected `local-history-` mint. + const diagnostics: { correlationId?: unknown }[] = []; + const throwingHistoryStore = { + capture: (): never => { + throw new Error("history capture backend unavailable"); + }, + } as unknown as EditorLocalHistoryStore; + const ctx = { ...postContext(body()), correlationId: "req-patch-apply-thread-01" }; + + const result = await handleEditorPatchApply( + ctx, + { + ...deps({ env: ENABLED, editorLocalHistoryStore: throwingHistoryStore }), + diagnostics: { + record: (record: { correlationId?: unknown }): void => { + diagnostics.push(record); + }, + }, + }, + options(), + ); + + expect(wire(result).status).toBe("applied"); + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]?.correlationId).toBe("req-patch-apply-thread-01"); + }); + it("records a reject decision and mutates nothing", async () => { const result = await handleEditorPatchApply( postContext(body({ decision: "reject" })), diff --git a/packages/keiko-server/src/editor/patchApplyRoutes.ts b/packages/keiko-server/src/editor/patchApplyRoutes.ts index 289f0342ae..99eefa5261 100644 --- a/packages/keiko-server/src/editor/patchApplyRoutes.ts +++ b/packages/keiko-server/src/editor/patchApplyRoutes.ts @@ -214,7 +214,13 @@ function captureAppliedHistory(ctx: ApplyContext, result: PatchApplyResult): voi try { content = readFileSync(absolutePath, "utf8"); } catch (error) { - emitEditorLocalHistoryCaptureFailure(ctx.deps, "agent-apply", error, ctx.nowMs); + emitEditorLocalHistoryCaptureFailure( + ctx.deps, + "agent-apply", + error, + ctx.nowMs, + ctx.correlationId, + ); continue; } captureEditorLocalHistorySafely({ @@ -225,6 +231,7 @@ function captureAppliedHistory(ctx: ApplyContext, result: PatchApplyResult): voi content, origin: "agent-apply", nowMs: ctx.nowMs, + correlationId: ctx.correlationId, }); } } @@ -255,6 +262,9 @@ interface ApplyContext { readonly signal: AbortSignal; readonly nowMs: number; readonly options: EditorPatchApplyRouteOptions; + // The request's own correlation id (ADR-0173 D5 / g12), threaded down so a local-history + // capture failure joins the SAME id as the rest of this request's trail. + readonly correlationId: string | undefined; } async function runVerificationPhase( @@ -493,6 +503,7 @@ export async function handleEditorPatchApply( signal, nowMs, options, + correlationId: ctx.correlationId, }); return { status: 200, body: deps.redactor(response) }; }); diff --git a/packages/keiko-server/src/files.test.ts b/packages/keiko-server/src/files.test.ts index 0efe76f87b..f80c1fbad4 100644 --- a/packages/keiko-server/src/files.test.ts +++ b/packages/keiko-server/src/files.test.ts @@ -1020,6 +1020,51 @@ describe("desktop files browser", () => { expect(JSON.stringify(diagnostics)).not.toContain("saved despite history failure"); }); + it("threads the request's own correlation id into a local-history capture failure instead of minting one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope in writeFilesContentRoute — the capture failure must reuse it, not a disconnected + // one. Before the fix the diagnostic and response always carried a fresh mint regardless of + // ctx.correlationId. + const diagnostics: ServerDiagnosticRecord[] = []; + const failingVault: LocalSecretVault = { + get: () => undefined, + set: (): never => { + throw new Error("capture-secret-marker-2"); + }, + replaceAll: () => undefined, + delete: () => undefined, + has: () => false, + list: () => [], + }; + const failingHistory = createEditorLocalHistoryStore({ + stateDir: join(root, ".history-test-state-correlation"), + env: {}, + vaultFactory: () => failingVault, + }); + const ctx = { + ...patchContentContext({ root, path: "src/app.ts", content: "threaded id\n" }), + correlationId: "req-files-save-thread-01", + }; + + const result = await handleFilesContent(ctx, { + store, + redactor: buildRedactor({}), + editorLocalHistoryStore: failingHistory, + diagnostics: { + record: (record: ServerDiagnosticRecord): void => { + diagnostics.push(record); + }, + }, + } as unknown as UiHandlerDeps); + + expect(result.status).toBe(200); + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]?.correlationId).toBe("req-files-save-thread-01"); + expect(result.body).toMatchObject({ + localHistoryProtection: { correlationId: "req-files-save-thread-01" }, + }); + }); + it("fails closed for an unregistered root while preserving the save and original diagnostic", async () => { const arbitrary = await realpath(await mkdtemp(join(tmpdir(), "keiko-files-unregistered-"))); extraRoot = arbitrary; @@ -1610,6 +1655,50 @@ describe("desktop files mutations (create / rename / delete)", () => { ).toHaveLength(1); }); + it("sets parentCorrelationId to the spawning rename request's own id on a skipped migration", async () => { + // ADR-0173 D5 / g12: reKeyRenamedBreakpoints runs detached (never awaited by the rename + // response), so it mints its own correlationId for this background operation — but the + // rename request's own ctx.correlationId, when known, must still ride as parentCorrelationId + // so an operator can join this diagnostic back to the request that spawned it. Before the fix + // there was no parentCorrelationId field on the emitted record at all. + const renameInstrumentation = vi.fn().mockResolvedValue(undefined); + const diagnostics: ServerDiagnosticRecord[] = []; + const breakpoints = { + snapshot: (): { readonly ok: false; readonly reason: string } => ({ + ok: false, + reason: "state_unavailable", + }), + }; + const ctx = { + ...patchContentContext({ root, path: "src/app.ts", newPath: "src/renamed.ts" }), + correlationId: "req-rename-thread-01", + }; + + const result = await handleFilesRename(ctx, { + store, + redactor: buildRedactor({}), + dapDebug: { + breakpoints, + renameInstrumentation, + diagnosticSink: { + record: (record: ServerDiagnosticRecord): void => { + diagnostics.push(record); + }, + }, + }, + } as unknown as UiHandlerDeps); + + expect(result).toMatchObject({ status: 200, body: { path: "src/renamed.ts" } }); + const skipped = diagnostics.filter((record) => + record.operation.endsWith("breakpoint-migration-skipped"), + ); + expect(skipped).toHaveLength(1); + expect(skipped[0]?.parentCorrelationId).toBe("req-rename-thread-01"); + // The operation's OWN correlationId stays a fresh, disconnected mint (it is not the request's + // id) — only parentCorrelationId links it back. + expect(skipped[0]?.correlationId).not.toBe("req-rename-thread-01"); + }); + it("delegates every fileId under a renamed directory in one call (KEIKO-0179)", async () => { await writeFile(join(root, "src", "lib.ts"), "export const b = 2;\n"); const debugStateDir = await realpath(await mkdtemp(join(tmpdir(), "keiko-files-mut-dap-dir-"))); diff --git a/packages/keiko-server/src/files.ts b/packages/keiko-server/src/files.ts index 08bd1295f8..757249cdc5 100644 --- a/packages/keiko-server/src/files.ts +++ b/packages/keiko-server/src/files.ts @@ -2537,6 +2537,7 @@ async function readFilesContentRoute(ctx: RouteContext, deps: UiHandlerDeps): Pr function createPreRestoreCapture( deps: UiHandlerDeps, target: ResolvedTarget, + correlationId: string | undefined, ): (content: string) => NonNullable { return (content) => captureEditorLocalHistorySafely({ @@ -2546,6 +2547,7 @@ function createPreRestoreCapture( absolutePath: target.path, content, origin: "pre-restore", + correlationId, }); } @@ -2553,6 +2555,7 @@ function captureNormalFileSave( deps: UiHandlerDeps, target: ResolvedTarget, fields: FilesWriteFields, + correlationId: string | undefined, ): FilesContentWireResponse["localHistoryProtection"] { if (fields.historyOrigin !== undefined) return undefined; return captureEditorLocalHistorySafely({ @@ -2562,6 +2565,7 @@ function captureNormalFileSave( absolutePath: target.path, content: fields.content, origin: "user-save", + correlationId, }); } @@ -2599,10 +2603,12 @@ async function writeFilesContentRoute( typeof body.expectedModifiedAt === "number" ? body.expectedModifiedAt : undefined, baseVersion, beforeWrite: - fields.historyOrigin === "pre-restore" ? createPreRestoreCapture(deps, target) : undefined, + fields.historyOrigin === "pre-restore" + ? createPreRestoreCapture(deps, target, ctx.correlationId) + : undefined, }); notifyHostLspWorkspaceFileChanged(target.realRoot, target.path); - const localHistoryProtection = captureNormalFileSave(deps, target, fields); + const localHistoryProtection = captureNormalFileSave(deps, target, fields, ctx.correlationId); return { status: 200, body: localHistoryProtection === undefined ? response : { ...response, localHistoryProtection }, @@ -2718,6 +2724,7 @@ async function reKeyRenamedBreakpoints( realRoot: string, previousPath: string, nextPath: string, + requestCorrelationId: string | undefined, ): Promise { const service = deps.dapDebug; if (service === undefined) return; @@ -2727,9 +2734,11 @@ async function reKeyRenamedBreakpoints( // identity-inspection failure) used to skip the whole migration silently, bypassing the // service-side rejection diagnostic entirely. The rename still must not fail — but the skipped // migration has to be observable, mirroring the service's own redacted, body-free convention. - emitServerDiagnostic( - service.diagnosticSink, - serverDiagnosticFromError({ + // This runs detached from the rename response (never awaited by the caller), so it mints its + // own id rather than reusing the request's — but `parentCorrelationId` (ADR-0173 D5 / g12) + // still joins it back to the request that spawned it when that id is known. + emitServerDiagnostic(service.diagnosticSink, { + ...serverDiagnosticFromError({ correlationId: `files-rename-${randomUUID()}`, operation: "files.rename.breakpoint-migration-skipped", source: "files.rename", @@ -2738,7 +2747,8 @@ async function reKeyRenamedBreakpoints( "Breakpoint migration for a rename was skipped: the instrumentation snapshot is " + "unavailable; breakpoints remain under the old path.", }), - ); + ...(requestCorrelationId === undefined ? {} : { parentCorrelationId: requestCorrelationId }), + }); return; } const renames = affectedRenamedFileIds(snapshot, previousPath, nextPath); @@ -2783,7 +2793,13 @@ export async function handleFilesRename( // turning a long-completed filesystem rename into a UI timeout. renameInstrumentation's // contract is that it never rejects (failures degrade to redacted diagnostics), so nothing is // silently lost by detaching. - void reKeyRenamedBreakpoints(deps, resolvedRoot.realRoot, result.previousPath, result.path); + void reKeyRenamedBreakpoints( + deps, + resolvedRoot.realRoot, + result.previousPath, + result.path, + ctx.correlationId, + ); } return { status: 200, body: result }; }); diff --git a/packages/keiko-server/src/gateway-error-diagnostic.test.ts b/packages/keiko-server/src/gateway-error-diagnostic.test.ts new file mode 100644 index 0000000000..de6367fc68 --- /dev/null +++ b/packages/keiko-server/src/gateway-error-diagnostic.test.ts @@ -0,0 +1,78 @@ +import { describe, expect, it } from "vitest"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; +import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; +import { + emitGatewayErrorDiagnostic, + type GatewayErrorDiagnosticDeps, +} from "./gateway-error-diagnostic.js"; + +function capturingDeps(): { + readonly deps: GatewayErrorDiagnosticDeps; + readonly events: ServerDiagnosticRecord[]; +} { + const events: ServerDiagnosticRecord[] = []; + return { + events, + deps: { + diagnostics: { + record: (record): void => { + events.push(record); + }, + }, + redactor: (value: unknown): unknown => value, + }, + }; +} + +describe("emitGatewayErrorDiagnostic", () => { + it("emits one record through the sink with the given operation/source", () => { + const { deps, events } = capturingDeps(); + + emitGatewayErrorDiagnostic( + deps, + new Error("boom"), + "correlation-9", + "POST /api/example", + "example.source", + ); + + expect(events).toHaveLength(1); + const [event] = events; + if (event === undefined) throw new Error("expected a diagnostic record"); + expect(event.correlationId).toBe("correlation-9"); + expect(event.operation).toBe("POST /api/example"); + expect(event.source).toBe("example.source"); + expect(event.errorClass).toBe("Error"); + }); + + it("falls back the correlation id to the fixed unknown-id sentinel when none is known", () => { + const { deps, events } = capturingDeps(); + + emitGatewayErrorDiagnostic( + deps, + new Error("boom"), + undefined, + "POST /api/example", + "example.source", + ); + + expect(events[0]?.correlationId).toBe(UNKNOWN_CORRELATION_ID); + }); + + it("never throws when no diagnostics sink is configured", () => { + const deps: GatewayErrorDiagnosticDeps = { + diagnostics: undefined, + redactor: (value: unknown): unknown => value, + }; + + expect(() => { + emitGatewayErrorDiagnostic( + deps, + new Error("boom"), + "correlation-1", + "POST /api/example", + "example.source", + ); + }).not.toThrow(); + }); +}); diff --git a/packages/keiko-server/src/gateway-error-diagnostic.ts b/packages/keiko-server/src/gateway-error-diagnostic.ts new file mode 100644 index 0000000000..98314b46d1 --- /dev/null +++ b/packages/keiko-server/src/gateway-error-diagnostic.ts @@ -0,0 +1,48 @@ +// Shared GatewayError → operator-diagnostic wiring (ADR-0173 D5 g25/g27). +// +// Before this module, `chat-stream-handlers.ts`'s `errorEvent()` was the ONLY place a GatewayError +// reaching the desktop chat surface got routed to the redacted operator diagnostic sink before the +// response left — the buffered `/api/desktop/chat` path (`chat-handlers.ts`) and grounded Q&A +// (`grounded-qa.ts`) mapped the SAME error class straight to an HTTP body with no diagnostic call +// at all, so a mid-request gateway failure was traceable only when it happened to arrive over SSE. +// This file extracts that one block so every caller emits the identical record shape. +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; +import { + emitServerDiagnostic, + serverDiagnosticFromError, + type ServerDiagnosticSink, +} from "./diagnostics-log.js"; +import type { Redactor } from "./deps.js"; + +// A structural subset of `UiHandlerDeps` — the two fields this helper actually reads — so callers +// never need to import the full `UiHandlerDeps` type just to satisfy this one function. +export interface GatewayErrorDiagnosticDeps { + readonly diagnostics?: ServerDiagnosticSink | undefined; + readonly redactor: Redactor; +} + +// `correlationId` falls back to `UNKNOWN_CORRELATION_ID` rather than being omitted: +// `ServerDiagnosticRecord` requires one (a diagnostic nobody can join to a request is far less +// useful than one honestly marked unjoinable), matching the fallback `chat-stream-handlers.ts`'s +// `errorEvent()` already used before this extraction — every caller inherits the same behaviour, +// not a stricter or looser one. The fixed sentinel (rather than the bare literal `"unknown"`) is +// deliberate: it is shape-valid, so it survives `emitServerDiagnostic`'s sanitizer unchanged instead +// of being rewritten to the sanitizer's own "hostile value" marker. +export function emitGatewayErrorDiagnostic( + deps: GatewayErrorDiagnosticDeps, + error: unknown, + correlationId: string | undefined, + operation: string, + source: string, +): void { + emitServerDiagnostic( + deps.diagnostics, + serverDiagnosticFromError({ + correlationId: correlationId ?? UNKNOWN_CORRELATION_ID, + operation, + source, + error, + redact: (message) => String(deps.redactor(message)), + }), + ); +} diff --git a/packages/keiko-server/src/gateway-setup.test.ts b/packages/keiko-server/src/gateway-setup.test.ts index 0d86ad811c..efefa44a04 100644 --- a/packages/keiko-server/src/gateway-setup.test.ts +++ b/packages/keiko-server/src/gateway-setup.test.ts @@ -5872,6 +5872,40 @@ describe("handleGatewaySetup", () => { deps.store.close(); }); + // ADR-0173 D5 g12: the discovery-truncation diagnostic must join the SAME trace as the rest of + // this setup attempt (e.g. the gateway.chat probe lines), not mint a disconnected id of its own + // — otherwise an operator cannot tell which setup attempt a truncation diagnostic belongs to. + it("threads the request's correlation id onto the discovery-truncation diagnostic (g12)", async () => { + const uiDir = await tempDir("keiko-gw-ui-discovery-truncated-corr-"); + const evidenceDir = await tempDir("keiko-gw-ev-discovery-truncated-corr-"); + const diagnostics: ServerDiagnosticRecord[] = []; + const oversized = Array.from({ length: MAX_DISCOVERED_MODELS + 5 }, (_unused, index) => ({ + id: `discovered-model-${String(index)}`, + })); + const deps = buildUiHandlerDeps({ + configPath: undefined, + evidenceDir, + env: { ...VAULT_ENV }, + uiDbPath: join(uiDir, "keiko-ui.db"), + gatewayModelDiscovery: () => Promise.resolve(parseModelDiscovery({ data: oversized })), + gatewayEmbeddingProbe: PASSTHROUGH_EMBEDDING_PROBE, + gatewaySetupTester: (_config, modelIds) => Promise.resolve([...modelIds]), + diagnostics: { record: (record): void => void diagnostics.push(record) }, + }); + + await handleGatewaySetup( + ctx( + { baseUrl: "https://llm-gateway.example.com", apiKey: "example-secret-token" }, + "corr-discovery-truncation-g12", + ), + deps, + ); + + const truncation = diagnostics.find((record) => record.code === "GATEWAY_DISCOVERY_TRUNCATED"); + expect(truncation?.correlationId).toBe("corr-discovery-truncation-g12"); + deps.store.close(); + }); + it("does not emit the truncation diagnostic when discovery fits the cap (KEIKO-0325)", async () => { const uiDir = await tempDir("keiko-gw-ui-discovery-fits-"); const evidenceDir = await tempDir("keiko-gw-ev-discovery-fits-"); diff --git a/packages/keiko-server/src/gateway-setup.ts b/packages/keiko-server/src/gateway-setup.ts index feac26bb05..662f33d2dc 100644 --- a/packages/keiko-server/src/gateway-setup.ts +++ b/packages/keiko-server/src/gateway-setup.ts @@ -77,6 +77,7 @@ import type { VerifiedModelCapabilityFields, } from "./deps.js"; import { currentGatewayConfig, currentGatewayEgressConfig } from "./deps.js"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; import { emitServerDiagnostic, serverDiagnosticFromError, @@ -1807,6 +1808,7 @@ export async function smokeTestCandidates( async function defaultGatewaySetupTester( config: GatewayConfig, candidateModelIds: readonly string[], + correlationId: string | undefined, ): Promise { // Wired to the process activity log: first-run setup is where an operator's endpoint is wrong // in a way no UI message can name (a proxy that blocks CONNECT, a provider that answers 404 for @@ -1821,6 +1823,7 @@ async function defaultGatewaySetupTester( { role: "system", content: CONVERSATION_SYSTEM_PROMPT }, { role: "user", content: "Reply with exactly: OK" }, ], + logContext: { correlationId }, }); }, SETUP_SMOKE_CONCURRENCY, @@ -1828,7 +1831,10 @@ async function defaultGatewaySetupTester( const responseFormatModelIds = await passingCandidates( testedModelIds, async (modelId) => { - const response = await gateway.chat(buildQiJudgePreflightRequest(modelId)); + const response = await gateway.chat({ + ...buildQiJudgePreflightRequest(modelId), + logContext: { correlationId }, + }); if (tryParseJudgeVerdict(response.content) === null) { throw new Error("response format unsupported"); } @@ -1913,8 +1919,18 @@ function gatewayEmbeddingProbe(deps: UiHandlerDeps): GatewayEmbeddingProbe { return deps.gatewayEmbeddingProbe ?? defaultGatewayEmbeddingProbe; } -function gatewaySetupTester(deps: UiHandlerDeps): GatewaySetupTester { - return deps.gatewaySetupTester ?? defaultGatewaySetupTester; +// The seam type (UiHandlerDeps["gatewaySetupTester"]) is a fixed 2-arg shape shared by every +// test override, so the request-scoped correlation id is closed over here rather than added as a +// 3rd seam parameter — the override contract stays untouched while the real tester still stamps +// GatewayCallRequest.logContext (ADR-0173 D5). +function gatewaySetupTester( + deps: UiHandlerDeps, + correlationId: string | undefined, +): GatewaySetupTester { + const override = deps.gatewaySetupTester; + if (override !== undefined) return override; + return (config, candidateModelIds) => + defaultGatewaySetupTester(config, candidateModelIds, correlationId); } const FIGMA_ME_ENDPOINT = "https://api.figma.com/v1/me"; @@ -4136,7 +4152,7 @@ function reportSetupVerificationFailure( emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: correlationId ?? "unknown", + correlationId: correlationId ?? UNKNOWN_CORRELATION_ID, operation: "POST /api/gateway/setup", source, error, @@ -4194,6 +4210,11 @@ interface SetupVerificationInput { readonly current: GatewayConfig | undefined; /** Operator diagnostic sink; used to surface discovery truncation (KEIKO-0325). */ readonly diagnostics?: ServerDiagnosticSink | undefined; + // The request's own correlation id (ADR-0173 D5 g12), threaded through so a discovery-truncation + // or unusable-models diagnostic for THIS setup attempt joins the same trace as the gateway.chat + // probe lines `verifySetupCandidate` triggers, instead of minting a disconnected id. Falls back + // to a fresh mint only when the request genuinely carried none. + readonly correlationId: string | undefined; } interface SetupCandidateModels { @@ -4616,11 +4637,12 @@ function candidateProbeOptions( // construction — a count and a code, never a model id or an endpoint. function reportDiscoveryTruncation( diagnostics: ServerDiagnosticSink | undefined, + correlationId: string | undefined, candidateModels: SetupCandidateModels, ): void { if (candidateModels.truncated !== true) return; emitServerDiagnostic(diagnostics, { - correlationId: randomUUID(), + correlationId: correlationId ?? randomUUID(), timestamp: new Date().toISOString(), operation: "POST /api/gateway/setup", source: "gateway-setup.discovery", @@ -4705,6 +4727,7 @@ async function admitEmbeddingCandidates( // channel stays free of gateway inventory. function reportUnusableDiscoveredModels( diagnostics: ServerDiagnosticSink | undefined, + correlationId: string | undefined, unsupported: readonly GatewayUnsupportedDiscoveredModel[], admission: EmbeddingAdmission, ): void { @@ -4712,7 +4735,7 @@ function reportUnusableDiscoveredModels( const dropped = admission.droppedUnverified.length; if (unsupported.length === 0 && retained === 0 && dropped === 0) return; emitServerDiagnostic(diagnostics, { - correlationId: randomUUID(), + correlationId: correlationId ?? randomUUID(), timestamp: new Date().toISOString(), operation: "POST /api/gateway/setup", source: "gateway-setup.discovery", @@ -4735,7 +4758,7 @@ async function verifySetupCandidate(input: SetupVerificationInput): Promise 0 ? DEPLOYMENT_SMOKE_TIMEOUT_MS @@ -4754,6 +4777,7 @@ async function verifySetupCandidate(input: SetupVerificationInput): Promise { const seams: SetupSeams = { - tester: gatewaySetupTester(deps), + tester: gatewaySetupTester(deps, request.correlationId), embeddingProbe: gatewayEmbeddingProbe(deps), discovery: deps.gatewayModelDiscovery ?? defaultGatewayModelDiscovery, }; diff --git a/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.test.ts b/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.test.ts index 9c6d3299f9..52ed2e5192 100644 --- a/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.test.ts +++ b/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.test.ts @@ -204,4 +204,70 @@ describe("recordGitDeliveryMutationEvidence — fail-closed + never throws", () consoleError.mockRestore(); } }); + + // ADR-0173 D5 / g12: a persistence-failure diagnostic used to mint a fresh, disconnected + // `randomUUID()` even though the record already carries the mutation's own deterministic + // `correlation.actionId` (`defaultGitDeliveryActionId`'s output shape, reused here). Fails + // before the fix — the diagnostic's correlationId would be an unrelated fresh UUID instead of + // the record's own action id. + it("threads the record's own action id as the diagnostic correlation id when it is validly shaped", () => { + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (entry) => { + records.push(entry); + }, + }; + const actionId = "gde-action-deadbeefcafefeed01234567"; + const throwingStore: EvidenceStore = { + put: (): string => { + throw Object.assign(new Error("ledger write failed"), { code: "ENOSPC" }); + }, + get: (): string | undefined => undefined, + list: (): readonly string[] => [], + delete: (): void => { + /* no-op */ + }, + }; + + recordGitDeliveryMutationEvidence( + { evidenceStore: throwingStore, redactString, diagnostics }, + record({ correlation: { workflowRunIdHash: "a".repeat(64), actionId } }), + ); + + expect(records).toHaveLength(1); + expect(records[0]?.correlationId).toBe(actionId); + }); + + // The `record()` fixture's default `actionId` ("act-1") is only 5 characters — shorter than + // `isValidCorrelationId`'s 8-character floor — so this pins the fallback branch: an actionId + // that is not validly shaped as a correlation id must never reach the diagnostic verbatim, and + // the existing shape-only pin above (line ~200) still passes because the fallback is a fresh, + // validly-shaped UUID, not the unshaped actionId itself. + it("falls back to a fresh id when the record's action id is not validly shaped", () => { + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (entry) => { + records.push(entry); + }, + }; + const throwingStore: EvidenceStore = { + put: (): string => { + throw new Error("ledger write failed"); + }, + get: (): string | undefined => undefined, + list: (): readonly string[] => [], + delete: (): void => { + /* no-op */ + }, + }; + + recordGitDeliveryMutationEvidence( + { evidenceStore: throwingStore, redactString, diagnostics }, + record(), + ); + + expect(records).toHaveLength(1); + expect(records[0]?.correlationId).not.toBe("act-1"); + expect(records[0]?.correlationId).toMatch(/^[A-Za-z0-9._-]{8,128}$/); + }); }); diff --git a/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.ts b/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.ts index cdaff760de..2d292fe54c 100644 --- a/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.ts +++ b/packages/keiko-server/src/gitDelivery/mutationEvidenceLedger.ts @@ -26,6 +26,7 @@ import { import { deepRedactStrings } from "@oscharko-dev/keiko-evidence"; import type { EvidenceStore } from "@oscharko-dev/keiko-evidence"; import { randomUUID } from "node:crypto"; +import { isValidCorrelationId } from "../correlation.js"; import { emitServerDiagnostic, serverDiagnosticFromError, @@ -66,7 +67,11 @@ export interface RecordGitDeliveryEvidenceOptions { // The previous default was `console.error("…", error)` — the raw error object on a channel no // production assembly overrode, so a failed governed-mutation evidence write was invisible AND could // carry the very content this ledger redacts. Routed through the single redacted diagnostic sink. -function reportPersistFailure(options: RecordGitDeliveryEvidenceOptions, error: unknown): void { +function reportPersistFailure( + options: RecordGitDeliveryEvidenceOptions, + correlationId: string, + error: unknown, +): void { if (options.onPersistError !== undefined) { options.onPersistError(error); return; @@ -74,7 +79,7 @@ function reportPersistFailure(options: RecordGitDeliveryEvidenceOptions, error: emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "gitDelivery.mutationEvidence.persist", source: "gitDelivery.mutationEvidenceLedger", error, @@ -84,6 +89,20 @@ function reportPersistFailure(options: RecordGitDeliveryEvidenceOptions, error: ); } +// The record's own `correlation.actionId` (ADR-0173 D5 / g12) is the run already in scope at the +// moment this evidence was built — a deterministic, content-free id (`defaultGitDeliveryActionId` +// hashes the command; `gitDelivery/mergeExecution.ts` and siblings mint it once per governed +// mutation attempt). Reusing it instead of a fresh `randomUUID()` lets an operator join a failed +// persistence diagnostic back to the SAME mutation attempt's other evidence. Re-validated here +// against `isValidCorrelationId`'s shape rather than trusted blindly: `actionId` is typed as a +// plain `string` on the wire contract, so a producer that has not adopted the deterministic helper +// (or a test fixture) can still hand this a value that is not safe to use as a correlation id — +// that case falls back to a fresh mint, exactly like the pre-fix behaviour. +function evidenceCorrelationId(record: GitDeliveryEvidenceRecord): string { + const { actionId } = record.correlation; + return isValidCorrelationId(actionId) ? actionId : randomUUID(); +} + function isPlainObject(value: unknown): value is Record { return typeof value === "object" && value !== null && !Array.isArray(value); } @@ -157,6 +176,6 @@ export function recordGitDeliveryMutationEvidence( try { appendRecord(options.evidenceStore, runId, safe, cap); } catch (error) { - reportPersistFailure(options, error); + reportPersistFailure(options, evidenceCorrelationId(record), error); } } diff --git a/packages/keiko-server/src/gitDelivery/syncEvidence.test.ts b/packages/keiko-server/src/gitDelivery/syncEvidence.test.ts index 11e3634817..aa8a381e65 100644 --- a/packages/keiko-server/src/gitDelivery/syncEvidence.test.ts +++ b/packages/keiko-server/src/gitDelivery/syncEvidence.test.ts @@ -250,6 +250,11 @@ describe("recordGitSyncEvidence — best-effort and fail-closed", () => { expect(records[0]?.source).toBe("gitDelivery.syncEvidence"); expect(records[0]?.code).toBe("ENOSPC"); expect(records[0]?.correlationId).toMatch(/^[A-Za-z0-9._-]{8,128}$/); + // ADR-0173 D5 / g12: the failure's correlationId is the SAME date-bucket runId the write + // itself targeted (from the real producer, not a re-derived formula), not a disconnected + // `randomUUID()` — an operator can join the failure back to the bucket it belongs to. Before + // the fix this was a random UUID and never equalled the bucket runId. + expect(records[0]?.correlationId).toBe(gitSyncEvidenceRunIdFor(AT)); expect(JSON.stringify(records)).not.toContain(secret); expect(consoleError).not.toHaveBeenCalled(); } finally { diff --git a/packages/keiko-server/src/gitDelivery/syncEvidence.ts b/packages/keiko-server/src/gitDelivery/syncEvidence.ts index 73ed65212b..940f2c5118 100644 --- a/packages/keiko-server/src/gitDelivery/syncEvidence.ts +++ b/packages/keiko-server/src/gitDelivery/syncEvidence.ts @@ -16,6 +16,7 @@ import { deepRedactStrings } from "@oscharko-dev/keiko-evidence"; import type { EvidenceStore } from "@oscharko-dev/keiko-evidence"; import { sha256Hex } from "@oscharko-dev/keiko-security"; import { randomUUID } from "node:crypto"; +import { isValidCorrelationId } from "../correlation.js"; import { emitServerDiagnostic, serverDiagnosticFromError, @@ -78,15 +79,25 @@ export interface RecordGitSyncEvidenceOptions { // The previous default was `console.error("…", error)` — the raw error object on a channel no // production assembly overrode, so a failed evidence write was invisible AND could carry the very // content this ledger redacts. Routed through the server's single redacted diagnostic sink instead. -function reportPersistFailure(options: RecordGitSyncEvidenceOptions, error: unknown): void { +function reportPersistFailure( + options: RecordGitSyncEvidenceOptions, + runId: string, + error: unknown, +): void { if (options.onPersistError !== undefined) { options.onPersistError(error); return; } + // Reuses the date-bucket runId the write itself targeted (ADR-0173 D5 / g12, mirroring + // mutationEvidenceLedger.ts's `evidenceCorrelationId`) rather than a disconnected fresh mint, so + // an operator can join this diagnostic back to the SAME bucket's other evidence. Re-validated + // against `isValidCorrelationId` even though this module derives the shape itself: a future + // change to the runId format must not silently become an unshaped correlation id. + const correlationId = isValidCorrelationId(runId) ? runId : randomUUID(); emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "gitDelivery.syncEvidence.persist", source: "gitDelivery.syncEvidence", error, @@ -165,6 +176,6 @@ export function recordGitSyncEvidence( try { appendRecord(options.evidenceStore, runId, safe, cap); } catch (error) { - reportPersistFailure(options, error); + reportPersistFailure(options, runId, error); } } diff --git a/packages/keiko-server/src/grounded-entailment-judge.test.ts b/packages/keiko-server/src/grounded-entailment-judge.test.ts index 7dc00edb5e..a046f24c9c 100644 --- a/packages/keiko-server/src/grounded-entailment-judge.test.ts +++ b/packages/keiko-server/src/grounded-entailment-judge.test.ts @@ -3,7 +3,7 @@ import { describe, expect, it } from "vitest"; import type { - GatewayRequest, + GatewayCallRequest, ModelCapability, NormalizedResponse, } from "@oscharko-dev/keiko-model-gateway"; @@ -32,10 +32,10 @@ function throwingPort(): ModelPort { }; } -function respondingPort(content: string): { port: ModelPort; calls: GatewayRequest[] } { - const calls: GatewayRequest[] = []; +function respondingPort(content: string): { port: ModelPort; calls: GatewayCallRequest[] } { + const calls: GatewayCallRequest[] = []; const port: ModelPort = { - call: (request: GatewayRequest): Promise => { + call: (request: GatewayCallRequest): Promise => { calls.push(request); return Promise.resolve({ content, @@ -176,6 +176,21 @@ describe("createGatewayEntailmentJudge", () => { ); }); + // ADR-0173 D5: the entailment stage's own turn-scoped correlation id must reach the judge's + // model.call so a gateway retry/circuit-breaker line for this second-pass verification joins + // the same trail as the answer it is checking. + it("stamps the supplied correlation id into the judge's GatewayCallRequest.logContext", async () => { + const supported = respondingPort('{"verdict":"supported"}'); + const judge = createGatewayEntailmentJudge( + depsWith(supported.port), + MODEL_ID, + "cid-entailment-judge-000001", + ); + await judge?.judge({ claimText: "30 days", excerptText: "retention: 30 days" }); + expect(supported.calls).toHaveLength(1); + expect(supported.calls[0]?.logContext?.correlationId).toBe("cid-entailment-judge-000001"); + }); + it("fails closed to unavailable when the gateway throws (never supported, never throws)", async () => { const judge = createGatewayEntailmentJudge(depsWith(throwingPort()), MODEL_ID); expect(judge).toBeDefined(); diff --git a/packages/keiko-server/src/grounded-entailment-judge.ts b/packages/keiko-server/src/grounded-entailment-judge.ts index c1eaea6387..f2a3fa0791 100644 --- a/packages/keiko-server/src/grounded-entailment-judge.ts +++ b/packages/keiko-server/src/grounded-entailment-judge.ts @@ -19,6 +19,7 @@ import { findCapability, findConfiguredCapability, type ChatMessage, + type GatewayCallRequest, type GatewayRequest, type ModelCapability, } from "@oscharko-dev/keiko-model-gateway"; @@ -171,6 +172,7 @@ function isModelCompatible(capability: ModelCapability | undefined): boolean { export function createGatewayEntailmentJudge( deps: UiHandlerDeps, modelId: string, + correlationId?: string, ): EntailmentJudge | undefined { const capability = capabilityFor(deps, modelId); if (!isModelCompatible(capability)) return undefined; @@ -183,13 +185,14 @@ export function createGatewayEntailmentJudge( signal?: AbortSignal, ): Promise => { const cancellation = MgQI.composeCancellationSignal(profile.timeoutMsHint, signal); - const request: GatewayRequest = { + const request: GatewayCallRequest = { modelId, messages: buildEntailmentPrompt(input), stream: false, cancellationSignal: cancellation.signal, temperature: 0, responseFormat: buildEntailmentResponseFormat(), + logContext: { correlationId }, }; try { const response = await model.call(request, cancellation.signal); diff --git a/packages/keiko-server/src/grounded-entailment-stage.ts b/packages/keiko-server/src/grounded-entailment-stage.ts index 7c39d36e55..933462094f 100644 --- a/packages/keiko-server/src/grounded-entailment-stage.ts +++ b/packages/keiko-server/src/grounded-entailment-stage.ts @@ -176,7 +176,7 @@ export function createEntailmentStage( ...observability, correlationId: observability.correlationId ?? randomUUID(), }; - const judge = createGatewayEntailmentJudge(deps, modelId); + const judge = createGatewayEntailmentJudge(deps, modelId, correlated.correlationId); if (judge === undefined) { // KEIKO-0359: report WHY the stage is inert. Going inert used to be completely silent, so a // model whose capability metadata Gateway Setup never enriched looked identical to a model diff --git a/packages/keiko-server/src/grounded-qa-hybrid.test.ts b/packages/keiko-server/src/grounded-qa-hybrid.test.ts index 1abdbf062b..07981e3b71 100644 --- a/packages/keiko-server/src/grounded-qa-hybrid.test.ts +++ b/packages/keiko-server/src/grounded-qa-hybrid.test.ts @@ -54,7 +54,9 @@ import { GROUNDED_NO_EVIDENCE_ANSWER } from "./grounded-faithfulness.js"; import type { ModelPort } from "@oscharko-dev/keiko-harness"; import { parseGatewayConfig, + type GatewayCallRequest, type ModelCapability, + type NormalizedResponse, type RerankOutcome, } from "@oscharko-dev/keiko-model-gateway"; import type { GroundedRetriever } from "./grounded-qa-multi-source.js"; @@ -62,11 +64,13 @@ import { EmbeddingAdapterError, connectorQuery, connectorRetrievalTopK, + createHybridAnswerer, estimateConnectorExcerptBytes, hashString32, runHybridGroundedAsk, type ConnectorRetrieve, } from "./grounded-qa-hybrid.js"; +import { normalizeGroundedAnswerPayload } from "./grounded-answer.js"; import { createInMemoryUiStore, type UiStore } from "./store/index.js"; import type { UiHandlerDeps } from "./deps.js"; import { buildRedactor, createRunRegistry } from "./index.js"; @@ -2124,6 +2128,100 @@ describe("AC5 routing — single connector must route to handleLocalKnowledgeGro const lkAnswer = asLocalKnowledge(answer); expect(lkAnswer.contextPack.kind).toBe("local-knowledge"); }); + + // ADR-0173 D5: local-knowledge-grounded-qa.ts's StoreBackedAnswerGenerator.generate is the real + // model.call site this dispatch path reaches (no seam bypasses it here, unlike the hybrid tests + // above) — it must stamp the request's correlation id into GatewayCallRequest.logContext. + it("threads the request correlation id into the local-knowledge answerer's model gateway call", async () => { + const { capsuleId: capId } = await seedReadyCapsule("Solo Docs Correlation"); + const chatId = makeHybridChat([], [{ kind: "capsule", capsuleId: capId, connectedAtMs: NOW }]); + const hybrid: HybridSeam = { answer: throwingHybridAnswerer() }; + const embeddingModelId = "text-embedding-3-small"; + const adapter = scriptedAdapter(); + const seenRequests: GatewayCallRequest[] = []; + const recordingModelPort: ModelPort = { + call: (request): Promise => { + seenRequests.push(request); + return Promise.resolve({ + modelId: CHAT_MODEL, + content: "Local knowledge answer [1].", + finishReason: "stop" as const, + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "lk-logcontext-test", + promptTokens: 10, + completionTokens: 5, + latencyMs: 5, + costClass: "medium" as const, + }, + }); + }, + }; + const configuredDeps: UiHandlerDeps = { + ...hybridDeps({ localKnowledgeEmbeddingRequest: adapter.request }), + config: { + providers: [ + { + modelId: CHAT_MODEL, + baseUrl: "https://provider.example/v1", + apiKey: "test-api-key-1234567890", + timeoutMs: 30_000, + maxRetries: 0, + retryBaseDelayMs: 500, + }, + { + modelId: embeddingModelId, + baseUrl: "https://provider.example/v1", + apiKey: "test-api-key-1234567890", + timeoutMs: 30_000, + maxRetries: 0, + retryBaseDelayMs: 500, + }, + ], + circuitBreaker: { failureThreshold: 5, cooldownMs: 30_000, halfOpenProbes: 2 }, + capabilities: [ + { + id: CHAT_MODEL, + kind: "chat", + contextWindow: 64_000, + maxOutputTokens: 4_096, + toolCalling: true, + structuredOutput: true, + streaming: true, + supportsImageInput: false, + supportsDocumentInput: false, + workflowEligible: false, + costClass: "medium", + latencyClass: "standard", + throughputHint: "test", + preferredUseCases: [], + knownLimitations: [], + }, + ], + }, + configPresent: true, + modelPortFactory: () => recordingModelPort, + }; + const requestCtx: RouteContext = { + ...routeCtx(JSON.stringify({ chatId, content: "Solo question", modelId: CHAT_MODEL })), + correlationId: "cid-local-knowledge-000001", + }; + + const result = await handleGroundedAsk( + requestCtx, + configuredDeps, + undefined, + undefined, + hybrid, + ); + + expect(result.status, JSON.stringify(result.body)).toBe(200); + expect(seenRequests.length).toBeGreaterThan(0); + for (const request of seenRequests) { + expect(request.logContext?.correlationId).toBe("cid-local-knowledge-000001"); + } + }); }); // ─── Case 4c: Configured model reranker over hybrid candidates ──────────────── @@ -3298,3 +3396,52 @@ describe("hybrid entailment forwards the retrieved folder packs (KEIKO-0237)", ( expect(observedCapsulesPerCall).toEqual([1]); }); }); + +// ─── Correlation threading (ADR-0173 D5) ────────────────────────────────────── +// +// Every hybrid dispatch test above injects `HybridSeam.answer` (a bare (system, user) => string +// function), which never touches the real Gateway-backed answerer this file's production code +// builds via `resolveHybridAnswerer` -> `createHybridAnswerer`. That builder is the actual +// model.call site fixed here, so it is unit-tested directly against a fake ModelPort that records +// the request it receives. +describe("createHybridAnswerer correlation threading", () => { + it("stamps the caller's correlation id into the Gateway double's GatewayCallRequest.logContext", async () => { + const seenRequests: GatewayCallRequest[] = []; + const recordingModel: ModelPort = { + call(request): Promise { + seenRequests.push(request); + return Promise.resolve({ + modelId: request.modelId, + content: "hybrid answer", + finishReason: "stop", + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "hybrid-answerer-test", + promptTokens: 3, + completionTokens: 2, + latencyMs: 1, + costClass: "medium", + }, + }); + }, + }; + + const answerer = createHybridAnswerer( + recordingModel, + CHAT_MODEL, + new AbortController().signal, + "cid-hybrid-answerer-000001", + ); + // `HybridAnswerer`'s declared return type is `Promise` (a + // `string | GroundedAnswerResult` union), even though `createHybridAnswerer`'s own + // implementation always resolves the object branch — `normalizeGroundedAnswerPayload` is the + // SAME narrowing every production caller already applies to a `HybridAnswerer` result + // (grounded-qa-hybrid.ts, grounded-orchestrator.ts), not a test-only cast. + const result = normalizeGroundedAnswerPayload(await answerer("system prompt", "user prompt")); + + expect(result.content).toBe("hybrid answer"); + expect(seenRequests).toHaveLength(1); + expect(seenRequests[0]?.logContext?.correlationId).toBe("cid-hybrid-answerer-000001"); + }); +}); diff --git a/packages/keiko-server/src/grounded-qa-hybrid.ts b/packages/keiko-server/src/grounded-qa-hybrid.ts index 75ee95ca6d..22d8eacffd 100644 --- a/packages/keiko-server/src/grounded-qa-hybrid.ts +++ b/packages/keiko-server/src/grounded-qa-hybrid.ts @@ -185,6 +185,9 @@ export interface HybridGroundedAskCtx { readonly deps: UiHandlerDeps; readonly signal: AbortSignal; readonly readinessAdmission?: ConversationReadinessAdmission | undefined; + // ADR-0173 D5: the request-scoped correlation id, threaded from PreparedGroundedAsk into the + // GatewayCallRequest.logContext the hybrid answerer stamps onto its model.call. + readonly correlationId?: string | undefined; readonly folderRetriever?: FolderRetriever; readonly connectorRetrieve?: ConnectorRetrieve; readonly answer?: HybridAnswerer; @@ -811,6 +814,7 @@ export function createHybridAnswerer( model: ModelPort, modelId: string, signal: AbortSignal, + correlationId: string | undefined, ): HybridAnswerer { return async (system, user): Promise => { ensureNotCancelled(signal); @@ -822,6 +826,7 @@ export function createHybridAnswerer( { role: "user", content: user }, ], stream: false, + logContext: { correlationId }, }, signal, ); @@ -1654,7 +1659,7 @@ function resolveHybridAnswerer(ctx: HybridGroundedAskCtx): ResolvedAnswerer | Ro readinessAdmission, ctx.deps, ); - return { answer: createHybridAnswerer(model, ctx.modelId, ctx.signal) }; + return { answer: createHybridAnswerer(model, ctx.modelId, ctx.signal, ctx.correlationId) }; } async function noEvidenceAssistant( diff --git a/packages/keiko-server/src/grounded-qa-multi-source.test.ts b/packages/keiko-server/src/grounded-qa-multi-source.test.ts index 04164b4d51..c779360765 100644 --- a/packages/keiko-server/src/grounded-qa-multi-source.test.ts +++ b/packages/keiko-server/src/grounded-qa-multi-source.test.ts @@ -41,6 +41,7 @@ import { buildLabeledAnswerCitations, buildConnectedScopes, buildMultiSourceGatewayMessages, + createMultiSourceAnswerer, mergeContextPackSummaries, runMultiSourceAsk, sourceLabels, @@ -50,6 +51,7 @@ import { type MultiSourceAnswerer, } from "./grounded-qa-multi-source.js"; import { buildGroundedAnswerContextPackSummary } from "@oscharko-dev/keiko-contracts/bff-wire"; +import { normalizeGroundedAnswerPayload } from "./grounded-answer.js"; import { attachContextBudgetDiagnostics } from "./grounded-context-diagnostics.js"; import { createInMemoryUiStore, type Chat, type UiStore } from "./store/index.js"; import type { UiHandlerDeps } from "./deps.js"; @@ -57,7 +59,12 @@ import { buildRedactor, createRunRegistry } from "./index.js"; import type { RouteContext } from "./routes.js"; import type { OrchestratorInput, OrchestratorOutput } from "./grounded-orchestrator.js"; import { RepoSearchUnsupportedFileError } from "@oscharko-dev/keiko-workspace"; -import { ContextOverflowError } from "@oscharko-dev/keiko-model-gateway"; +import { + ContextOverflowError, + type GatewayCallRequest, + type NormalizedResponse, +} from "@oscharko-dev/keiko-model-gateway"; +import type { ModelPort } from "@oscharko-dev/keiko-harness"; const NOW = 1_700_000_000_000; const CHAT_MODEL = "example-chat-model"; @@ -1635,3 +1642,50 @@ describe("multi-source entailment forwards the retrieved packs (KEIKO-0237)", () expect(observedCapsulesPerCall).toEqual([0]); }); }); + +// ─── Correlation threading (ADR-0173 D5) ────────────────────────────────────── +// +// createMultiSourceAnswerer is the real model.call site the tests above bypass via an injected +// MultiSourceSeam.answerer; unit-test it directly against a fake ModelPort that records the request. +describe("createMultiSourceAnswerer correlation threading", () => { + it("stamps the caller's correlation id into the Gateway double's GatewayCallRequest.logContext", async () => { + const seenRequests: GatewayCallRequest[] = []; + const recordingModel: ModelPort = { + call(request): Promise { + seenRequests.push(request); + return Promise.resolve({ + modelId: request.modelId, + content: "multi-source answer", + finishReason: "stop", + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "multi-source-answerer-test", + promptTokens: 3, + completionTokens: 2, + latencyMs: 1, + costClass: "medium", + }, + }); + }, + }; + + const answerer = createMultiSourceAnswerer( + recordingModel, + "example-chat-model", + buildRedactor({}), + new AbortController().signal, + "cid-multi-source-answerer-000001", + ); + // `MultiSourceAnswerer`'s declared return type is `Promise` (a + // `string | GroundedAnswerResult` union), even though `createMultiSourceAnswerer`'s own + // implementation always resolves the object branch — `normalizeGroundedAnswerPayload` is the + // SAME narrowing every production caller already applies to this result + // (grounded-qa-multi-source.ts, grounded-orchestrator.ts), not a test-only cast. + const result = normalizeGroundedAnswerPayload(await answerer("What is alpha?", [])); + + expect(result.content).toBe("multi-source answer"); + expect(seenRequests).toHaveLength(1); + expect(seenRequests[0]?.logContext?.correlationId).toBe("cid-multi-source-answerer-000001"); + }); +}); diff --git a/packages/keiko-server/src/grounded-qa-multi-source.ts b/packages/keiko-server/src/grounded-qa-multi-source.ts index 9ad0d0d5d5..c8679ad22b 100644 --- a/packages/keiko-server/src/grounded-qa-multi-source.ts +++ b/packages/keiko-server/src/grounded-qa-multi-source.ts @@ -560,6 +560,7 @@ export function createMultiSourceAnswerer( modelId: string, redactor: Redactor, signal: AbortSignal, + correlationId: string | undefined, ): MultiSourceAnswerer { return async (question, labeledPacks): Promise => { ensureNotCancelled(signal); @@ -568,6 +569,7 @@ export function createMultiSourceAnswerer( modelId, messages: buildMultiSourceGatewayMessages(question, labeledPacks, redactor), stream: false, + logContext: { correlationId }, }, signal, ); diff --git a/packages/keiko-server/src/grounded-qa.test.ts b/packages/keiko-server/src/grounded-qa.test.ts index 1794288925..fb9bebe0af 100644 --- a/packages/keiko-server/src/grounded-qa.test.ts +++ b/packages/keiko-server/src/grounded-qa.test.ts @@ -34,6 +34,7 @@ import { buildGroundedGatewayMessages, groundedPromptInputTokensForCapability, handleGroundedAsk, + mappedGatewayError, modelWindowAwareBudget, modelInputPromptByteLimit, promptByteLength, @@ -52,6 +53,8 @@ import { createInMemoryEvidenceStore, loadEvidence } from "@oscharko-dev/keiko-e import { CancelledError, ContextOverflowError, + RateLimitError, + type GatewayCallRequest, type GatewayConfig, type GatewayRequest, type NormalizedResponse, @@ -70,7 +73,7 @@ import { RepoSearchInvalidQueryError } from "@oscharko-dev/keiko-workspace"; import { createMemoryVault, type MemoryVaultStore } from "@oscharko-dev/keiko-memory-vault"; import type { MemoryId } from "@oscharko-dev/keiko-contracts/memory"; import type { MemoryUserId } from "@oscharko-dev/keiko-contracts"; -import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; import { handleSendDesktopChat } from "./chat-handlers.js"; import { canonicalChatTurnGroundingScopeIdentity, @@ -1720,6 +1723,36 @@ describe("handleGroundedAsk", () => { ); }); + // ADR-0173 D5: the folder single-source answerer must stamp the request's correlation id into + // GatewayCallRequest.logContext so a gateway retry/circuit-breaker line for this call joins the + // same trail as the HTTP request that triggered it. + it("threads the request correlation id into the Model Gateway call's logContext", async () => { + const { chatId, projectPath } = await setupChatWithScope(); + seedScopedRepo(projectPath); + const seenRequests: GatewayRequest[] = []; + const requestCtx: RouteContext = { + ...ctx( + JSON.stringify({ + chatId, + content: GROUNDED_FIXTURE_QUESTION, + modelId: CHAT_MODEL, + }), + ), + correlationId: "cid-grounded-folder-000001", + }; + + const result = await handleGroundedAsk( + requestCtx, + deps(fakeModel("Grounded answer [src/foo.ts:1-3]", seenRequests)), + ); + + expect(result.status, JSON.stringify(result.body)).toBe(200); + expect(seenRequests).toHaveLength(1); + expect( + (firstGatewayRequest(seenRequests) as GatewayCallRequest).logContext?.correlationId, + ).toBe("cid-grounded-folder-000001"); + }); + it("production path includes an explicitly connected single file when the question has no lexical hit", async () => { const project = store.createProject(tmp, "demo"); mkdirSync(join(project.path, "src/pages"), { recursive: true }); @@ -3345,3 +3378,59 @@ describe("handleGroundedAsk", () => { expect(answer.uncertainty[0]?.kind).toBe("budget-clipped"); }); }); + +// ADR-0173 D5 g25/g27 — mirrors the buffered desktop chat path's own symmetry fix +// (chat-handlers.test.ts's "desktopChatErrorResult gateway diagnostic symmetry"): grounded Q&A used +// to map a GatewayError straight to a response with no operator diagnostic at all. +describe("mappedGatewayError diagnostic symmetry", () => { + function diagnosticDeps(diagnostics: ServerDiagnosticSink): UiHandlerDeps { + return { + env: {}, + config: undefined, + redactor: (value: unknown): unknown => value, + diagnostics, + } as unknown as UiHandlerDeps; + } + + it("emits an operator diagnostic for a RateLimitError, keyed to the given correlation id", () => { + const events: ServerDiagnosticRecord[] = []; + const deps = diagnosticDeps({ + record: (record): void => { + events.push(record); + }, + }); + + const result = mappedGatewayError( + new RateLimitError("provider rate limited", 1_500), + deps, + "grounded-correlation-1", + ); + + expect(result?.status).toBe(503); + expect(events).toHaveLength(1); + const [event] = events; + if (event === undefined) throw new Error("expected a diagnostic record"); + expect(event.correlationId).toBe("grounded-correlation-1"); + expect(event.operation).toBe("POST /api/chats/messages/grounded"); + expect(event.source).toBe("grounded.qa"); + expect(event.errorClass).toBe("RateLimitError"); + }); + + it("does not diagnose an intentional cancellation", () => { + const events: ServerDiagnosticRecord[] = []; + const deps = diagnosticDeps({ + record: (record): void => { + events.push(record); + }, + }); + + const result = mappedGatewayError( + new CancelledError("grounded request cancelled"), + deps, + "grounded-correlation-2", + ); + + expect(result?.status).toBe(499); + expect(events).toHaveLength(0); + }); +}); diff --git a/packages/keiko-server/src/grounded-qa.ts b/packages/keiko-server/src/grounded-qa.ts index a5c8dc958c..3338e640d0 100644 --- a/packages/keiko-server/src/grounded-qa.ts +++ b/packages/keiko-server/src/grounded-qa.ts @@ -140,6 +140,7 @@ import { evidenceRetentionDiagnosticObserver, emitServerDiagnostic, } from "./diagnostics-log.js"; +import { emitGatewayErrorDiagnostic } from "./gateway-error-diagnostic.js"; import { buildAnswerCitations as projectAnswerCitations, buildPackCitations, @@ -201,19 +202,39 @@ export function gatewayErrorStatus(error: GatewayError): number { return 502; } -function gatewayErrorResult(error: GatewayError, deps: UiHandlerDeps): RouteResult { +// ADR-0173 D5 g25/g27 — mirrors the buffered desktop chat path (`chat-handlers.ts`): a GatewayError +// mapped straight to an HTTP response used to leave no trace in the operator diagnostic sink, unlike +// the SSE chat path, which already routed the same error class through it. A cancellation is the +// caller's own choice, not a failure, so it is excluded — matching the buffered path's convention +// of never diagnosing an intentional cancel. +function gatewayErrorResult( + error: GatewayError, + deps: UiHandlerDeps, + correlationId: string | undefined, +): RouteResult { if (error instanceof CancelledError) { return { status: 499, body: errorBody(error.code, "Grounded request was cancelled.") }; } + emitGatewayErrorDiagnostic( + deps, + error, + correlationId, + "POST /api/chats/messages/grounded", + "grounded.qa", + ); const status = gatewayErrorStatus(error); const message = redact(error.message, currentRedactionSecrets(deps)); return { status, body: errorBody(error.code, message) }; } -export function mappedGatewayError(error: unknown, deps: UiHandlerDeps): RouteResult | undefined { +export function mappedGatewayError( + error: unknown, + deps: UiHandlerDeps, + correlationId?: string, +): RouteResult | undefined { return ( mappedConversationReadinessError(error) ?? - (error instanceof GatewayError ? gatewayErrorResult(error, deps) : undefined) + (error instanceof GatewayError ? gatewayErrorResult(error, deps, correlationId) : undefined) ); } @@ -864,6 +885,7 @@ function createGatewayAnswerer( redactor: Redactor, signal: AbortSignal, modelInputTokensMax: number | undefined, + correlationId: string | undefined, ): GroundedAnswerer { return { answer: async (question, pack): Promise => { @@ -874,6 +896,7 @@ function createGatewayAnswerer( modelId, messages: buildGroundedGatewayMessages(question, pack, redactor, promptOptions), stream: false, + logContext: { correlationId }, }, signal, ); @@ -905,12 +928,70 @@ function resolveGroundedAnswerModel( return withConversationReadinessAdmission(resolvedModel, modelId, readinessAdmission, deps); } +interface DefaultRunnerContext { + readonly deps: UiHandlerDeps; + readonly modelId: string; + readonly signal: AbortSignal; + readonly contextProfile: UiHandlerDeps["contextProfile"]; + readonly model: ModelPort; + readonly modelInputTokensMax: number | undefined; + readonly entailmentStage: EntailmentStage | undefined; + readonly correlationId: string | undefined; +} + +// Split out of defaultRunner to keep it within the line budget: the actual GroundedRunner closure +// invoked once per exploration input. +function runDefaultGroundedExploration( + runnerCtx: DefaultRunnerContext, + input: OrchestratorInput, +): Promise { + const { deps, modelId, signal, contextProfile, model, modelInputTokensMax, entailmentStage } = + runnerCtx; + const nowMs = Date.now; + const budgetedInput = + input.budget === undefined + ? { ...input, budget: modelWindowAwareBudget(deps, modelId) } + : input; + const contextPackReranker = configuredContextPackRerankerFor(deps, budgetedInput.query, signal); + const semanticLease = configuredRepoSemanticSearchProviderLeaseFor( + deps, + signal, + budgetedInput.workspaceRoot, + ); + return runGroundedExploration(budgetedInput, { + answerer: createGatewayAnswerer( + model, + modelId, + deps.redactor, + signal, + modelInputTokensMax, + runnerCtx.correlationId, + ), + nowMs, + signal, + microIndex: microIndexForGroundedScope(budgetedInput.scope, nowMs), + workspaceIndexForRoot: deps.workspaceIndexForRoot, + ...(contextPackReranker === undefined ? {} : { contextPackReranker }), + ...(semanticLease.provider === undefined + ? {} + : { repoSemanticSearchProvider: semanticLease.provider }), + ...(entailmentStage === undefined ? {} : { entailmentStage }), + // ADR-0055 D1/D5 (PR4-W1): thread the provisioned profile so the diagnostics observer fires + // on the assembled pack. exactOptionalPropertyTypes — omit the key entirely when absent so + // the legacy no-profile path stays byte-identical (observer guard never sees a key). + ...(contextProfile === undefined ? {} : { contextProfile }), + }).finally(() => { + semanticLease.close(); + }); +} + function defaultRunner( deps: UiHandlerDeps, modelId: string, readinessAdmission: ConversationReadinessAdmission, signal: AbortSignal, contextProfile: UiHandlerDeps["contextProfile"], + correlationId: string | undefined, ): GroundedRunner | RouteResult { const model = resolveGroundedAnswerModel(deps, modelId, readinessAdmission); if ("status" in model) return model; @@ -925,37 +1006,18 @@ function defaultRunner( { diagnostics: deps.diagnostics }, signal, ); - return (input: OrchestratorInput): Promise => { - const nowMs = Date.now; - const budgetedInput = - input.budget === undefined - ? { ...input, budget: modelWindowAwareBudget(deps, modelId) } - : input; - const contextPackReranker = configuredContextPackRerankerFor(deps, budgetedInput.query, signal); - const semanticLease = configuredRepoSemanticSearchProviderLeaseFor( - deps, - signal, - budgetedInput.workspaceRoot, - ); - return runGroundedExploration(budgetedInput, { - answerer: createGatewayAnswerer(model, modelId, deps.redactor, signal, modelInputTokensMax), - nowMs, - signal, - microIndex: microIndexForGroundedScope(budgetedInput.scope, nowMs), - workspaceIndexForRoot: deps.workspaceIndexForRoot, - ...(contextPackReranker === undefined ? {} : { contextPackReranker }), - ...(semanticLease.provider === undefined - ? {} - : { repoSemanticSearchProvider: semanticLease.provider }), - ...(entailmentStage === undefined ? {} : { entailmentStage }), - // ADR-0055 D1/D5 (PR4-W1): thread the provisioned profile so the diagnostics observer fires - // on the assembled pack. exactOptionalPropertyTypes — omit the key entirely when absent so - // the legacy no-profile path stays byte-identical (observer guard never sees a key). - ...(contextProfile === undefined ? {} : { contextProfile }), - }).finally(() => { - semanticLease.close(); - }); + const runnerCtx: DefaultRunnerContext = { + deps, + modelId, + signal, + contextProfile, + model, + modelInputTokensMax, + entailmentStage, + correlationId, }; + return (input: OrchestratorInput): Promise => + runDefaultGroundedExploration(runnerCtx, input); } // ─── Citation projection ────────────────────────────────────────────────────── @@ -1053,6 +1115,9 @@ interface AskWorkerCtx { readonly deps: UiHandlerDeps; readonly runner: GroundedRunner; readonly signal: AbortSignal; + // ADR-0173 D5 — carried from PreparedGroundedAsk.correlationId so a GatewayError surfacing from + // the runner (or a late cancellation) reaches its operator diagnostic joined to the request. + readonly correlationId: string | undefined; } interface PreparedGroundedAsk { @@ -1067,6 +1132,10 @@ interface PreparedGroundedAsk { readonly memory?: GroundedMemoryPreparation | undefined; readonly modelId?: string | undefined; readonly readinessAdmission?: ConversationReadinessAdmission | undefined; + // ADR-0173 D5: the request-scoped correlation id (RouteContext.correlationId), carried through + // every `{ ...prepared, ... }` preparation stage so the model call at the bottom of the + // orchestrator pipeline can stamp it into GatewayCallRequest.logContext. + readonly correlationId?: string | undefined; } interface GroundedMemoryPreparation { @@ -1289,7 +1358,7 @@ async function runAsk(workerCtx: AskWorkerCtx): Promise { if (!isValidGroundedPack(output.pack)) { return internalError("Grounded answer context pack failed validation."); } - const cancelResult = ensureRouteNotCancelled(workerCtx.signal, deps); + const cancelResult = ensureRouteNotCancelled(workerCtx.signal, deps, workerCtx.correlationId); if (cancelResult !== undefined) return cancelResult; return finalizeGroundedAnswer(workerCtx, output); } @@ -1368,12 +1437,13 @@ function isRouteResult(value: unknown): value is RouteResult { function ensureRouteNotCancelled( signal: AbortSignal, deps: UiHandlerDeps, + correlationId: string | undefined, ): RouteResult | undefined { try { ensureNotCancelled(signal); return undefined; } catch (error) { - const gatewayResult = mappedGatewayError(error, deps); + const gatewayResult = mappedGatewayError(error, deps, correlationId); if (gatewayResult !== undefined) return gatewayResult; throw error; } @@ -1404,7 +1474,7 @@ async function runGroundedRunner( } const workspaceResult = mappedWorkspaceError(error); if (workspaceResult !== undefined) return workspaceResult; - const gatewayResult = mappedGatewayError(error, workerCtx.deps); + const gatewayResult = mappedGatewayError(error, workerCtx.deps, workerCtx.correlationId); if (gatewayResult !== undefined) return gatewayResult; throw error; } @@ -1428,7 +1498,7 @@ async function prepareGroundedAsk( if (parsed.kind === "err") return parsed.result; const chat = findChatById(deps, parsed.value.chatId); if (chat === undefined) return notFound("Chat not found."); - return { chat, input: parsed.value, signal }; + return { chat, input: parsed.value, signal, correlationId: ctx.correlationId }; } function resolveGroundedRunner( @@ -1437,6 +1507,7 @@ function resolveGroundedRunner( readinessAdmission: ConversationReadinessAdmission, signal: AbortSignal, runner: GroundedRunner | undefined, + correlationId: string | undefined, ): | { readonly modelId: string; @@ -1452,7 +1523,14 @@ function resolveGroundedRunner( }; } const contextProfile = currentContextProfileForModel(deps, modelId); - const builtRunner = defaultRunner(deps, modelId, readinessAdmission, signal, contextProfile); + const builtRunner = defaultRunner( + deps, + modelId, + readinessAdmission, + signal, + contextProfile, + correlationId, + ); if (typeof builtRunner !== "function") return builtRunner; return { modelId, contextProfile, runner: builtRunner }; } @@ -1474,6 +1552,7 @@ function resolveMultiSourceSeam( readinessAdmission: ConversationReadinessAdmission, signal: AbortSignal, override: MultiSourceSeam | undefined, + correlationId: string | undefined, ): MultiSourceSeam | RouteResult { if (override !== undefined) return override; const resolvedModel = deps.modelPortFactory(modelId); @@ -1488,7 +1567,7 @@ function resolveMultiSourceSeam( ); return { retriever: defaultRetriever(signal, deps), - answerer: createMultiSourceAnswerer(model, modelId, deps.redactor, signal), + answerer: createMultiSourceAnswerer(model, modelId, deps.redactor, signal, correlationId), }; } @@ -1510,6 +1589,7 @@ async function dispatchMultiSourceAsk( groundedReadinessAdmission(args), signal, seamOverride, + args.correlationId, ); if ("status" in seam) return seam; return runMultiSourceAsk({ @@ -1604,6 +1684,7 @@ async function dispatchFolderAsk( groundedReadinessAdmission(prepared), signal, runner, + prepared.correlationId, ); if ("status" in resolved) return resolved; return runAsk({ @@ -1620,6 +1701,7 @@ async function dispatchFolderAsk( deps, runner: resolved.runner, signal, + correlationId: prepared.correlationId, }); } @@ -1673,6 +1755,7 @@ async function dispatchHybridAsk( contextProfile: currentContextProfileForModel(deps, modelId), deps, signal, + correlationId: prepared.correlationId, readinessAdmission: groundedReadinessAdmission(prepared), preSkippedFolders: skippedFolders.map((s) => ({ label: s.label, @@ -1734,6 +1817,7 @@ async function dispatchPreparedGroundedAsk( deps, prepared.signal, groundedReadinessAdmission(prepared), + prepared.correlationId, ); } return dispatchHybridAsk(preparedWithCanonicalFolders, deps, skippedFolders, hybrid); diff --git a/packages/keiko-server/src/local-knowledge-grounded-qa.ts b/packages/keiko-server/src/local-knowledge-grounded-qa.ts index cde13f1c83..ef04b5692e 100644 --- a/packages/keiko-server/src/local-knowledge-grounded-qa.ts +++ b/packages/keiko-server/src/local-knowledge-grounded-qa.ts @@ -661,6 +661,7 @@ class StoreBackedAnswerGenerator implements AnswerGenerator { private readonly auditSink: ReturnType, private readonly redactExcerpt: (value: string) => string, private readonly limits: ReturnType, + private readonly correlationId: string | undefined, ) {} public async generate(input: AnswerGeneratorInput): Promise { @@ -675,6 +676,7 @@ class StoreBackedAnswerGenerator implements AnswerGenerator { this.limits, ), stream: false, + logContext: { correlationId: this.correlationId }, }, input.signal ?? new AbortController().signal, ); @@ -752,7 +754,11 @@ function uniqueQueryVariants(variants: readonly string[]): readonly string[] { return out; } -function createBroadQueryTransformer(model: ModelPort, modelId: string): QueryTransformer { +function createBroadQueryTransformer( + model: ModelPort, + modelId: string, + correlationId: string | undefined, +): QueryTransformer { return { rewrite: async ({ query, maxVariants, signal }): Promise => { try { @@ -775,6 +781,7 @@ function createBroadQueryTransformer(model: ModelPort, modelId: string): QueryTr }, ], stream: false, + logContext: { correlationId }, }, queryTransformSignal(signal), ); @@ -2213,6 +2220,7 @@ function createScopedAnswerGenerator( deps: UiHandlerDeps, env: { readonly store: KnowledgeStore }, limits: ReturnType, + correlationId: string | undefined, ): StoreBackedAnswerGenerator { return new StoreBackedAnswerGenerator( model, @@ -2221,32 +2229,45 @@ function createScopedAnswerGenerator( createSqliteAuditSink(env.store), (value: string): string => redactText(deps, value), limits, + correlationId, ); } +// The trailing three positional parameters `runScopedGroundedAnswer` used to take (signal, +// readinessAdmission, correlationId) bundled into one object so the function itself stays under +// the repository's 7-parameter ceiling (Sonar S107) as ADR-0173 D5 g9's correlationId threading +// added an 8th. Grouped together because all three travel together for the lifetime of a single +// grounded-ask attempt, unlike `chat`/`input`/`deps`/`env`/`selected`, which each name a different +// piece of state. +interface ScopedGroundedAnswerContext { + readonly signal: AbortSignal; + readonly readinessAdmission: ConversationReadinessAdmission; + readonly correlationId: string | undefined; +} + async function runScopedGroundedAnswer( chat: Chat, input: AskInput, deps: UiHandlerDeps, env: Pick, "store" | "vectorIndex">, selected: SelectedLocalKnowledgeScope, - signal: AbortSignal, - readinessAdmission: ConversationReadinessAdmission, + context: ScopedGroundedAnswerContext, ): Promise { + const { signal, readinessAdmission, correlationId } = context; const embeddingAdapter = createEmbeddingAdapter(deps); if ("status" in embeddingAdapter) return embeddingAdapter; const modelId = input.modelId ?? chat.selectedModel; const model = resolveModel(deps, modelId, readinessAdmission); if ("status" in model) return model; const limits = currentGroundingLimits(deps); - const generator = createScopedAnswerGenerator(model, modelId, deps, env, limits); + const generator = createScopedAnswerGenerator(model, modelId, deps, env, limits, correlationId); const startedAt = Date.now(); const result = await runGroundedAnswer( { retrieval: { store: env.store, embeddingAdapter, - queryTransformer: createBroadQueryTransformer(model, modelId), + queryTransformer: createBroadQueryTransformer(model, modelId, correlationId), vectorIndex: env.vectorIndex, }, answerGenerator: generator, @@ -2344,6 +2365,7 @@ export async function handleLocalKnowledgeGroundedAsk( deps: UiHandlerDeps, signal: AbortSignal, readinessAdmission?: ConversationReadinessAdmission, + correlationId?: string, ): Promise { const modelId = input.modelId ?? chat.selectedModel; const effectiveAdmission = localKnowledgeReadinessAdmission(deps, modelId, readinessAdmission); @@ -2357,15 +2379,11 @@ export async function handleLocalKnowledgeGroundedAsk( if (signal.aborted) throw new CancelledError("grounded request cancelled"); return stateFailureRoute(chat, input, deps, env, selected, stateFailure); } - const answer = await runScopedGroundedAnswer( - chat, - input, - deps, - env, - selected, + const answer = await runScopedGroundedAnswer(chat, input, deps, env, selected, { signal, - effectiveAdmission, - ); + readinessAdmission: effectiveAdmission, + correlationId, + }); if ("status" in answer) return answer; return { status: 200, body: answer }; } catch (error) { diff --git a/packages/keiko-server/src/memory-audit-handler.test.ts b/packages/keiko-server/src/memory-audit-handler.test.ts index e09ecc811b..bb0e247a3d 100644 --- a/packages/keiko-server/src/memory-audit-handler.test.ts +++ b/packages/keiko-server/src/memory-audit-handler.test.ts @@ -281,6 +281,42 @@ describe("createMemoryAuditHandler", () => { expect(errors).toHaveLength(1); }); + it("reports a bridge persistence failure with the SAME date-bucket runId as its correlationId", () => { + // ADR-0173 D5 / g12: the vault-bridge path (createMemoryAuditHandler) reports through the + // diagnostic sink, not onPersistError, so its failure must carry the SAME runId the append + // targeted rather than a disconnected `randomUUID()`. Before the fix this was a random UUID. + const throwingStore: EvidenceStore = { + put: (): string => { + throw Object.assign(new Error("disk full"), { code: "ENOSPC" }); + }, + get: (): string | undefined => undefined, + list: (): readonly string[] => [], + location: (runId: string): string => runId, + delete: (): void => undefined, + }; + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (entry) => { + records.push(entry); + }, + }; + const handler = createMemoryAuditHandler({ + evidenceStore: throwingStore, + redactString: identityRedact, + now: () => FIXED_NOW, + newEventId: makeIdFactory(), + diagnostics, + }); + + expect(() => { + handler({ kind: "memory:inserted", record: makeRecord({ status: "proposed" }) }); + }).not.toThrow(); + + expect(records).toHaveLength(1); + expect(records[0]?.source).toBe("memory-audit-handler.bridge"); + expect(records[0]?.correlationId).toBe(auditRunIdFor(FIXED_NOW)); + }); + it("preserves a corrupt audit manifest instead of resetting it", () => { const store = createInMemoryEvidenceStore(); const runId = auditRunIdFor(FIXED_NOW); @@ -733,6 +769,10 @@ describe("recordMemoryAudits", () => { expect(records[0]?.operation).toBe("memory.audit.persist"); expect(records[0]?.code).toBe("EACCES"); expect(records[0]?.correlationId).toMatch(/^[A-Za-z0-9._-]{8,128}$/); + // ADR-0173 D5 / g12: the failure's correlationId is the SAME date-bucket runId the append + // itself targeted, not a disconnected `randomUUID()` — an operator can join the failure back + // to the bucket it belongs to. Before the fix this was a random UUID. + expect(records[0]?.correlationId).toBe(auditRunIdFor(FIXED_NOW)); // Body-free: the store's path never enters the record. expect(JSON.stringify(records)).not.toContain("/Users/op/.keiko/evidence"); expect(consoleError).not.toHaveBeenCalled(); diff --git a/packages/keiko-server/src/memory-audit-handler.ts b/packages/keiko-server/src/memory-audit-handler.ts index f861828b09..14677881f3 100644 --- a/packages/keiko-server/src/memory-audit-handler.ts +++ b/packages/keiko-server/src/memory-audit-handler.ts @@ -43,6 +43,7 @@ import { createHash, randomUUID } from "node:crypto"; import type { MemoryAuditEvent, MemoryId, MemoryStatus } from "@oscharko-dev/keiko-contracts"; import type { EvidenceStore } from "@oscharko-dev/keiko-evidence"; import type { MemoryEvent } from "@oscharko-dev/keiko-memory-vault"; +import { isValidCorrelationId } from "./correlation.js"; import { buildDeletedEvent, buildInsertedEvent, @@ -91,16 +92,22 @@ interface AuditPersistFailureContext { function reportAuditPersistFailure( options: AuditPersistFailureContext, source: string, + runId: string, error: unknown, ): void { if (options.onPersistError !== undefined) { options.onPersistError(error); return; } + // Reuses the date-bucket runId the failed append targeted (ADR-0173 D5 / g12, mirroring + // gitDelivery/mutationEvidenceLedger.ts's `evidenceCorrelationId`) instead of a disconnected + // fresh mint, so an operator can join this diagnostic back to the SAME bucket's other audit + // evidence. Re-validated against `isValidCorrelationId` rather than trusted blindly. + const correlationId = isValidCorrelationId(runId) ? runId : randomUUID(); emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "memory.audit.persist", source, error, @@ -171,7 +178,7 @@ function parseExistingEvents(json: string | undefined): PersistedMemoryAuditEven try { const parsed: unknown = JSON.parse(json); if (!Array.isArray(parsed)) { - throw new Error("memory audit manifest has unexpected shape"); + throw new TypeError("memory audit manifest has unexpected shape"); } return parsed as PersistedMemoryAuditEvent[]; } catch (error) { @@ -350,12 +357,13 @@ export function createMemoryAuditHandler(options: MemoryAuditHandlerOptions): Me if (auditEvent === undefined) { return; } + const runId = auditRunIdFor(auditEvent.occurredAt); try { - appendAuditEvents(options.evidenceStore, auditRunIdFor(auditEvent.occurredAt), [ + appendAuditEvents(options.evidenceStore, runId, [ sanitizeAuditEvent(auditEvent, options.redactString), ]); } catch (error) { - reportAuditPersistFailure(options, "memory-audit-handler.bridge", error); + reportAuditPersistFailure(options, "memory-audit-handler.bridge", runId, error); } }; } @@ -484,7 +492,7 @@ export function recordMemoryAudits( if (options.required === true) { throw error; } - reportAuditPersistFailure(options, "memory-audit-handler.direct", error); + reportAuditPersistFailure(options, "memory-audit-handler.direct", runId, error); } } } diff --git a/packages/keiko-server/src/memory-conflict-advisory.test.ts b/packages/keiko-server/src/memory-conflict-advisory.test.ts index f77bbc0650..65877a9e2f 100644 --- a/packages/keiko-server/src/memory-conflict-advisory.test.ts +++ b/packages/keiko-server/src/memory-conflict-advisory.test.ts @@ -3,6 +3,7 @@ import { afterEach, describe, expect, it, vi } from "vitest"; import { createDefaultChatCapability, + type GatewayCallRequest, type GatewayConfig, type GatewayRequest, type NormalizedResponse, @@ -250,6 +251,38 @@ describe("enrichReviewItemsWithAdvisory — eligibility carve-out (ADR-0120 D4)" expect(calls).toHaveLength(1); }); + // ADR-0173 D5: this background consolidation job has no live HTTP request in scope, so the job's + // own id is the stable correlation key stamped into the advisory model's GatewayCallRequest.logContext. + it("stamps the job id into the advisory model gateway call's logContext", async () => { + const calls: GatewayRequest[] = []; + const winner = memoryId("mem-winner"); + const loser = memoryId("mem-loser"); + const item: ReviewItem = { + id: "rv-multi-logcontext", + reason: "multi-way-duplicate", + relatedMemoryIds: [winner, loser], + sourceMemoryIds: [winner, loser], + proposedAction: { kind: "merge", winner, losers: [loser] }, + detectedAt: NOW, + }; + const deps = baseDeps( + respondingModel(calls, () => + structuredResponse({ keep: "A", rationale: "Clear duplicate." }), + ), + [], + ); + + await enrichReviewItemsWithAdvisory( + deps, + JOB_ID, + [item], + [record(winner, "Prefers TypeScript."), record(loser, "Prefers TypeScript.")], + ); + + expect(calls).toHaveLength(1); + expect((calls[0] as GatewayCallRequest | undefined)?.logContext?.correlationId).toBe(JOB_ID); + }); + it("is NOT eligible for a potential-conflict pair whose only evidence is a clean negation flip", async () => { const calls: GatewayRequest[] = []; const older = memoryId("mem-old"); diff --git a/packages/keiko-server/src/memory-conflict-advisory.ts b/packages/keiko-server/src/memory-conflict-advisory.ts index 7d0b50859c..2943f2f91c 100644 --- a/packages/keiko-server/src/memory-conflict-advisory.ts +++ b/packages/keiko-server/src/memory-conflict-advisory.ts @@ -233,6 +233,7 @@ async function callAdvisoryModel( modelId: string, prompt: string, responseFormat: ResponseFormat, + jobId: string, ): Promise { const controller = new AbortController(); let timer: ReturnType | undefined; @@ -256,6 +257,7 @@ async function callAdvisoryModel( temperature: 0, topP: 1, responseFormat, + logContext: { correlationId: jobId }, }, controller.signal, ), @@ -406,6 +408,49 @@ function emitAdvisoryPhaseSummary( }); } +interface AdvisoryPhaseSharedContext { + readonly deps: UiHandlerDeps; + readonly jobId: string; + readonly model: ModelPort; + readonly modelId: string; + readonly memoriesById: ReadonlyMap; + readonly policy: CapturePolicyOptions; + readonly startedAt: number; +} + +// Split out of runAdvisoryPhase to keep it within the line budget: one review item's candidate +// gate, cap/budget truncation, and (sequential, ADR-0120 D8) advisory model call. `counts` is +// mutated in place — the caller owns its lifetime across the whole phase. +async function processAdvisoryReviewItem( + ctx: AdvisoryPhaseSharedContext, + item: ReviewItem, + attempted: number, + counts: AdvisoryPhaseCounts, +): Promise<{ readonly item: ReviewItem; readonly attemptedCall: boolean }> { + const candidate = prepareAdvisoryCandidate(item, ctx.memoriesById, ctx.deps.redactor, ctx.policy); + if (candidate === undefined) return { item, attemptedCall: false }; + if (attempted >= MAX_ADVISORY_CALLS_PER_JOB) { + counts.truncatedByCap += 1; + return { item, attemptedCall: false }; + } + if (Date.now() - ctx.startedAt >= ADVISORY_PHASE_BUDGET_MS) { + counts.truncatedByBudget += 1; + return { item, attemptedCall: false }; + } + const call = await callAdvisoryModel( + ctx.model, + ctx.modelId, + candidate.prompt, + advisoryResponseFormat(candidate.labels), + ctx.jobId, + ); + const outcome = advisoryOutcomeFromCall(call, candidate, ctx.deps.redactor, ctx.policy); + return { + item: applyAdvisoryOutcome(item, outcome, ctx.deps, ctx.jobId, counts), + attemptedCall: true, + }; +} + async function runAdvisoryPhase( deps: UiHandlerDeps, jobId: string, @@ -429,35 +474,20 @@ async function runAdvisoryPhase( truncatedByCap: 0, truncatedByBudget: 0, }; - const startedAt = Date.now(); + const sharedCtx: AdvisoryPhaseSharedContext = { + deps, + jobId, + model, + modelId, + memoriesById, + policy, + startedAt: Date.now(), + }; let attempted = 0; for (const item of reviewItems) { - const candidate = prepareAdvisoryCandidate(item, memoriesById, deps.redactor, policy); - if (candidate === undefined) { - enriched.push(item); - continue; - } - if (attempted >= MAX_ADVISORY_CALLS_PER_JOB) { - counts.truncatedByCap += 1; - enriched.push(item); - continue; - } - if (Date.now() - startedAt >= ADVISORY_PHASE_BUDGET_MS) { - counts.truncatedByBudget += 1; - enriched.push(item); - continue; - } - attempted += 1; - // Sequential by design (ADR-0120 D8): bounds concurrency to 1 and keeps the wall-clock - // budget check above accurate between calls, rather than a call-per-item fan-out. - const call = await callAdvisoryModel( - model, - modelId, - candidate.prompt, - advisoryResponseFormat(candidate.labels), - ); - const outcome = advisoryOutcomeFromCall(call, candidate, deps.redactor, policy); - enriched.push(applyAdvisoryOutcome(item, outcome, deps, jobId, counts)); + const result = await processAdvisoryReviewItem(sharedCtx, item, attempted, counts); + enriched.push(result.item); + if (result.attemptedCall) attempted += 1; } emitAdvisoryPhaseSummary(deps, jobId, counts); // Re-check cancellation after the (possibly multi-second) advisory window closes (ADR-0120 diff --git a/packages/keiko-server/src/memory-maintenance-handlers.test.ts b/packages/keiko-server/src/memory-maintenance-handlers.test.ts index c5be638909..3141b00f4a 100644 --- a/packages/keiko-server/src/memory-maintenance-handlers.test.ts +++ b/packages/keiko-server/src/memory-maintenance-handlers.test.ts @@ -30,13 +30,14 @@ import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; const DAY = 864e5; const RETENTION_NOW = Date.parse("2026-08-02T08:00:00.000Z"); -function makeCtx(): RouteContext { +function makeCtx(correlationId?: string): RouteContext { const socket = new Socket(); return { req: {} as RouteContext["req"], res: { socket } as unknown as RouteContext["res"], params: {}, url: new URL("http://127.0.0.1/api/memory/maintenance"), + ...(correlationId === undefined ? {} : { correlationId }), }; } @@ -343,6 +344,59 @@ describe("handleRunMaintenance", () => { expect(JSON.stringify({ result, diagnostics })).not.toContain(raw); }); + it("threads the request's own correlation id into the retention-config-invalid response instead of minting one", () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts) and is already + // in scope in handleRunMaintenance — the failure diagnostic and error body must reuse it, not + // a disconnected randomUUID(). Before the fix handleRunMaintenance discarded ctx entirely + // (bound as `_ctx`), so the response correlationId never matched ctx.correlationId. + const vault = makeVault(); + const diagnostics: ServerDiagnosticRecord[] = []; + const result = handleRunMaintenance( + makeCtx("req-maintenance-thread-01"), + makeDeps({ + memoryVault: vault, + env: { KEIKO_MEMORY_RETENTION_MAX_AGE_DAYS: "not-a-number" }, + diagnostics: { record: (record) => diagnostics.push(record) }, + }), + ); + + expect(result).toMatchObject({ + status: 500, + body: { error: { correlationId: "req-maintenance-thread-01" } }, + }); + expect(diagnostics[0]?.correlationId).toBe("req-maintenance-thread-01"); + }); + + it("threads the request's own correlation id into an autonomy-mode-read failure too, sharing it with the retention read", () => { + // ADR-0173 D5 / g12: resolveMaintenanceAutonomyMode's own default mint only fires when NO id + // is threaded in; the route always threads its one correlationId (from ctx or minted once) so + // an autonomy-mode failure never gets its own disconnected id relative to the SAME call's + // other diagnostics. + const diagnostics: ServerDiagnosticRecord[] = []; + const vault = makeVault(); + const store = createInMemoryUiStore(); + const faultyStore: UiStore = { + ...store, + readMemoryAutonomyPolicy: (): never => { + throw new Error("preference store unavailable"); + }, + }; + handleRunMaintenance( + makeCtx("req-maintenance-autonomy-thread-01"), + makeDeps({ + memoryVault: vault, + store: faultyStore, + diagnostics: { record: (record) => diagnostics.push(record) }, + }), + ); + + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]?.source).toBe( + "memory-maintenance-handlers.resolveMaintenanceAutonomyMode", + ); + expect(diagnostics[0]?.correlationId).toBe("req-maintenance-autonomy-thread-01"); + }); + it("returns a review item instead of auto-superseding a pairwise correction conflict", () => { const vault = makeVault(); const now = Date.now(); @@ -776,6 +830,37 @@ describe("maybeRunAutoMaintenance (O-V4)", () => { expect(JSON.stringify(diagnostics)).not.toContain("customer content"); }); + it("mints ONE correlation id shared by every diagnostic of a single auto-maintenance pass, not one per failure point", () => { + // ADR-0173 D5 / g12: before the fix, resolveMemoryRetentionPolicy's own catch and this + // function's onFailure catch each minted a disconnected randomUUID() — an operator could not + // tell two diagnostics from the SAME opportunistic pass apart from two diagnostics from two + // different passes. A malformed retention env (read at pass start) AND a vault fault (surfaced + // through onFailure) now both report under the SAME id. + const diagnostics: ServerDiagnosticRecord[] = []; + const faulty = { + ...makeVault(), + listMemoriesAcrossScopes: () => { + throw new Error("disk gone"); + }, + } as MemoryVaultStore; + + maybeRunChatAutoMaintenance( + makeDeps({ + env: { KEIKO_MEMORY_RETENTION_MAX_AGE_DAYS: "not-a-number" }, + diagnostics: { record: (record) => diagnostics.push(record) }, + }), + faulty, + {}, + NOW, + ); + + const sources = diagnostics.map((record) => record.source); + expect(sources).toContain("memory-maintenance-handlers.resolveMemoryRetentionPolicy"); + expect(sources).toContain("chat.memory.maintenance"); + const ids = new Set(diagnostics.map((record) => record.correlationId)); + expect(ids.size).toBe(1); + }); + it("promotes nothing when no autonomy mode is supplied (fail closed to governed-assist)", () => { const vault = makeVault(); insert(vault, { diff --git a/packages/keiko-server/src/memory-maintenance-handlers.ts b/packages/keiko-server/src/memory-maintenance-handlers.ts index 732e250730..d84b8b2aa0 100644 --- a/packages/keiko-server/src/memory-maintenance-handlers.ts +++ b/packages/keiko-server/src/memory-maintenance-handlers.ts @@ -593,14 +593,22 @@ export function memoryMaintenanceAuditSink(deps: UiHandlerDeps): MemoryAuditSink // never widen authority and must never break the caller (the chat path runs this pass), so an // unreadable policy row degrades to the most restrictive posture — no unattended acceptance — and // is reported as a content-free operator diagnostic rather than swallowed. -export function resolveMaintenanceAutonomyMode(deps: UiHandlerDeps): CodingWorkbenchMode { +// +// `correlationId` defaults to a fresh mint ONLY so a caller with no id in scope keeps compiling +// unchanged (ADR-0173 D5 / g12). The route caller (`handleRunMaintenance`) threads its own +// request id; the chat auto-maintenance caller mints ONE id for its whole pass and threads that, +// so a route request or a background pass never fragments across disconnected mints. +export function resolveMaintenanceAutonomyMode( + deps: UiHandlerDeps, + correlationId: string = randomUUID(), +): CodingWorkbenchMode { try { return resolveMemoryMaintenanceAutonomyMode(deps); } catch (error) { emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "memory.maintenance.autonomy-mode", source: "memory-maintenance-handlers.resolveMaintenanceAutonomyMode", error, @@ -611,8 +619,11 @@ export function resolveMaintenanceAutonomyMode(deps: UiHandlerDeps): CodingWorkb } } -function reportRetentionPolicyFailure(deps: UiHandlerDeps, error: unknown): string { - const correlationId = randomUUID(); +function reportRetentionPolicyFailure( + deps: UiHandlerDeps, + error: unknown, + correlationId: string = randomUUID(), +): string { emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ @@ -630,22 +641,26 @@ export type MemoryRetentionPolicyResolution = | { readonly ok: true; readonly policy: MemoryRetentionPolicy | undefined } | { readonly ok: false }; -export function resolveMemoryRetentionPolicy(deps: UiHandlerDeps): MemoryRetentionPolicyResolution { +export function resolveMemoryRetentionPolicy( + deps: UiHandlerDeps, + correlationId?: string, +): MemoryRetentionPolicyResolution { try { return { ok: true, policy: memoryRetentionPolicy(deps.env) }; } catch (error) { - reportRetentionPolicyFailure(deps, error); + reportRetentionPolicyFailure(deps, error, correlationId); return { ok: false }; } } function manualRetentionPolicy( deps: UiHandlerDeps, + correlationId: string, ): MemoryRetentionPolicy | undefined | RouteResult { try { return memoryRetentionPolicy(deps.env); } catch (error) { - const correlationId = reportRetentionPolicyFailure(deps, error); + reportRetentionPolicyFailure(deps, error, correlationId); return { status: 500, body: errorBody( @@ -657,15 +672,19 @@ function manualRetentionPolicy( } } -export function handleRunMaintenance(_ctx: RouteContext, deps: UiHandlerDeps): RouteResult { +export function handleRunMaintenance(ctx: RouteContext, deps: UiHandlerDeps): RouteResult { const vault = resolveVault(deps); if (isRouteResult(vault)) return vault; + // Minted once so a caller who supplied no id (RouteContext.correlationId is optional for test + // literals) still shares ONE id across every diagnostic this single route invocation reports, + // rather than each helper minting its own (ADR-0173 D5 / g12). + const correlationId = ctx.correlationId ?? randomUUID(); try { const multipliers = memorySemanticizationMultipliers(deps.env); - const retentionPolicy = manualRetentionPolicy(deps); + const retentionPolicy = manualRetentionPolicy(deps, correlationId); if (isRouteResult(retentionPolicy)) return retentionPolicy; const counts = runMemoryMaintenance(vault, memoryMaintenanceAuditSink(deps), { - autonomyMode: resolveMaintenanceAutonomyMode(deps), + autonomyMode: resolveMaintenanceAutonomyMode(deps, correlationId), ...(multipliers !== undefined ? { decayHalfLifeMultiplierByType: multipliers } : {}), ...(retentionPolicy !== undefined ? { retentionPolicy } : {}), }); diff --git a/packages/keiko-server/src/memory-salience.test.ts b/packages/keiko-server/src/memory-salience.test.ts index 85fd5bbd1d..f26d9596fe 100644 --- a/packages/keiko-server/src/memory-salience.test.ts +++ b/packages/keiko-server/src/memory-salience.test.ts @@ -8,7 +8,11 @@ import { join } from "node:path"; import { createMemoryVault, type MemoryVaultStore } from "@oscharko-dev/keiko-memory-vault"; import type { NormalizedResponse } from "@oscharko-dev/keiko-contracts"; import type { ModelPort } from "@oscharko-dev/keiko-harness"; -import type { GatewayConfig, GatewayRequest } from "@oscharko-dev/keiko-model-gateway"; +import type { + GatewayCallRequest, + GatewayConfig, + GatewayRequest, +} from "@oscharko-dev/keiko-model-gateway"; import type { ConversationId, MemoryRecord, @@ -317,6 +321,10 @@ describe("captureSalientFromTurn", () => { expect.objectContaining({ errorClass: "SalienceCaptureDropped", message: "voice salience capture skipped: background queue full (32/32)", + // ADR-0173 D5 / g12: this informational diagnostic used to mint its own disconnected + // `randomUUID()` instead of reusing the turn-scoped id the caller already resolved + // (`"assistant-dropped"`, the correlationId argument below). Fails before the fix. + correlationId: "assistant-dropped", }), ); @@ -356,6 +364,75 @@ describe("captureSalientFromTurn", () => { expect(countMemories(vault, ctx)).toBe(3); }); + // ADR-0173 D5 / g12: the capture-summary diagnostic used to mint its own disconnected + // `randomUUID()` instead of the turn-scoped id `captureSalientFromTurn` already resolved, so a + // successful turn's summary line could never be joined to that same turn's other diagnostics. + // Fails before the fix (the summary's correlationId would be an unrelated fresh UUID). + it("carries the turn's correlation id on the capture summary diagnostic", async () => { + const vault = makeVault(); + const diagnostics = { record: vi.fn<(record: ServerDiagnosticRecord) => void>() }; + const deps = makeDeps({ memoryVault: vault, diagnostics }); + + const actions = await captureSalientFromTurn( + deps, + { content: USER_TEXT, memory: { enabled: true } }, + context(), + "gpt-test", + "Sounds like a great project!", + "desktop", + "assistant-summary-turn", + ); + + expect(actions.length).toBeGreaterThan(0); + expect(diagnostics.record).toHaveBeenCalledWith( + expect.objectContaining({ + errorClass: "SalienceCaptureSummary", + correlationId: "assistant-summary-turn", + }), + ); + }); + + // ADR-0173 D5: the same turn-scoped correlation id must also reach the salience model.call's + // GatewayCallRequest.logContext, not only the diagnostic above, so a gateway retry line for this + // extraction joins the turn's trail. + it("stamps the turn's correlation id into the salience model gateway call's logContext", async () => { + const vault = makeVault(); + const seenRequests: GatewayCallRequest[] = []; + const recordingModel: ModelPort = { + call(request): Promise { + seenRequests.push(request); + return Promise.resolve({ + modelId: request.modelId, + content: ATLAS_FACTS, + finishReason: "stop", + toolCalls: [], + structuredOutput: null, + usage: { + requestId: "salience-logcontext-test", + promptTokens: 7, + completionTokens: 3, + latencyMs: 11, + costClass: "high", + }, + }); + }, + }; + const deps = makeDeps({ memoryVault: vault, modelPortFactory: () => recordingModel }); + + await captureSalientFromTurn( + deps, + { content: USER_TEXT, memory: { enabled: true } }, + context(), + "gpt-test", + "Sounds like a great project!", + "desktop", + "assistant-logcontext-turn", + ); + + expect(seenRequests.length).toBeGreaterThan(0); + expect(seenRequests[0]?.logContext?.correlationId).toBe("assistant-logcontext-turn"); + }); + it("keeps a failed model response body out of operator diagnostics", async () => { const bodyMarker = "fixture-salience-provider-body-marker"; const vault = makeVault(); diff --git a/packages/keiko-server/src/memory-salience.ts b/packages/keiko-server/src/memory-salience.ts index a45fac6dd3..d803875a13 100644 --- a/packages/keiko-server/src/memory-salience.ts +++ b/packages/keiko-server/src/memory-salience.ts @@ -170,6 +170,7 @@ function buildSalienceContext(context: ConversationMemoryRuntimeContext): Captur function buildCallModel( deps: UiHandlerDeps, modelId: string, + correlationId: string, ): NonNullable | null { const model = deps.modelPortFactory(modelId); if (model === undefined) { @@ -185,6 +186,7 @@ function buildCallModel( stream: false, ...(responseFormat !== undefined ? { responseFormat } : {}), ...(seed !== undefined ? { seed } : {}), + logContext: { correlationId }, }, new AbortController().signal, ); @@ -218,14 +220,19 @@ function salienceSeedFor(deps: UiHandlerDeps, modelId: string): number | undefin // redaction-safe server diagnostic sink (diagnostics-log.ts) instead of console.* directly, mirroring // the emitAdvisoryPhaseSummary pattern in memory-conflict-advisory.ts. errorClass doubles as a // machine-readable event-kind tag for non-error informational records (e.g. a capture summary). +// `correlationId` is always the turn-scoped id `captureSalientFromTurn` already resolved (or its +// own fallback default) — never minted fresh here — so an informational salience diagnostic joins +// the SAME trail as that turn's eventual failure diagnostic (`emitSalienceFailureDiagnostic`) +// instead of reporting under a disconnected, unrelated id. function emitSalienceDiagnostic( deps: UiHandlerDeps, + correlationId: string, source: string, errorClass: string, message: string, ): void { emitServerDiagnostic(deps.diagnostics, { - correlationId: randomUUID(), + correlationId, timestamp: new Date().toISOString(), operation: "memory.salience", source, @@ -238,6 +245,7 @@ function logSalienceDiagnostic( diagnostic: SalienceDiagnostic, deps: UiHandlerDeps, modelId: string, + correlationId: string, ): void { const responseFormatEnabled = salienceResponseFormatFor(deps, modelId) !== undefined; const detail = @@ -247,6 +255,7 @@ function logSalienceDiagnostic( // Safe diagnostic: model id, response-format bit, and counts only; never user text or model text. emitSalienceDiagnostic( deps, + correlationId, "memory-salience.logSalienceDiagnostic", "SalienceExtractionDiagnostic", `model=${modelId} responseFormat=${String(responseFormatEnabled)} kind=${diagnostic.kind} ${detail}`, @@ -470,9 +479,14 @@ function logSalienceCaptureFailure( ); } -function logSalienceCaptureDropped(surface: SalienceCaptureSurface, deps: UiHandlerDeps): void { +function logSalienceCaptureDropped( + surface: SalienceCaptureSurface, + deps: UiHandlerDeps, + correlationId: string, +): void { emitSalienceDiagnostic( deps, + correlationId, "memory-salience.scheduleMemorySalienceCapture", "SalienceCaptureDropped", `${surface} salience capture skipped: background queue full (${String( @@ -494,7 +508,7 @@ export function scheduleMemorySalienceCapture( return; } if (pendingSalienceCaptures >= MAX_PENDING_SALIENCE_CAPTURES) { - logSalienceCaptureDropped(surface, deps); + logSalienceCaptureDropped(surface, deps, correlationId); return; } pendingSalienceCaptures += 1; @@ -522,17 +536,29 @@ type TurnSalienceExtraction = | { readonly kind: "refused"; readonly reason: RejectionReason } | { readonly kind: "outcomes"; readonly outcomes: readonly CaptureOutcome[] }; +// The per-turn scalars `extractTurnSalienceOutcomes` and `runSalienceCapture` both thread through +// unchanged, bundled into one parameter so neither function's positional-argument count crosses +// the repository's 7-argument ceiling (Sonar S107) now that g9's correlationId threading added an +// 8th to each. `SalienceCaptureInputs` extends this with the one field `runSalienceCapture` alone +// needs (`surface`), rather than widening this shape for a field `extractTurnSalienceOutcomes` +// never reads. +interface TurnSalienceInputs { + readonly modelId: string; + readonly assistantText: string; + readonly correlationId: string; +} + async function extractTurnSalienceOutcomes( deps: UiHandlerDeps, vault: MemoryVaultStore, request: SalienceTurnRequest, context: ConversationMemoryRuntimeContext, captureContext: CaptureContext, - modelId: string, - assistantText: string, + inputs: TurnSalienceInputs, ): Promise { + const { modelId, assistantText, correlationId } = inputs; const salienceModelId = configuredSalienceModelId(deps, modelId); - const callModelMessages = buildCallModel(deps, salienceModelId); + const callModelMessages = buildCallModel(deps, salienceModelId, correlationId); if (callModelMessages === null) return { kind: "unavailable" }; const policy = memoryCapturePolicyForDeps(deps); const refusalReason = memoryTextSecretEgressRejectionReason(request.content, policy); @@ -556,7 +582,7 @@ async function extractTurnSalienceOutcomes( newMemoryId: captureContext.newMemoryId, newProposalId: captureContext.newProposalId, onDiagnostic: (diagnostic) => { - logSalienceDiagnostic(diagnostic, deps, salienceModelId); + logSalienceDiagnostic(diagnostic, deps, salienceModelId, correlationId); }, }, ); @@ -599,9 +625,11 @@ function logSalienceCaptureSummary( mode: CodingWorkbenchMode, summary: SalienceCaptureSummary, deps: UiHandlerDeps, + correlationId: string, ): void { emitSalienceDiagnostic( deps, + correlationId, "memory-salience.captureSalientFromTurn", "SalienceCaptureSummary", `mode=${mode} proposed=${String(summary.proposed)} accepted=${String(summary.accepted)} ` + @@ -655,6 +683,42 @@ function activeSalienceVault( return request.memory?.enabled === true ? deps.memoryVault : undefined; } +interface SalienceCaptureInputs extends TurnSalienceInputs { + readonly surface: SalienceCaptureSurface; +} + +// The turn-scoped work `captureSalientFromTurn` runs inside its own try/catch. Split out so that +// function's own body stays a thin boundary (resolve the vault, catch, report) — everything that +// can throw lives here instead. +async function runSalienceCapture( + deps: UiHandlerDeps, + vault: MemoryVaultStore, + request: SalienceTurnRequest, + context: ConversationMemoryRuntimeContext, + inputs: SalienceCaptureInputs, +): Promise { + const { surface, correlationId } = inputs; + const mode = resolveMemoryCaptureAutonomyMode(deps, request.memory?.mode); + const captureContext = buildSalienceContext(context); + const extraction = await extractTurnSalienceOutcomes( + deps, + vault, + request, + context, + captureContext, + inputs, + ); + if (extraction.kind === "unavailable") return []; + if (extraction.kind === "refused") { + recordTurnCaptureRefusal(deps, mode, surface, context, captureContext.nowMs, extraction.reason); + return []; + } + const { outcomes } = extraction; + const { actions, summary } = await persistSalienceActions(deps, vault, outcomes, mode, surface); + if (outcomes.length > 0) logSalienceCaptureSummary(mode, summary, deps, correlationId); + return actions; +} + // Captures salient memories from a completed chat turn. Never throws — any failure (model error, // vault error, malformed output) yields [] so the chat response is unaffected. Direct callers that // do not own a committed message id receive one capture-scoped fallback correlation id; post-commit @@ -671,33 +735,12 @@ export async function captureSalientFromTurn( const vault = activeSalienceVault(deps, request); if (vault === undefined) return []; try { - const mode = resolveMemoryCaptureAutonomyMode(deps, request.memory?.mode); - const captureContext = buildSalienceContext(context); - const extraction = await extractTurnSalienceOutcomes( - deps, - vault, - request, - context, - captureContext, + return await runSalienceCapture(deps, vault, request, context, { modelId, assistantText, - ); - if (extraction.kind === "unavailable") return []; - if (extraction.kind === "refused") { - recordTurnCaptureRefusal( - deps, - mode, - surface, - context, - captureContext.nowMs, - extraction.reason, - ); - return []; - } - const { outcomes } = extraction; - const { actions, summary } = await persistSalienceActions(deps, vault, outcomes, mode, surface); - if (outcomes.length > 0) logSalienceCaptureSummary(mode, summary, deps); - return actions; + surface, + correlationId, + }); } catch (error) { // Boundary: salience must never break the chat path. Log and continue. emitSalienceFailureDiagnostic( diff --git a/packages/keiko-server/src/qualityIntelligence/__tests__/figmaSnapshotAdapter.test.ts b/packages/keiko-server/src/qualityIntelligence/__tests__/figmaSnapshotAdapter.test.ts index e699622d47..39499e440f 100644 --- a/packages/keiko-server/src/qualityIntelligence/__tests__/figmaSnapshotAdapter.test.ts +++ b/packages/keiko-server/src/qualityIntelligence/__tests__/figmaSnapshotAdapter.test.ts @@ -11,6 +11,7 @@ import { join } from "node:path"; import { describe, expect, it } from "vitest"; import { parseGatewayConfig } from "@oscharko-dev/keiko-model-gateway"; import type { + GatewayCallRequest, GatewayRequest, ModelCapability, NormalizedResponse, @@ -431,6 +432,47 @@ describe("makeFigmaVisionHintProvider", () => { } }); + // ADR-0173 D5: this vision pass has no live HTTP request in scope (a background Figma snapshot + // run), so the snapshot run id is the natural correlation key stamped into the vision model's + // GatewayCallRequest.logContext. + it("stamps the snapshot run id into the vision model gateway call's logContext", async () => { + const dir = mkdtempSync(join(tmpdir(), "qi-figma-adapter-vision-logcontext-")); + const seenRequests: GatewayRequest[] = []; + try { + const { loaded, screen } = recordVisionSnapshot(dir); + const port: ModelPort = { + call: (request) => { + seenRequests.push(request); + return Promise.resolve(normalizedResponse(JSON.stringify({ hints: [] }), "vision-low")); + }, + }; + const deps = depsWith({ + config: configWith([ + capability("vision-low", { supportsImageInput: true, supportsResponseFormat: true }), + ]), + configPresent: true, + evidenceDir: dir, + modelPortFactory: () => port, + }); + + const provider = makeFigmaVisionHintProvider(deps); + await provider({ + snapshotRunId: loaded.runId, + screenId: screen.screenId, + image: screen.image, + imageRelativePath: screen.image.relativePath, + baselineText: "Screen: Login [s1]", + }); + + expect(seenRequests).toHaveLength(1); + expect((seenRequests[0] as GatewayCallRequest | undefined)?.logContext?.correlationId).toBe( + loaded.runId, + ); + } finally { + rmSync(dir, { recursive: true, force: true }); + } + }); + it("omits strict response format when the image model lacks structured output", async () => { const dir = mkdtempSync(join(tmpdir(), "qi-figma-adapter-vision-tolerant-")); const seenRequests: GatewayRequest[] = []; diff --git a/packages/keiko-server/src/qualityIntelligence/__tests__/generationPort.test.ts b/packages/keiko-server/src/qualityIntelligence/__tests__/generationPort.test.ts index 5c8dba1665..eda2b626ae 100644 --- a/packages/keiko-server/src/qualityIntelligence/__tests__/generationPort.test.ts +++ b/packages/keiko-server/src/qualityIntelligence/__tests__/generationPort.test.ts @@ -6,6 +6,7 @@ import { afterEach, describe, expect, it, vi } from "vitest"; import type { + GatewayCallRequest, GatewayRequest, ModelCapability, NormalizedResponse, @@ -846,6 +847,18 @@ describe("createQiGenerationPort.generate — determinism-first parameters", () expect(result.modelParameters?.responseFormatEnforced).toBe(false); }); + // ADR-0173 D5: the run id supplied to createQiGenerationPort must reach the model.call so a + // gateway retry/circuit-breaker line for this generation stage joins the run's other lines. + it("stamps the supplied correlation id into the GatewayCallRequest.logContext", async () => { + const { deps, calls } = depsFor("chat-model-1"); + const port = createQiGenerationPort(deps, "chat-model-1", "cid-qi-generation-000001"); + await port.generate(args()); + expect(calls).toHaveLength(1); + expect((calls[0]?.request as GatewayCallRequest | undefined)?.logContext?.correlationId).toBe( + "cid-qi-generation-000001", + ); + }); + it("does not send a seed when the model does not advertise seeding support", async () => { const { deps, calls } = depsFor("unseeded-model"); const port = createPort(deps, { diff --git a/packages/keiko-server/src/qualityIntelligence/__tests__/judgePort.test.ts b/packages/keiko-server/src/qualityIntelligence/__tests__/judgePort.test.ts index dfb1966225..ac9fd87b4f 100644 --- a/packages/keiko-server/src/qualityIntelligence/__tests__/judgePort.test.ts +++ b/packages/keiko-server/src/qualityIntelligence/__tests__/judgePort.test.ts @@ -4,6 +4,7 @@ import { afterEach, describe, expect, it, vi } from "vitest"; import type { + GatewayCallRequest, GatewayRequest, ModelCapability, NormalizedResponse, @@ -683,6 +684,24 @@ describe("createQiJudgePort.judge — gateway call", () => { expect(verdict.gatewayCallCount).toBe(1); }); + // ADR-0173 D5: the caller's correlation id (a run id or an HTTP request id) must reach the + // judge's model.call so a gateway retry/circuit-breaker line for this judge stage joins the + // same trail as the run/request that triggered it. + it("stamps the supplied correlation id into the GatewayCallRequest.logContext", async () => { + const { deps, calls } = depsFor("chat-model-1", VALID_VERDICT_JSON); + const port = createQiJudgePort(deps, "chat-model-1", { + correlationId: "cid-qi-judge-000001", + }); + await port.judge({ + candidateText: "candidate text", + sourceContext: [{ atomId: "atom-1", text: "REQ-1" }], + }); + expect(calls).toHaveLength(1); + expect((calls[0]?.request as GatewayCallRequest | undefined)?.logContext?.correlationId).toBe( + "cid-qi-judge-000001", + ); + }); + it("uses stream: false in the gateway request", async () => { const { deps, calls } = depsFor("chat-model-1", VALID_VERDICT_JSON); const port = createQiJudgePort(deps, "chat-model-1"); diff --git a/packages/keiko-server/src/qualityIntelligence/figmaSnapshotAdapter.ts b/packages/keiko-server/src/qualityIntelligence/figmaSnapshotAdapter.ts index 4ae2b45034..d2cd8be5c2 100644 --- a/packages/keiko-server/src/qualityIntelligence/figmaSnapshotAdapter.ts +++ b/packages/keiko-server/src/qualityIntelligence/figmaSnapshotAdapter.ts @@ -22,7 +22,7 @@ import { type FigmaSnapshotImageRef, type FigmaSnapshotRecord, } from "@oscharko-dev/keiko-evidence"; -import type { GatewayRequest } from "@oscharko-dev/keiko-model-gateway"; +import type { GatewayCallRequest } from "@oscharko-dev/keiko-model-gateway"; import type { UiHandlerDeps } from "../deps.js"; import { resolveQiMultimodalSelection } from "./modelSelection.js"; @@ -228,7 +228,7 @@ function buildVisionRequest( dataUrl: string, baselineText: string, structuredOutput: boolean, -): GatewayRequest { +): GatewayCallRequest { const userText = visionUserText(request, baselineText); return { modelId, @@ -256,6 +256,9 @@ function buildVisionRequest( responseFormat: VISION_RESPONSE_FORMAT, } : {}), + // The Figma snapshot run id is the natural background-job correlation key here: this vision + // pass has no live HTTP request in scope (ADR-0173 D5, background-run case). + logContext: { correlationId: request.snapshotRunId }, }; } diff --git a/packages/keiko-server/src/qualityIntelligence/generationPort.ts b/packages/keiko-server/src/qualityIntelligence/generationPort.ts index a975937690..26e4d0db37 100644 --- a/packages/keiko-server/src/qualityIntelligence/generationPort.ts +++ b/packages/keiko-server/src/qualityIntelligence/generationPort.ts @@ -13,7 +13,7 @@ import { findConfiguredCapability, QualityIntelligenceSafeErrorException, type ChatMessage, - type GatewayRequest, + type GatewayCallRequest, type ModelCapability, } from "@oscharko-dev/keiko-model-gateway"; import { @@ -285,7 +285,8 @@ function buildGenerationRequest( useSeed: boolean, requestedSeed: number | undefined, signal: AbortSignal, -): GatewayRequest { + correlationId: string | undefined, +): GatewayCallRequest { return { modelId, messages, @@ -304,6 +305,7 @@ function buildGenerationRequest( }, } : {}), + logContext: { correlationId }, }; } @@ -336,6 +338,7 @@ function abortErrorForGeneration(reasonKind: "timeout" | "external" | "none"): E // eslint-disable-next-line max-lines-per-function function createModelGenerationPort( resolved: ResolvedGenerationModel, + correlationId: string | undefined, ): QualityIntelligenceGenerationPort { const { model, modelId, useResponseFormat, useSeed, requestedSeed } = resolved; return { @@ -354,6 +357,7 @@ function createModelGenerationPort( useSeed, requestedSeed, cancellation.signal, + correlationId, ); let removeAbortListener = (): void => { /* not attached yet */ @@ -393,10 +397,11 @@ function createModelGenerationPort( export function createQiGenerationPort( deps: UiHandlerDeps, target: QiGenerationTarget, + correlationId?: string, ): QualityIntelligenceGenerationPort { const normalized = normalizeTarget(target); if (normalized.kind === "baseline") { return createBaselineGenerationPort(); } - return createModelGenerationPort(resolveGenerationModel(deps, normalized)); + return createModelGenerationPort(resolveGenerationModel(deps, normalized), correlationId); } diff --git a/packages/keiko-server/src/qualityIntelligence/handoffRoutes.ts b/packages/keiko-server/src/qualityIntelligence/handoffRoutes.ts index ec9c3ffde3..e7e03c6cef 100644 --- a/packages/keiko-server/src/qualityIntelligence/handoffRoutes.ts +++ b/packages/keiko-server/src/qualityIntelligence/handoffRoutes.ts @@ -317,7 +317,7 @@ const startHandoffRun = (deps: UiHandlerDeps, roots: readonly string[]): string const runPromise = currentGatewayConfig(deps) === undefined ? execute() - : buildQiModelRoutingForRun(deps, {}).then((modelRouting) => execute(modelRouting)); + : buildQiModelRoutingForRun(deps, {}, runId).then((modelRouting) => execute(modelRouting)); void runPromise .then((summary) => { qiRunRegistry.complete(runId, summary.status); diff --git a/packages/keiko-server/src/qualityIntelligence/judgePort.ts b/packages/keiko-server/src/qualityIntelligence/judgePort.ts index 0d995d1139..6074e5ffb0 100644 --- a/packages/keiko-server/src/qualityIntelligence/judgePort.ts +++ b/packages/keiko-server/src/qualityIntelligence/judgePort.ts @@ -14,6 +14,7 @@ import { findConfiguredCapability, QualityIntelligenceSafeErrorException, type ChatMessage, + type GatewayCallRequest, type GatewayRequest, type ModelCapability, } from "@oscharko-dev/keiko-model-gateway"; @@ -217,6 +218,9 @@ const JUDGE_TASK_PROFILE = MgQI.getQualityIntelligenceTaskProfile("qi:judge-logi export interface QiJudgePortOptions { readonly requestedSeed?: number | undefined; + // The request/run correlation id (ADR-0173 D5), stamped into every judge model call's + // GatewayCallRequest.logContext so a judge-stage gateway line joins the run's other lines. + readonly correlationId?: string | undefined; } function isRubricDimensionName(value: string): value is TestQualityDimensionName { @@ -469,7 +473,7 @@ export function createQiJudgePort( }; } const cancellation = MgQI.composeCancellationSignal(JUDGE_TASK_PROFILE.timeoutMsHint, signal); - const request: GatewayRequest = { + const request: GatewayCallRequest = { modelId, messages, stream: false, @@ -477,6 +481,7 @@ export function createQiJudgePort( temperature: 0, ...(useSeed ? { seed: requestedSeed } : {}), responseFormat: buildQiJudgeResponseFormat(), + logContext: { correlationId: options.correlationId }, }; let removeAbortListener = (): void => { /* not attached yet */ diff --git a/packages/keiko-server/src/qualityIntelligence/modelPolicyRoutes.ts b/packages/keiko-server/src/qualityIntelligence/modelPolicyRoutes.ts index e41673e3be..10ee5519a1 100644 --- a/packages/keiko-server/src/qualityIntelligence/modelPolicyRoutes.ts +++ b/packages/keiko-server/src/qualityIntelligence/modelPolicyRoutes.ts @@ -18,7 +18,7 @@ import { listConfiguredCapabilities, findConfiguredCapability, } from "@oscharko-dev/keiko-model-gateway"; -import type { GatewayRequest, ModelCapability } from "@oscharko-dev/keiko-model-gateway"; +import type { GatewayCallRequest, ModelCapability } from "@oscharko-dev/keiko-model-gateway"; import type { QualityIntelligenceModelPolicy, QualityIntelligenceModelPolicyPreflightResponse, @@ -324,9 +324,10 @@ function requestForPreflight( stage: "generate" | "judge", modelId: string, _capability: ModelCapability, -): GatewayRequest { + correlationId: string | undefined, +): GatewayCallRequest { if (stage === "judge") { - return buildQiJudgePreflightRequest(modelId); + return { ...buildQiJudgePreflightRequest(modelId), logContext: { correlationId } }; } return { modelId, @@ -340,37 +341,38 @@ function requestForPreflight( content: "Quality Intelligence preflight.", }, ], + logContext: { correlationId }, }; } -async function preflightStage( +function unavailablePreflightResult( + stage: "generate" | "judge", + modelId?: string, +): QualityIntelligenceModelPreflightStageResult { + return { + stage, + ...(modelId === undefined ? {} : { modelId }), + status: "unavailable", + category: "unavailable", + message: preflightMessage("unavailable"), + }; +} + +// Split out of preflightStage to keep it within the line budget: the actual gateway round trip +// plus its schema/transport failure classification. +async function runPreflightGatewayCall( deps: UiHandlerDeps, stage: "generate" | "judge", - modelId: string | undefined, + modelId: string, + capability: ModelCapability, + correlationId: string | undefined, ): Promise { - const config = currentGatewayConfig(deps); - if (modelId === undefined || config === undefined) { - return { - stage, - status: "unavailable", - category: "unavailable", - message: preflightMessage("unavailable"), - }; - } - const capability = findConfiguredCapability(config, modelId); - if (capability?.kind !== "chat") { - return { - stage, - modelId, - status: "unavailable", - category: "unavailable", - message: preflightMessage("unavailable"), - }; - } try { const gateway = currentGateway(deps); if (gateway === undefined) throw new TypeError("Model gateway is unavailable."); - const response = await gateway.chat(requestForPreflight(stage, modelId, capability)); + const response = await gateway.chat( + requestForPreflight(stage, modelId, capability, correlationId), + ); if (stage === "judge" && tryParseJudgeVerdict(response.content) === null) { return { stage, @@ -393,6 +395,23 @@ async function preflightStage( } } +async function preflightStage( + deps: UiHandlerDeps, + stage: "generate" | "judge", + modelId: string | undefined, + correlationId: string | undefined, +): Promise { + const config = currentGatewayConfig(deps); + if (modelId === undefined || config === undefined) { + return unavailablePreflightResult(stage); + } + const capability = findConfiguredCapability(config, modelId); + if (capability?.kind !== "chat") { + return unavailablePreflightResult(stage, modelId); + } + return runPreflightGatewayCall(deps, stage, modelId, capability, correlationId); +} + function preflightSummaryStatus( generation: QualityIntelligenceModelPreflightStageResult, judge: QualityIntelligenceModelPreflightStageResult | undefined, @@ -417,6 +436,7 @@ function summarizePreflight( export async function buildQiModelRouting( deps: UiHandlerDeps, request: Pick, + correlationId?: string, ): Promise { const requested = policyForRequest(deps, request); const resolution = resolveQiModelPolicy(deps, { ...request, modelPolicy: requested }); @@ -426,11 +446,16 @@ export async function buildQiModelRouting( "The selected Quality Intelligence model policy is invalid.", ); } - const generation = await preflightStage(deps, "generate", resolution.resolved.testDesignModelId); + const generation = await preflightStage( + deps, + "generate", + resolution.resolved.testDesignModelId, + correlationId, + ); const judge = resolution.resolved.judgeModelId === undefined - ? await preflightStage(deps, "judge", undefined) - : await preflightStage(deps, "judge", resolution.resolved.judgeModelId); + ? await preflightStage(deps, "judge", undefined, correlationId) + : await preflightStage(deps, "judge", resolution.resolved.judgeModelId, correlationId); return { policyVersion: 1, requested, @@ -466,8 +491,9 @@ function judgePreflightFailureReason(routing: QualityIntelligenceModelRouting): export async function buildQiModelRoutingForRun( deps: UiHandlerDeps, request: Pick, + correlationId?: string, ): Promise { - const routing = await buildQiModelRouting(deps, request); + const routing = await buildQiModelRouting(deps, request, correlationId); const generation = routing.preflight.generation; if (generation?.status !== "passed" && routing.resolved.testDesignModelId !== undefined) { throw new QiModelPolicyError( @@ -516,7 +542,7 @@ export async function handlePutQiModelPolicy( ); } try { - await buildQiModelRoutingForRun(deps, { modelPolicy: policy }); + await buildQiModelRoutingForRun(deps, { modelPolicy: policy }, ctx.correlationId); } catch (error) { if (error instanceof QiModelPolicyError) { return errorResult(400, error.code, error.message); @@ -558,10 +584,14 @@ export async function handlePreflightQiModelPolicy( ); } try { - const modelRouting = await buildQiModelRouting(deps, { - ...(modelPolicy !== undefined ? { modelPolicy } : {}), - ...(typeof parsed.modelId === "string" ? { modelId: parsed.modelId } : {}), - }); + const modelRouting = await buildQiModelRouting( + deps, + { + ...(modelPolicy !== undefined ? { modelPolicy } : {}), + ...(typeof parsed.modelId === "string" ? { modelId: parsed.modelId } : {}), + }, + ctx.correlationId, + ); const body: QualityIntelligenceModelPolicyPreflightResponse = { modelRouting }; return { status: 200, body }; } catch (error) { diff --git a/packages/keiko-server/src/qualityIntelligence/reCheckRoutes.ts b/packages/keiko-server/src/qualityIntelligence/reCheckRoutes.ts index a2bca527e5..c08fe172e4 100644 --- a/packages/keiko-server/src/qualityIntelligence/reCheckRoutes.ts +++ b/packages/keiko-server/src/qualityIntelligence/reCheckRoutes.ts @@ -313,8 +313,9 @@ async function parseSources(req: IncomingMessage): Promise function buildJudgePortIfAvailable( deps: UiHandlerDeps, modelId: string, + correlationId: string, ): ReturnType | undefined { - const outcome = tryCreateQiJudgePort(deps, modelId); + const outcome = tryCreateQiJudgePort(deps, modelId, { correlationId }); return outcome.available ? outcome.port : undefined; } @@ -1056,6 +1057,7 @@ function regenWorkflowDeps( evidenceStore: ReturnType, capture: (cands: readonly QiTestCaseCandidate[], generatedAt: string) => void, signal: AbortSignal, + newRunId: string, ): QualityIntelligenceModelRoutedTestDesignDeps { return { sink: { emit: () => undefined }, @@ -1066,7 +1068,7 @@ function regenWorkflowDeps( capture(cands, generatedAt); }, }, - generate: createQiGenerationPort(deps, target), + generate: createQiGenerationPort(deps, target, newRunId), // The regenerate-stale judge deliberately shares the auto-selected generation model id rather than // resolving an independent qi:judge-logic model the way the initial run does (runExecution.ts). // This is safe because the regen target comes from resolveQiTestDesignSelection(deps) with NO @@ -1077,7 +1079,9 @@ function regenWorkflowDeps( // asymmetry — an explicitly requested chat-only generation model paired with a separate // structured-output judge — cannot arise here because the regen path never carries an explicit // generation-model request. - ...(target.kind === "model" ? { judge: buildJudgePortIfAvailable(deps, target.modelId) } : {}), + ...(target.kind === "model" + ? { judge: buildJudgePortIfAvailable(deps, target.modelId, newRunId) } + : {}), }; } @@ -1101,6 +1105,7 @@ async function executeScopedWorkflow(args: { readonly atomsToRegenerate: readonly QualityIntelligenceIngestedAtom[]; readonly profile: PolicyProfile; readonly signal: AbortSignal; + readonly newRunId: string; }): Promise { const { deps, @@ -1112,6 +1117,7 @@ async function executeScopedWorkflow(args: { atomsToRegenerate, profile, signal, + newRunId, } = args; try { const summary = await runQualityIntelligenceModelRoutedTestDesign( @@ -1122,7 +1128,7 @@ async function executeScopedWorkflow(args: { provenanceRefs: ingestion.provenanceRefs, profile, }, - regenWorkflowDeps(deps, target, evidenceStore, capture, signal), + regenWorkflowDeps(deps, target, evidenceStore, capture, signal, newRunId), ); return summary.status === "succeeded" ? null @@ -1183,6 +1189,7 @@ async function runScopedEphemeral(args: { atomsToRegenerate, profile, signal, + newRunId, }); if (failure !== null) return { ok: false, result: failure }; return finalizeScopedWorkflow(evidenceStore, newRunId, generatedCandidates, generatedAt); diff --git a/packages/keiko-server/src/qualityIntelligence/runExecution.ts b/packages/keiko-server/src/qualityIntelligence/runExecution.ts index 4caaff8c8f..80047dfd66 100644 --- a/packages/keiko-server/src/qualityIntelligence/runExecution.ts +++ b/packages/keiko-server/src/qualityIntelligence/runExecution.ts @@ -112,6 +112,7 @@ function resolveExecutionStrategy( deps: UiHandlerDeps, request: QualityIntelligenceStartRunRequest, modelRouting: QualityIntelligenceModelRouting, + runId: string, ): ResolvedExecutionStrategy { const modelId = modelRouting.resolved.testDesignModelId; const config = currentGatewayConfig(deps); @@ -125,7 +126,7 @@ function resolveExecutionStrategy( // attribution contract and persist `seedUsed: null` when the model cannot apply the seed. if (modelId === undefined) { return { - generate: createQiGenerationPort(deps, { kind: "baseline" }), + generate: createQiGenerationPort(deps, { kind: "baseline" }, runId), }; } if ( @@ -136,16 +137,20 @@ function resolveExecutionStrategy( }) ) { return { - generate: createQiGenerationPort(deps, { kind: "baseline" }), + generate: createQiGenerationPort(deps, { kind: "baseline" }, runId), }; } return { modelId, - generate: createQiGenerationPort(deps, { - kind: "model", - modelId, - requestedSeed: request.seed, - }), + generate: createQiGenerationPort( + deps, + { + kind: "model", + modelId, + requestedSeed: request.seed, + }, + runId, + ), }; } @@ -281,11 +286,12 @@ async function runResolvedQi( const { deps, runId, request } = input; const requestedRouting = buildExecutionRouting(input); const { ingestion, gatewayCallCount } = await ingestForRun(input, capsuleResolver); - const { modelId, generate } = resolveExecutionStrategy(deps, request, requestedRouting); + const { modelId, generate } = resolveExecutionStrategy(deps, request, requestedRouting, runId); const resolvedJudge = resolveJudgeForModelRun( deps, requestedRouting.resolved.judgeModelId, request.seed, + runId, ); // The routing the run actually executes under carries the judge degradation, so `onAccepted`, // the persisted manifest, and the terminal `done` frame all report the same classified failure. @@ -354,9 +360,10 @@ function resolveJudgeForModelRun( deps: UiHandlerDeps, judgeModelId: string | undefined, requestedSeed: number | undefined, + correlationId: string, ): ResolvedJudge { if (judgeModelId === undefined) return {}; - const outcome = tryCreateQiJudgePort(deps, judgeModelId, { requestedSeed }); + const outcome = tryCreateQiJudgePort(deps, judgeModelId, { requestedSeed, correlationId }); return outcome.available ? { judge: outcome.port } : { stageFailureReason: outcome.reasonSummary }; diff --git a/packages/keiko-server/src/qualityIntelligence/runRoutes.ts b/packages/keiko-server/src/qualityIntelligence/runRoutes.ts index 2684eee50d..325c87f7a0 100644 --- a/packages/keiko-server/src/qualityIntelligence/runRoutes.ts +++ b/packages/keiko-server/src/qualityIntelligence/runRoutes.ts @@ -616,7 +616,7 @@ export async function handleStartQiRun( let modelRouting: QualityIntelligenceModelRouting; try { - modelRouting = await buildQiModelRoutingForRun(deps, parsed.request); + modelRouting = await buildQiModelRoutingForRun(deps, parsed.request, runId); } catch (error) { qiRunRegistry.complete(runId, "failed"); if (error instanceof QiModelPolicyError) { diff --git a/packages/keiko-server/src/run-engine.test.ts b/packages/keiko-server/src/run-engine.test.ts index 4d888ad325..57e8c61a9b 100644 --- a/packages/keiko-server/src/run-engine.test.ts +++ b/packages/keiko-server/src/run-engine.test.ts @@ -323,6 +323,35 @@ describe("probeNetworkIsolationSafely", () => { expect(probeSafely("/nonexistent/workspace")).toBe(false); }); + it("threads the dispatching run's own id into the failure diagnostic instead of a disconnected mint", async () => { + // ADR-0173 D5 / g12: dispatchWorkflow/applyRun both have a runId in scope when they call this + // probe; the probe failure diagnostic must carry THAT id (via the default stderr sink, which + // this test observes through console.error) rather than a fresh randomUUID() unrelated to the + // run whose verification enforcement it affects. + vi.resetModules(); + const actualVerification = await vi.importActual< + typeof import("./editor/verificationExecution.js") + >("./editor/verificationExecution.js"); + vi.doMock("./editor/verificationExecution.js", () => ({ + ...actualVerification, + probeNetworkIsolation: (): never => { + throw new Error("probe backend detection failed"); + }, + })); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => undefined); + try { + const { probeNetworkIsolationSafely: probeSafely } = await import("./run-engine.js"); + const runId = `run-${randomUUID()}`; + expect(probeSafely("/nonexistent/workspace", runId)).toBe(false); + expect(consoleError).toHaveBeenCalledTimes(1); + const line = consoleError.mock.calls[0]?.[0] as string; + const record = JSON.parse(line.slice(line.indexOf("{"))) as { correlationId?: unknown }; + expect(record.correlationId).toBe(runId); + } finally { + consoleError.mockRestore(); + } + }); + it.each([true, false])( "passes through the real probe's available:%s without swallowing it", async (available) => { @@ -377,4 +406,49 @@ describe("applyRun — verification egress probe threading", () => { expect(capturedDeps).toBeDefined(); expect(typeof capturedDeps?.verificationEnforcedNetworkAvailable).toBe("boolean"); }); + + it("threads the replayed run's own runId into a probe failure during apply", async () => { + // ADR-0173 D5 / g12: run-handlers.ts's gated apply path always has the run's own runId in + // scope (RunRecord.runId); a probe failure during the replayed verify stage must carry it + // rather than a disconnected randomUUID(). + vi.resetModules(); + const actualWorkflows = await vi.importActual( + "@oscharko-dev/keiko-workflows", + ); + vi.doMock("@oscharko-dev/keiko-workflows", () => ({ + ...actualWorkflows, + generateUnitTests: (): Promise => Promise.resolve({ status: "completed" }), + })); + const actualVerification = await vi.importActual< + typeof import("./editor/verificationExecution.js") + >("./editor/verificationExecution.js"); + vi.doMock("./editor/verificationExecution.js", () => ({ + ...actualVerification, + probeNetworkIsolation: (): never => { + throw new Error("probe backend detection failed"); + }, + })); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => undefined); + try { + const { applyRun: apply } = await import("./run-engine.js"); + const runId = `run-${randomUUID()}`; + + await apply( + { kind: "unit-tests", payload: { workspaceRoot }, limits: undefined }, + { call: () => Promise.reject(new Error("unused")) }, + "m", + (value) => value, + undefined, + runId, + ); + + expect(consoleError).toHaveBeenCalledTimes(1); + const line = consoleError.mock.calls[0]?.[0] as string; + const record = JSON.parse(line.slice(line.indexOf("{"))) as { correlationId?: unknown }; + expect(record.correlationId).toBe(runId); + } finally { + consoleError.mockRestore(); + vi.doUnmock("./editor/verificationExecution.js"); + } + }); }); diff --git a/packages/keiko-server/src/run-engine.ts b/packages/keiko-server/src/run-engine.ts index cf53ebda5f..94555b3986 100644 --- a/packages/keiko-server/src/run-engine.ts +++ b/packages/keiko-server/src/run-engine.ts @@ -257,12 +257,15 @@ function cancelWorkflow(controller: AbortController): (reason?: string) => void // run at all — never fail open into an unenforced network:"none" step. A failure is still recorded // through the server's single redacted diagnostic sink (no cwd, no raw error text — a content-free // error class only) so a probe that starts failing is operator-visible, not silently swallowed. -export function probeNetworkIsolationSafely(cwd: string): boolean { +export function probeNetworkIsolationSafely(cwd: string, runId?: string): boolean { try { return probeNetworkIsolation(cwd).available; } catch (error) { emitServerDiagnostic(undefined, { - correlationId: randomUUID(), + // Threads the dispatching run's own id (ADR-0173 D5 / g12) when the caller has one in + // scope, rather than a disconnected mint, so this probe failure joins the SAME run's other + // diagnostics. + correlationId: runId ?? randomUUID(), timestamp: new Date().toISOString(), operation: "workflow.network-isolation-probe", source: "run-engine.probeNetworkIsolationSafely", @@ -276,36 +279,47 @@ export function probeNetworkIsolationSafely(cwd: string): boolean { // Starts the underlying run for a workflow request: an AbortController drives cancellation (the // workflow honours deps.signal), and the BFF-owned runId is injected as the workflow idSource so the // streamed events carry the same runId the registry/SSE key on. +// Split out of dispatchWorkflow purely to keep that function's line count under the repository +// limit as the probe-correlation threading grew it; behavior is unchanged from before the split. +function dispatchWorkflowMemoryDeps( + ctx: EngineContext, + runId: string, +): { readonly memoryPort?: ReturnType } { + if (ctx.memoryVault === undefined || ctx.evidence === undefined) return {}; + return { + memoryPort: createWorkflowMemoryPort({ + vault: ctx.memoryVault, + evidenceStore: ctx.evidence.store, + runId, + redactString: ctx.memoryAuditRedactString ?? ((input: string): string => input), + ...(ctx.memoryCustomerIdentifierMatchers === undefined + ? {} + : { customerIdentifierMatchers: ctx.memoryCustomerIdentifierMatchers }), + }), + }; +} + function dispatchWorkflow(ctx: EngineContext, sink: QueueEventSink, runId: string): Dispatched { const controller = new AbortController(); const ports = governedWorkflowPorts(ctx); + // Probe THIS host for an enforcing egress backend and hand the answer to the verify stage, the + // same probe-then-enforce composition the editor verification path uses (ADR-0043 D8). Threads + // this dispatch's own runId (ADR-0173 D5 / g12) into a probe-failure diagnostic. + const verificationEnforcedNetworkAvailable = probeNetworkIsolationSafely( + workspaceRoot(ctx.request), + runId, + ); const commonDeps = { model: ports.model, ...(ports.spawn === undefined ? {} : { spawn: ports.spawn }), - // Probe THIS host for an enforcing egress backend and hand the answer to the verify stage, the - // same probe-then-enforce composition the editor verification path uses. Without it the stage - // could only ever see "no backend available" and had to choose between denying every - // network:"none" step and running model-authored code with inherited network (ADR-0043 D8). - verificationEnforcedNetworkAvailable: probeNetworkIsolationSafely(workspaceRoot(ctx.request)), + verificationEnforcedNetworkAvailable, sink, signal: controller.signal, idSource: (): string => runId, ...(ctx.request.governedHandoff === undefined ? {} : { workflowHandoff: ctx.request.governedHandoff }), - ...(ctx.memoryVault !== undefined && ctx.evidence !== undefined - ? { - memoryPort: createWorkflowMemoryPort({ - vault: ctx.memoryVault, - evidenceStore: ctx.evidence.store, - runId, - redactString: ctx.memoryAuditRedactString ?? ((input: string): string => input), - ...(ctx.memoryCustomerIdentifierMatchers === undefined - ? {} - : { customerIdentifierMatchers: ctx.memoryCustomerIdentifierMatchers }), - }), - } - : {}), + ...dispatchWorkflowMemoryDeps(ctx, runId), }; if (ctx.request.kind === "unit-tests") { const result = generateUnitTests(unitTestInput(ctx.request), commonDeps).then((report) => ({ @@ -649,6 +663,10 @@ export async function applyRun( modelId: string, redactReport: (value: unknown) => unknown, governance?: AgentRunGovernanceBinding, + // The originating run's own id (ADR-0173 D5 / g12), threaded into the re-invoked verify stage's + // network-isolation probe so a probe failure joins the SAME run's other diagnostics rather than + // a disconnected mint. + runId?: string, ): Promise { const input = isRecord(snapshot.payload) ? snapshot.payload : {}; const limitsOverride = snapshot.limits !== undefined ? { limits: snapshot.limits } : {}; @@ -672,7 +690,7 @@ export async function applyRun( // Apply replays an accepted snapshot through the same verify stage the initial dispatch used // (dispatchWorkflow above); without this, a governed apply's network:"none" steps see no probe // result and are denied even on hosts an enforcing backend IS available on (ADR-0043 D8). - verificationEnforcedNetworkAvailable: probeNetworkIsolationSafely(root), + verificationEnforcedNetworkAvailable: probeNetworkIsolationSafely(root, runId), ...(snapshot.governedHandoff === undefined ? {} : { workflowHandoff: snapshot.governedHandoff }), diff --git a/packages/keiko-server/src/run-handlers.test.ts b/packages/keiko-server/src/run-handlers.test.ts index b3cf950582..78c372aa01 100644 --- a/packages/keiko-server/src/run-handlers.test.ts +++ b/packages/keiko-server/src/run-handlers.test.ts @@ -1330,3 +1330,82 @@ describe("apply re-proves workspace authorization at the write boundary", () => expect(modelCalls).toEqual([]); }); }); + +describe("apply threads the run's own id into its verification egress probe", () => { + afterEach(() => { + vi.doUnmock("./editor/verificationExecution.js"); + vi.resetModules(); + }); + + it("passes record.runId through to the network-isolation probe failure diagnostic, not a disconnected mint", async () => { + // ADR-0173 D5 / g12: run-handlers.ts's gated apply path always has RunRecord.runId in scope; + // a network-isolation probe failure reached through the replayed verify stage must carry it. + vi.resetModules(); + const actualVerification = await vi.importActual< + typeof import("./editor/verificationExecution.js") + >("./editor/verificationExecution.js"); + vi.doMock("./editor/verificationExecution.js", () => ({ + ...actualVerification, + probeNetworkIsolation: (): never => { + throw new Error("probe backend detection failed"); + }, + })); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => undefined); + try { + const { handleApplyRun: freshHandleApplyRun } = await import("./index.js"); + const registry = createRunRegistry(); + const workspace = authorizedApplyWorkspace(); + registry.register({ + runId: "probe-thread-run", + fingerprint: "fp-probe-thread-run", + modelId: "example-chat-model", + sink: new QueueEventSink(), + cancel: (): void => undefined, + }); + registry.complete( + "probe-thread-run", + "completed", + { status: "dry-run" }, + { + kind: "unit-tests", + payload: { workspaceRoot: workspace.root, target: { kind: "file", filePath: "x.ts" } }, + limits: undefined, + }, + ); + const deps: UiHandlerDeps = { + config: undefined, + configPresent: false, + evidenceStore: createInMemoryEvidenceStore(), + env: {}, + redactor: buildRedactor({}), + registry, + store: workspace.store, + modelPortFactory: (): ModelPort => ({ + call: (): Promise => Promise.reject(new Error("test-stop")), + }), + }; + + const result = await freshHandleApplyRun( + { + req: {} as never, + res: {} as never, + params: { runId: "probe-thread-run" }, + url: new URL("http://127.0.0.1/api/runs/probe-thread-run/apply"), + }, + deps, + ); + + expect(result.status).toBe(200); + expect(consoleError).toHaveBeenCalled(); + const diagnosticCall = consoleError.mock.calls.find((call) => + String(call[0]).includes("workflow.network-isolation-probe"), + ); + expect(diagnosticCall).toBeDefined(); + const line = String(diagnosticCall?.[0]); + const record = JSON.parse(line.slice(line.indexOf("{"))) as { correlationId?: unknown }; + expect(record.correlationId).toBe("probe-thread-run"); + } finally { + consoleError.mockRestore(); + } + }); +}); diff --git a/packages/keiko-server/src/run-handlers.ts b/packages/keiko-server/src/run-handlers.ts index 22fcd95873..9e4d89074d 100644 --- a/packages/keiko-server/src/run-handlers.ts +++ b/packages/keiko-server/src/run-handlers.ts @@ -689,7 +689,14 @@ export async function handleApplyRun(ctx: RouteContext, deps: UiHandlerDeps): Pr const budgetRejection = reserveAgentRunApplyBudget(record, snapshot); if (budgetRejection !== null) return budgetRejection; record.appliable = undefined; - const report = await applyRun(snapshot, model, record.modelId, deps.redactor, record.governance); + const report = await applyRun( + snapshot, + model, + record.modelId, + deps.redactor, + record.governance, + record.runId, + ); record.applyReport = report; record.appliedAt = Date.now(); return { diff --git a/packages/keiko-server/src/sse-write.test.ts b/packages/keiko-server/src/sse-write.test.ts index dafaa2f780..eb76be3cb7 100644 --- a/packages/keiko-server/src/sse-write.test.ts +++ b/packages/keiko-server/src/sse-write.test.ts @@ -4,7 +4,12 @@ // must never break the protective abort+destroy path. import { describe, expect, it, vi } from "vitest"; import type { ServerResponse } from "node:http"; -import { writeOrDestroy, type SseBackpressureSignal } from "./sse-write.js"; +import { + sseBackpressureReporter, + writeOrDestroy, + type SseBackpressureSignal, +} from "./sse-write.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; function fakeRes(writeReturns: boolean): { res: ServerResponse; @@ -94,3 +99,35 @@ describe("writeOrDestroy backpressure signal (GEN-PERF-CHAT-006)", () => { expect(destroy).toHaveBeenCalledTimes(1); }); }); + +// ADR-0173 D5 / g12: `sseBackpressureReporter` used to mint a fresh `randomUUID()` INSIDE the +// returned closure on every backpressure signal. A caller with the stream's own request/session id +// already in scope had no way to thread it through, and — the sharper defect — two signals from +// the SAME reporter (the same SSE stream) reported under two disconnected ids. +describe("sseBackpressureReporter correlation id (ADR-0173 D5 / g12)", () => { + it("threads a caller-supplied correlation id onto the backpressure diagnostic", () => { + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { record: (record) => records.push(record) }; + const observe = sseBackpressureReporter({ diagnostics }, "terminal", "req-abc12345"); + + observe({ frameBytes: 42, accepted: false }); + + expect(records).toHaveLength(1); + expect(records[0]?.correlationId).toBe("req-abc12345"); + }); + + it("mints one id per reporter construction, shared across every signal that reporter emits", () => { + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { record: (record) => records.push(record) }; + const observeA = sseBackpressureReporter({ diagnostics }, "terminal"); + const observeB = sseBackpressureReporter({ diagnostics }, "terminal"); + + observeA({ frameBytes: 1, accepted: false }); + observeA({ frameBytes: 2, accepted: false }); + observeB({ frameBytes: 3, accepted: false }); + + expect(records).toHaveLength(3); + expect(records[0]?.correlationId).toBe(records[1]?.correlationId); + expect(records[0]?.correlationId).not.toBe(records[2]?.correlationId); + }); +}); diff --git a/packages/keiko-server/src/sse-write.ts b/packages/keiko-server/src/sse-write.ts index f356844e58..6f05dc2cef 100644 --- a/packages/keiko-server/src/sse-write.ts +++ b/packages/keiko-server/src/sse-write.ts @@ -65,14 +65,21 @@ export function writeOrDestroy( * happens either way, but nothing records WHY the stream ended. * * Carries only the frame byte count (never body bytes), so it cannot leak model tokens if logged. + * + * `correlationId` defaults to a fresh mint taken ONCE here, at reporter-construction time (i.e. at + * SSE stream setup) — not inside the returned closure, which fires at most once anyway, but + * minting eagerly lets a caller that already has the stream's own request/session id in scope + * (ADR-0173 D5 / g12) pass it straight through instead of a disconnected one being drawn if and + * only if the stream is later killed. */ export function sseBackpressureReporter( deps: { readonly diagnostics?: ServerDiagnosticSink | undefined }, stream: string, + correlationId: string = randomUUID(), ): (signal: SseBackpressureSignal) => void { return (signal: SseBackpressureSignal): void => { emitServerDiagnostic(deps.diagnostics, { - correlationId: randomUUID(), + correlationId, timestamp: new Date().toISOString(), operation: `sse.${stream}`, source: `sse.${stream}.backpressure`, diff --git a/packages/keiko-server/src/terminal-routes.test.ts b/packages/keiko-server/src/terminal-routes.test.ts index 506de94db7..c91b40bc19 100644 --- a/packages/keiko-server/src/terminal-routes.test.ts +++ b/packages/keiko-server/src/terminal-routes.test.ts @@ -14,8 +14,10 @@ import { createRunRegistry } from "./runs.js"; import { createUiServer, UI_HOST } from "./server.js"; import { EventEmitter } from "node:events"; import type { ServerResponse } from "node:http"; -import { openTerminalSseStream } from "./terminal-routes.js"; +import { handleTerminalEvents, openTerminalSseStream } from "./terminal-routes.js"; import type { SseBackpressureSignal } from "./sse-write.js"; +import type { RouteContext } from "./routes.js"; +import type { ServerDiagnosticRecord, ServerDiagnosticSink } from "./diagnostics-log.js"; import { TerminalToolError, type TerminalEventEmitter, @@ -644,3 +646,31 @@ describe("openTerminalSseStream backpressure (KEIKO-0142)", () => { expect(fake.writes.length).toBeGreaterThan(1); }); }); + +describe("handleTerminalEvents backpressure correlation (ADR-0173 D5 / g12)", () => { + it("threads the request's own correlation id into the backpressure diagnostic instead of minting one", () => { + const fake = makeFakeSseRes(); + fake.writeReturns = false; // rejects the ready frame -> immediate backpressure kill. + const manager = new FakeTerminalExecutionManager(); + const records: ServerDiagnosticRecord[] = []; + const diagnostics: ServerDiagnosticSink = { + record: (entry) => { + records.push(entry); + }, + }; + const ctx: RouteContext = { + req: { on: (): void => undefined } as unknown as RouteContext["req"], + res: fake.res, + params: {}, + url: new URL("http://127.0.0.1/api/terminal/events"), + correlationId: "req-terminal-thread-01", + }; + const routeDeps: UiHandlerDeps = { ...deps, terminal: manager, diagnostics }; + + handleTerminalEvents(ctx, routeDeps); + + expect(records).toHaveLength(1); + expect(records[0]?.source).toBe("sse.terminal.backpressure"); + expect(records[0]?.correlationId).toBe("req-terminal-thread-01"); + }); +}); diff --git a/packages/keiko-server/src/terminal-routes.ts b/packages/keiko-server/src/terminal-routes.ts index a153b709b7..2c58188122 100644 --- a/packages/keiko-server/src/terminal-routes.ts +++ b/packages/keiko-server/src/terminal-routes.ts @@ -227,7 +227,14 @@ export function handleDeleteTerminalExecution(ctx: RouteContext, deps: UiHandler export function handleTerminalEvents(ctx: RouteContext, deps: UiHandlerDeps): HandlerOutcome { const guard = requireTerminal(deps); if (isRouteResult(guard)) return guard; - openTerminalSseStream(ctx.res, guard, deps.redactor, sseBackpressureReporter(deps, "terminal")); + // Threads the request's own correlation id (ADR-0173 D5 / g12) so a later backpressure kill + // joins back to the request that opened this stream instead of a disconnected mint. + openTerminalSseStream( + ctx.res, + guard, + deps.redactor, + sseBackpressureReporter(deps, "terminal", ctx.correlationId), + ); ctx.req.on("close", () => { ctx.res.end(); }); diff --git a/packages/keiko-server/src/update-remediation-routes.test.ts b/packages/keiko-server/src/update-remediation-routes.test.ts index 085823d458..49dedac9e7 100644 --- a/packages/keiko-server/src/update-remediation-routes.test.ts +++ b/packages/keiko-server/src/update-remediation-routes.test.ts @@ -54,6 +54,7 @@ function report(): UpdateRemediationStatusReport { class FakeUpdateRemediationManager implements UpdateRemediationManager { public readonly statuses: UpdateRemediationStatusRequest[] = []; public readonly actions: UpdateRemediationActionRequest[] = []; + public readonly runActionCorrelationIds: (string | undefined)[] = []; public readonly getStatus = ( request: UpdateRemediationStatusRequest = {}, @@ -64,8 +65,10 @@ class FakeUpdateRemediationManager implements UpdateRemediationManager { public readonly runAction = ( request: UpdateRemediationActionRequest, + correlationId?: string, ): Promise => { this.actions.push(request); + this.runActionCorrelationIds.push(correlationId); return Promise.resolve({ ...report(), overallStatus: "completed", updateCanComplete: true }); }; @@ -198,4 +201,21 @@ describe("update remediation routes", () => { actionId: "local-knowledge-reindex:local-knowledge", }); }); + + it("threads the request's own correlation id into runAction instead of leaving it to mint one", async () => { + // ADR-0173 D5 / g12: ctx.correlationId is minted at request entry (server.ts, honouring a + // well-formed client-supplied X-Keiko-Correlation-Id) and was already in scope in + // handleRunUpdateRemediationAction — before the fix it was never threaded into runAction, so + // every diagnostic runAction's own implementation reports minted an id disconnected from this + // request's trail. + const requestCorrelationId = "req-update-remediation-thread-01"; + const action = await fetch(`${baseUrl()}/api/update/remediation/actions`, { + method: "POST", + headers: { ...csrfHeaders(), "X-Keiko-Correlation-Id": requestCorrelationId }, + body: JSON.stringify({ actionId: "local-knowledge-reindex:local-knowledge" }), + }); + + expect(action.status).toBe(200); + expect(updateRemediation.runActionCorrelationIds).toEqual([requestCorrelationId]); + }); }); diff --git a/packages/keiko-server/src/update-remediation-routes.ts b/packages/keiko-server/src/update-remediation-routes.ts index 5128a96c23..f90a652584 100644 --- a/packages/keiko-server/src/update-remediation-routes.ts +++ b/packages/keiko-server/src/update-remediation-routes.ts @@ -124,6 +124,8 @@ export async function handleRunUpdateRemediationAction( if (!parsed.ok) { throw new UpdateRemediationError("BAD_REQUEST", parsed.errors.join("; "), 400); } - return { status: 200, body: await guard.runAction(parsed.value) }; + // Threads the request's own correlation id (ADR-0173 D5 / g12) so every diagnostic this one + // remediation action reports stays joined under it, per runAction's own contract. + return { status: 200, body: await guard.runAction(parsed.value, ctx.correlationId) }; }); } diff --git a/packages/keiko-server/src/update-remediation.test.ts b/packages/keiko-server/src/update-remediation.test.ts index 0076d8e2a6..d03d2e40fd 100644 --- a/packages/keiko-server/src/update-remediation.test.ts +++ b/packages/keiko-server/src/update-remediation.test.ts @@ -684,6 +684,66 @@ describe("update remediation manager", () => { expect(localKnowledge.runs()).toBe(1); }); + // ADR-0173 D5 / g12: each of `recordDraftFailure`'s call sites used to mint its own + // `randomUUID()`, so a cascade of failures inside a SINGLE `runAction` call (persist fails, then + // the outcome-uncertainty fallback also fails) reported as if they were unrelated operations. + // Fails before the fix — two independent random UUIDs practically never match — and passes after, + // once every reporter reads the one id `runAction` mints at its own start. + it("shares one correlation id across every diagnostic from a single failing action run", async () => { + const diagnostics: ServerDiagnosticRecord[] = []; + const localKnowledge = fakeLocalKnowledge(); + const durable = createUpdateLocalStateManager({ stateDir: makeStateDir(), now: () => NOW }); + let stateWrites = 0; + const unreliable: UpdateLocalStateManager = { + ...durable, + writeRuntimeState: (state) => { + stateWrites += 1; + if (stateWrites >= 2) throw new Error("terminal state unavailable"); + return durable.writeRuntimeState(state); + }, + }; + const subject = createUpdateRemediationManager({ + localState: unreliable, + localKnowledge, + now: () => NOW, + diagnostics: { record: (record) => diagnostics.push(record) }, + }); + + await subject.runAction({ + actionId: "local-knowledge-reindex:local-knowledge", + targetVersion: TARGET, + impact: localKnowledgeImpact, + }); + + const sources = diagnostics.map((record) => record.source); + expect(sources).toContain("update-remediation.persistDraftStatus"); + expect(sources).toContain("update-remediation.persistOutcomeUncertainty"); + const correlationIds = new Set(diagnostics.map((record) => record.correlationId)); + expect(correlationIds.size).toBe(1); + }); + + it("threads a caller-supplied correlation id through onto every reported diagnostic", async () => { + const diagnostics: ServerDiagnosticRecord[] = []; + const subject = createUpdateRemediationManager({ + localState: createUpdateLocalStateManager({ stateDir: makeStateDir(), now: () => NOW }), + localKnowledge: throwingLocalKnowledge(), + now: () => NOW, + diagnostics: { record: (record) => diagnostics.push(record) }, + redactString: (value) => value, + }); + + await subject.runAction( + { + actionId: "local-knowledge-reindex:local-knowledge", + targetVersion: TARGET, + impact: localKnowledgeImpact, + }, + "caller-req-77", + ); + + expect(diagnostics).toContainEqual(expect.objectContaining({ correlationId: "caller-req-77" })); + }); + it("retains the live lease when neither terminal nor uncertainty state can persist", async () => { const localKnowledge = fakeLocalKnowledge(); const durable = createUpdateLocalStateManager({ stateDir: makeStateDir(), now: () => NOW }); diff --git a/packages/keiko-server/src/update-remediation.ts b/packages/keiko-server/src/update-remediation.ts index 8620226694..0d19e174aa 100644 --- a/packages/keiko-server/src/update-remediation.ts +++ b/packages/keiko-server/src/update-remediation.ts @@ -27,8 +27,14 @@ import { export interface UpdateRemediationManager { readonly getStatus: (request?: UpdateRemediationStatusRequest) => UpdateRemediationStatusReport; + // `correlationId` is optional so an existing caller keeps compiling unchanged; when the HTTP + // route layer threads its own request-scoped id through (ADR-0173 D5 / g12), every diagnostic + // this ONE action execution reports stays joined under it. Absent a caller-supplied id, one is + // minted here, once, so a cascade of failures from a single execution (persist, then audit, then + // outcome-uncertainty) still shares one id instead of each reporter minting its own. readonly runAction: ( request: UpdateRemediationActionRequest, + correlationId?: string, ) => Promise; readonly completeRestart: (targetVersion?: string) => UpdateRemediationStatusReport; readonly updateCanComplete: (targetVersion?: string) => boolean; @@ -273,15 +279,19 @@ async function executeDraft( return "failed"; } +// `correlationId` is always the ONE id minted (or supplied) at the start of the enclosing +// `runAction` call — never a fresh mint here — so every failure this single action execution +// reports, however many of the call sites below fire, stays joined under it. function recordDraftFailure( options: UpdateRemediationManagerOptions, + correlationId: string, error: unknown, source = "update-remediation.executeDraft", ): void { emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "update.remediation.execute", source, error, @@ -293,11 +303,12 @@ function recordDraftFailure( async function executeDraftStatus( options: UpdateRemediationManagerOptions, draft: ActionDraft, + correlationId: string, ): Promise { try { return await executeDraft(options, draft); } catch (error) { - recordDraftFailure(options, error); + recordDraftFailure(options, correlationId, error); return "failed"; } } @@ -307,6 +318,7 @@ function persistOutcomeUncertainty( now: () => number, request: UpdateRemediationActionRequest, draft: ActionDraft, + correlationId: string, ): boolean { try { upsertRuntimeAction({ @@ -319,7 +331,12 @@ function persistOutcomeUncertainty( }); return true; } catch (error) { - recordDraftFailure(options, error, "update-remediation.persistOutcomeUncertainty"); + recordDraftFailure( + options, + correlationId, + error, + "update-remediation.persistOutcomeUncertainty", + ); return false; } } @@ -329,11 +346,12 @@ function recordDraftAuditSafely( request: UpdateRemediationActionRequest, draft: ActionDraft, status: RuntimeRemediationStatus, + correlationId: string, ): void { try { - recordRemediationAudit(options, request, draft, status); + recordRemediationAudit(options, request, draft, status, correlationId); } catch (error) { - recordDraftFailure(options, error, "update-remediation.persistDraftAudit"); + recordDraftFailure(options, correlationId, error, "update-remediation.persistDraftAudit"); } } @@ -343,6 +361,7 @@ function persistDraftStatusSafely( request: UpdateRemediationActionRequest, draft: ActionDraft, status: RuntimeRemediationStatus, + correlationId: string, ): boolean { try { upsertRuntimeAction({ @@ -354,12 +373,12 @@ function persistDraftStatusSafely( ...(status === "failed" ? { warningCode: "remediation-execution-failed" } : {}), }); } catch (error) { - recordDraftFailure(options, error, "update-remediation.persistDraftStatus"); - const interlocked = persistOutcomeUncertainty(options, now, request, draft); - recordDraftAuditSafely(options, request, draft, status); + recordDraftFailure(options, correlationId, error, "update-remediation.persistDraftStatus"); + const interlocked = persistOutcomeUncertainty(options, now, request, draft, correlationId); + recordDraftAuditSafely(options, request, draft, status, correlationId); return interlocked; } - recordDraftAuditSafely(options, request, draft, status); + recordDraftAuditSafely(options, request, draft, status, correlationId); return true; } @@ -388,6 +407,7 @@ function recordRemediationAudit( request: UpdateRemediationActionRequest, draft: ActionDraft, status: RuntimeRemediationStatus, + correlationId: string, ): void { const result = options.localState.recordAuditEvent(remediationAuditEventType(status), { targetVersion: request.targetVersion, @@ -397,7 +417,12 @@ function recordRemediationAudit( ...(status === "failed" ? { warningCode: "remediation-execution-failed" } : {}), }); if (result.warning !== undefined) { - recordDraftFailure(options, new Error(result.warning), "update-remediation.persistDraftAudit"); + recordDraftFailure( + options, + correlationId, + new Error(result.warning), + "update-remediation.persistDraftAudit", + ); } } @@ -406,6 +431,7 @@ function deferDraft( now: () => number, request: UpdateRemediationActionRequest, draft: ActionDraft, + correlationId: string, ): void { if (!draft.canDefer) { throw new UpdateRemediationError( @@ -421,7 +447,7 @@ function deferDraft( status: "deferred", now, }); - recordRemediationAudit(options, request, draft, "deferred"); + recordRemediationAudit(options, request, draft, "deferred", correlationId); } function assertDraftOutcomeKnown( @@ -444,6 +470,7 @@ async function runDraft( runningActions: Set, request: UpdateRemediationActionRequest, draft: ActionDraft, + correlationId: string, ): Promise { if (!draft.canRun) { throw new UpdateRemediationError( @@ -469,7 +496,8 @@ async function runDraft( now, request, draft, - await executeDraftStatus(options, draft), + await executeDraftStatus(options, draft, correlationId), + correlationId, ); } finally { if (releaseAllowed) { @@ -513,14 +541,15 @@ async function runRemediationAction( now: () => number, runningActions: Set, request: UpdateRemediationActionRequest, + correlationId: string, ): Promise { const drafts = draftsForImpact(options.localState, request.impact, options.localKnowledge); const draft = findDraftOrThrow(drafts, request.actionId); assertDraftOutcomeKnown(options, draft); if (request.decision === "defer") { - deferDraft(options, now, request, draft); + deferDraft(options, now, request, draft, correlationId); } else { - await runDraft(options, now, runningActions, request, draft); + await runDraft(options, now, runningActions, request, draft, correlationId); } return statusFor(options, now, { ...request, persist: false }); } @@ -559,8 +588,8 @@ export function createUpdateRemediationManager( const runningActions = new Set(); return { getStatus: (request): UpdateRemediationStatusReport => statusFor(options, now, request), - runAction: (request): Promise => - runRemediationAction(options, now, runningActions, request), + runAction: (request, correlationId = randomUUID()): Promise => + runRemediationAction(options, now, runningActions, request, correlationId), completeRestart: (targetVersion): UpdateRemediationStatusReport => completeRestartAction(options, now, targetVersion), updateCanComplete: (targetVersion): boolean => diff --git a/packages/keiko-server/src/voice-control-ws.test.ts b/packages/keiko-server/src/voice-control-ws.test.ts index d6fd822a3d..e72f227567 100644 --- a/packages/keiko-server/src/voice-control-ws.test.ts +++ b/packages/keiko-server/src/voice-control-ws.test.ts @@ -13,6 +13,7 @@ import type { Server } from "node:http"; import { WebSocket } from "ws"; import { createUiServer, UI_HOST } from "./server.js"; import type { ServerDiagnosticRecord } from "./diagnostics-log.js"; +import { CORRELATION_HEADER } from "./correlation.js"; import { MAX_VOICE_CONTROL_FRAME_BYTES } from "./voice-realtime.js"; import { VOICE_LIVE_TRANSCRIBE_PATH } from "./voice-live-dictation.js"; import { buildRedactor, createRunRegistry, type UiHandlerDeps } from "./index.js"; @@ -561,6 +562,136 @@ describe("WebSocket live dictation upgrade — transcription-only control plane" socket.close(); }); + // RB-6 / ADR-0173 D5 regression pin: the correlation id is resolved ONCE per WebSocket connection + // at handleUpgrade, never re-minted per failure. Before the fix, `reportNegotiationFailure` called + // `randomUUID()` on every invocation, so two failures on the SAME connection carried two unrelated + // ids; this proves they now match. + it("reuses the same correlation id across two negotiation failures on one live-dictation connection", async (): Promise => { + const diagnostics: ServerDiagnosticRecord[] = []; + const port = await boot( + depsWith({ + config: voiceConfig(true), + configPresent: true, + diagnostics: { record: (record): void => void diagnostics.push(record) }, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }), + ); + const { ws: socket, next } = expectOpen( + await connect(port, { path: VOICE_LIVE_TRANSCRIBE_PATH }), + ); + socket.send(liveSessionCreate()); + await next(); // session.created + await next(); // capability.offer + + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-live-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const firstFailure = await next(); + await next(); // media.track.state ended + + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-live-1", + seq: 2, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const secondFailure = await next(); + await next(); // media.track.state ended + + expect(firstFailure.correlationId).toMatch(/^[0-9a-f-]{36}$/u); + expect(secondFailure.correlationId).toBe(firstFailure.correlationId); + expect(diagnostics).toHaveLength(2); + expect(diagnostics[0]?.correlationId).toBe(firstFailure.correlationId); + expect(diagnostics[1]?.correlationId).toBe(firstFailure.correlationId); + socket.close(); + }); + + it("honors a well-formed client-supplied X-Keiko-Correlation-Id on the live-dictation upgrade", async (): Promise => { + const diagnostics: ServerDiagnosticRecord[] = []; + const port = await boot( + depsWith({ + config: voiceConfig(true), + configPresent: true, + diagnostics: { record: (record): void => void diagnostics.push(record) }, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }), + ); + const { ws: socket, next } = expectOpen( + await connect(port, { + path: VOICE_LIVE_TRANSCRIBE_PATH, + headers: { [CORRELATION_HEADER]: "client-supplied-live-corr-1" }, + }), + ); + socket.send(liveSessionCreate()); + await next(); // session.created + await next(); // capability.offer + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-live-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const failure = await next(); + expect(failure.correlationId).toBe("client-supplied-live-corr-1"); + expect(diagnostics[0]?.correlationId).toBe("client-supplied-live-corr-1"); + socket.close(); + }); + + it("replaces a malformed client-supplied X-Keiko-Correlation-Id on the live-dictation upgrade", async (): Promise => { + const port = await boot( + depsWith({ + config: voiceConfig(true), + configPresent: true, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }), + ); + const { ws: socket, next } = expectOpen( + await connect(port, { + path: VOICE_LIVE_TRANSCRIBE_PATH, + headers: { [CORRELATION_HEADER]: "short" }, + }), + ); + socket.send(liveSessionCreate()); + await next(); // session.created + await next(); // capability.offer + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-live-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const failure = await next(); + expect(failure.correlationId).not.toBe("short"); + expect(failure.correlationId).toMatch(/^[0-9a-f-]{36}$/u); + socket.close(); + }); + it("rejects chat context and persona on the live dictation endpoint", async () => { const port = await boot(depsWith({ config: voiceConfig(true), configPresent: true })); const { ws: socket } = expectOpen(await connect(port, { path: VOICE_LIVE_TRANSCRIBE_PATH })); @@ -662,6 +793,118 @@ describe("WebSocket voice control upgrade — protocol behavior", () => { socket.close(); }); + // RB-6 / ADR-0173 D5 regression pin: the correlation id is resolved ONCE per WebSocket connection + // at handleUpgrade, never re-minted per failure — mirrors the live-dictation pin above for the + // full realtime control plane, which had no correlation-id concept at all before the fix. + it("reuses the same correlation id across two negotiation failures on one realtime control connection", async (): Promise => { + const { deps, chat } = depsWithChat({ + config: voiceConfig(true), + configPresent: true, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }); + const port = await boot(deps); + const { ws: socket, next } = expectOpen(await connect(port)); + socket.send(sessionCreate(chat.id)); + await next(); // session.created + await next(); // capability.offer + + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-int-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const firstFailure = await next(); + await next(); // media.track.state ended + + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-int-1", + seq: 2, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const secondFailure = await next(); + await next(); // media.track.state ended + + expect(firstFailure).toMatchObject({ kind: "error", code: "negotiation-failed" }); + expect(firstFailure.correlationId).toMatch(/^[0-9a-f-]{36}$/u); + expect(secondFailure.correlationId).toBe(firstFailure.correlationId); + socket.close(); + }); + + it("honors a well-formed client-supplied X-Keiko-Correlation-Id on the realtime control upgrade", async (): Promise => { + const { deps, chat } = depsWithChat({ + config: voiceConfig(true), + configPresent: true, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }); + const port = await boot(deps); + const { ws: socket, next } = expectOpen( + await connect(port, { headers: { [CORRELATION_HEADER]: "client-supplied-rt-corr-1" } }), + ); + socket.send(sessionCreate(chat.id)); + await next(); // session.created + await next(); // capability.offer + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-int-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const failure = await next(); + expect(failure).toMatchObject({ kind: "error", code: "negotiation-failed" }); + expect(failure.correlationId).toBe("client-supplied-rt-corr-1"); + socket.close(); + }); + + it("replaces a malformed client-supplied X-Keiko-Correlation-Id on the realtime control upgrade", async (): Promise => { + const { deps, chat } = depsWithChat({ + config: voiceConfig(true), + configPresent: true, + voiceRealtimeNegotiationRequest: (): Promise => + Promise.resolve({ ok: false, kind: "wrong-header" }), + }); + const port = await boot(deps); + const { ws: socket, next } = expectOpen( + await connect(port, { headers: { [CORRELATION_HEADER]: "short" } }), + ); + socket.send(sessionCreate(chat.id)); + await next(); // session.created + await next(); // capability.offer + socket.send( + JSON.stringify({ + protocolVersion: "1", + sessionId: "sess-int-1", + seq: 1, + direction: "client-to-host", + kind: "signal.sdp.offer", + sdp: OFFER_SDP, + }), + ); + await next(); // media.track.state negotiating + const failure = await next(); + expect(failure.correlationId).not.toBe("short"); + expect(failure.correlationId).toMatch(/^[0-9a-f-]{36}$/u); + socket.close(); + }); + it("rejects a concurrent socket for an attached idempotent session", async () => { const { deps, chat } = depsWithChat({ config: voiceConfig(true), configPresent: true }); const port = await boot(deps); diff --git a/packages/keiko-server/src/voice-handlers.ts b/packages/keiko-server/src/voice-handlers.ts index 19affb3363..b982a0b7b3 100644 --- a/packages/keiko-server/src/voice-handlers.ts +++ b/packages/keiko-server/src/voice-handlers.ts @@ -41,6 +41,7 @@ import { currentGatewayConfig, currentGatewayEgressConfig } from "./deps.js"; import { isVoiceDisabledByPolicy } from "./read-handlers.js"; import { createRequestCancellation } from "./request-cancellation.js"; import { toSpeakableText } from "./voice-speech-text.js"; +import { UNKNOWN_CORRELATION_ID } from "./correlation.js"; import { emitServerDiagnostic, serverDiagnosticFromError } from "./diagnostics-log.js"; // The decoded-audio ceiling for one dictation clip. This is the authoritative bound on the @@ -793,7 +794,7 @@ async function pipeAudioStream( emitServerDiagnostic( deps.diagnostics, serverDiagnosticFromError({ - correlationId: ctx.correlationId ?? "unknown", + correlationId: ctx.correlationId ?? UNKNOWN_CORRELATION_ID, operation: "voice.speech.stream", source: "voice.speech", error, diff --git a/packages/keiko-server/src/voice-live-dictation.ts b/packages/keiko-server/src/voice-live-dictation.ts index 5d792b5e4e..d74e9c0e92 100644 --- a/packages/keiko-server/src/voice-live-dictation.ts +++ b/packages/keiko-server/src/voice-live-dictation.ts @@ -6,7 +6,6 @@ import type { IncomingMessage } from "node:http"; import type { Duplex } from "node:stream"; -import { randomUUID } from "node:crypto"; import { WebSocketServer, type RawData, type WebSocket as WsSocket } from "ws"; import { findConfiguredCapability, @@ -29,6 +28,7 @@ import { type VoiceSessionCreateMessage, } from "@oscharko-dev/keiko-contracts"; import { isAllowedHost } from "./host-check.js"; +import { resolveCorrelationId } from "./correlation.js"; import { currentGatewayConfig, currentGatewayEgressConfig, type UiHandlerDeps } from "./deps.js"; import { isVoiceDisabledByPolicy, isVoiceRealtimeCapable } from "./read-handlers.js"; import { @@ -324,6 +324,10 @@ class VoiceLiveDictationConnection { private readonly negotiate: LiveDictationNegotiateFn, private readonly redact: (value: unknown) => unknown, private readonly diagnostics: ServerDiagnosticSink | undefined, + // Resolved ONCE at handleUpgrade (RB-6 / ADR-0173 D5): every diagnostic this connection emits + // over its whole lifetime — however many negotiation attempts a client makes — is joinable to + // the same id, instead of a fresh one per failure. + private readonly correlationId: string, ) {} start(): void { @@ -452,7 +456,7 @@ class VoiceLiveDictationConnection { } private reportNegotiationFailure(kind: RealtimeNegotiationErrorKind, thrown: unknown): void { - const correlationId = randomUUID(); + const correlationId = this.correlationId; const diagnostic = serverDiagnosticFromError({ correlationId, operation: "voice.live-dictation.negotiate", @@ -513,8 +517,11 @@ class VoiceLiveDictationPlaneImpl implements VoiceControlPlane { ) { return false; } + // Resolved ONCE per upgrade (RB-6 / ADR-0173 D5), not re-minted per diagnostic — every + // negotiation failure this connection later reports carries the same id. + const correlationId = resolveCorrelationId(req); this.wss.handleUpgrade(req, sock, head, (ws) => { - this.onConnection(ws, deps); + this.onConnection(ws, deps, correlationId); }); return true; } @@ -614,7 +621,7 @@ class VoiceLiveDictationPlaneImpl implements VoiceControlPlane { }; } - private onConnection(ws: WsSocket, deps: UiHandlerDeps): void { + private onConnection(ws: WsSocket, deps: UiHandlerDeps, correlationId: string): void { this.attachHeartbeat(ws); // KEIKO-0342: enforce the concurrent-connection cap after handleUpgrade admitted the // socket. wss.clients already includes this new one by the time onConnection runs, so @@ -652,6 +659,7 @@ class VoiceLiveDictationPlaneImpl implements VoiceControlPlane { this.buildNegotiate(deps, session.transcriptionLanguage), deps.redactor, deps.diagnostics, + correlationId, ); connection.start(); }); diff --git a/packages/keiko-server/src/voice-realtime.test.ts b/packages/keiko-server/src/voice-realtime.test.ts index 084600ce05..cd15c90045 100644 --- a/packages/keiko-server/src/voice-realtime.test.ts +++ b/packages/keiko-server/src/voice-realtime.test.ts @@ -101,6 +101,10 @@ function resolvePendingNegotiations(calls: readonly PendingNegotiation[]): void for (const call of calls) call.resolve(ok()); } +// Default connection-scoped correlation id used by tests that don't care about its exact value — +// distinct from any protocol code/kind string so an accidental field mix-up is easy to spot. +const TEST_CORRELATION_ID = "conn-correlation-id-1"; + function connect(options?: { negotiate?: ( offerSdp: string, @@ -109,6 +113,7 @@ function connect(options?: { ) => Promise; redact?: (value: unknown) => unknown; session?: TestSession; + correlationId?: string; }): { socket: FakeSocket; session: TestSession; conn: VoiceControlConnection } { const socket = new FakeSocket(); const session = options?.session ?? makeSession(); @@ -117,6 +122,7 @@ function connect(options?: { session, negotiate: options?.negotiate ?? okAsync, redact: options?.redact ?? ((value: unknown): unknown => value), + correlationId: options?.correlationId ?? TEST_CORRELATION_ID, }); return { socket, session, conn }; } @@ -261,19 +267,48 @@ describe("VoiceControlConnection proxied-SDP signaling", () => { expect(negotiate.mock.calls[0]).toHaveLength(3); }); - it("answers a negotiation failure with error negotiation-failed and an ended track", async () => { + it("answers a negotiation failure with error negotiation-failed, the connection's correlation id, and an ended track", async () => { const { socket, conn } = connect({ negotiate: (): Promise => Promise.resolve({ ok: false, kind: "transport" }), + correlationId: "negotiation-fail-corr-1", }); conn.start(false); socket.sent.length = 0; await conn.receive(clientMessage("signal.sdp.offer", 1, { sdp: OFFER_SDP })); expect(kinds(socket)).toEqual(["media.track.state", "error", "media.track.state"]); - expect((socket.sent[1] as unknown as Record).code).toBe("negotiation-failed"); + const failure = socket.sent[1] as unknown as Record; + expect(failure.code).toBe("negotiation-failed"); + expect(failure.correlationId).toBe("negotiation-fail-corr-1"); }); - it("rejects a malformed SDP offer without calling the provider", async () => { + // RB-6 / ADR-0173 D5 regression pin: the correlation id is resolved ONCE per WebSocket connection + // (at handleUpgrade, injected here as the connection's constructor option), never re-minted per + // failure. Before the fix each negotiation failure on the same connection would have carried an + // unrelated fresh id; this proves a second failure on the same connection still matches the first. + it("reuses the same connection-scoped correlation id across repeated negotiation failures", async () => { + const { socket, conn } = connect({ + negotiate: (): Promise => + Promise.resolve({ ok: false, kind: "transport" }), + correlationId: "repeated-failure-corr-1", + }); + conn.start(false); + socket.sent.length = 0; + + await conn.receive(clientMessage("signal.sdp.offer", 1, { sdp: OFFER_SDP })); + const firstFailure = socket.sent[1] as unknown as Record; + expect(firstFailure.code).toBe("negotiation-failed"); + expect(firstFailure.correlationId).toBe("repeated-failure-corr-1"); + + socket.sent.length = 0; + await conn.receive(clientMessage("signal.sdp.offer", 2, { sdp: OFFER_SDP })); + const secondFailure = socket.sent[1] as unknown as Record; + expect(secondFailure.code).toBe("negotiation-failed"); + expect(secondFailure.correlationId).toBe("repeated-failure-corr-1"); + expect(secondFailure.correlationId).toBe(firstFailure.correlationId); + }); + + it("rejects a malformed SDP offer without calling the provider or attaching a correlation id", async () => { const negotiate = vi.fn(okAsync); const { socket, conn } = connect({ negotiate }); conn.start(false); @@ -281,7 +316,9 @@ describe("VoiceControlConnection proxied-SDP signaling", () => { await conn.receive(clientMessage("signal.sdp.offer", 1, { sdp: "not-an-sdp" })); expect(negotiate).not.toHaveBeenCalled(); expect(kinds(socket)).toEqual(["error"]); - expect((socket.sent[0] as unknown as Record).code).toBe("invalid-message"); + const failure = socket.sent[0] as unknown as Record; + expect(failure.code).toBe("invalid-message"); + expect(failure).not.toHaveProperty("correlationId"); }); it.each([ diff --git a/packages/keiko-server/src/voice-realtime.ts b/packages/keiko-server/src/voice-realtime.ts index 397dcf142c..d38347667f 100644 --- a/packages/keiko-server/src/voice-realtime.ts +++ b/packages/keiko-server/src/voice-realtime.ts @@ -47,6 +47,7 @@ import { type VoiceSessionCreateMessage, } from "@oscharko-dev/keiko-contracts"; import { isAllowedHost } from "./host-check.js"; +import { resolveCorrelationId } from "./correlation.js"; import { currentGatewayConfig, currentGatewayEgressConfig, type UiHandlerDeps } from "./deps.js"; import { isVoiceDisabledByPolicy, isVoiceRealtimeCapable } from "./read-handlers.js"; @@ -294,6 +295,11 @@ export interface VoiceControlConnectionOptions { readonly session: SessionState; readonly negotiate: NegotiateFn; readonly redact: (value: unknown) => unknown; + // Resolved ONCE per WebSocket connection at handleUpgrade (RB-6 / ADR-0173 D5), never re-minted + // per failure — every diagnostic-bearing message this connection emits over its whole lifetime, + // including across a session resumed by a later reconnect's OWN new connection, is joinable to + // the id of the upgrade that produced it. + readonly correlationId: string; } // The protocol state machine for one attached control socket. Pure of WebSocket/IO concerns beyond @@ -305,6 +311,7 @@ export class VoiceControlConnection { private readonly session: SessionState; private readonly negotiate: NegotiateFn; private readonly redact: (value: unknown) => unknown; + private readonly correlationId: string; private negotiation: AbortController | undefined; private closed = false; @@ -313,6 +320,7 @@ export class VoiceControlConnection { this.session = options.session; this.negotiate = options.negotiate; this.redact = options.redact; + this.correlationId = options.correlationId; } // Re-delivers the buffered replayable events to a (re)attached client, then announces the resolved @@ -429,7 +437,9 @@ export class VoiceControlConnection { } private failNegotiation(): void { - this.emitError("negotiation-failed"); + // Same connection-scoped correlation id as every other negotiation attempt on this socket + // (RB-6 / ADR-0173 D5) — never re-minted per failure. + this.emitError("negotiation-failed", this.correlationId); this.emit({ kind: "media.track.state", track: "audio-in", state: "ended" }); } @@ -471,8 +481,8 @@ export class VoiceControlConnection { this.emit({ kind: "media.track.state", track: "audio-in", state: "live" }); } - private emitError(code: VoiceProtocolErrorCode): void { - this.emit({ kind: "error", code }); + private emitError(code: VoiceProtocolErrorCode, correlationId?: string): void { + this.emit({ kind: "error", code, ...(correlationId !== undefined ? { correlationId } : {}) }); } // Builds a sequenced host→client control message from a payload, appends it to the bounded replay @@ -700,8 +710,11 @@ class VoiceControlPlaneImpl implements VoiceControlPlane { ) { return false; } + // Resolved ONCE per upgrade (RB-6 / ADR-0173 D5): the id is scoped to this physical WebSocket + // connection, not the resumable logical session, so a later reconnect gets its own fresh id. + const correlationId = resolveCorrelationId(req); this.wss.handleUpgrade(req, sock, head, (ws) => { - this.onConnection(ws, deps); + this.onConnection(ws, deps, correlationId); }); return true; } @@ -852,7 +865,7 @@ class VoiceControlPlaneImpl implements VoiceControlPlane { } // eslint-disable-next-line max-lines-per-function -- connection lifecycle keeps heartbeat, frame limits, session start, and detach handling together. - private onConnection(ws: WsSocket, deps: UiHandlerDeps): void { + private onConnection(ws: WsSocket, deps: UiHandlerDeps, correlationId: string): void { this.attachHeartbeat(ws); const voice = resolveVoiceCapability(currentGatewayConfig(deps) ?? { providers: [] }, { policyDisabled: isVoiceDisabledByPolicy(deps.env), @@ -896,6 +909,7 @@ class VoiceControlPlaneImpl implements VoiceControlPlane { session: resolved.state, negotiate, redact: deps.redactor, + correlationId, }); connection.start(resolved.resume); }); diff --git a/packages/keiko-server/src/workspace-index-provider.test.ts b/packages/keiko-server/src/workspace-index-provider.test.ts index c63b0b1e48..9527f483be 100644 --- a/packages/keiko-server/src/workspace-index-provider.test.ts +++ b/packages/keiko-server/src/workspace-index-provider.test.ts @@ -425,4 +425,47 @@ describe("workspace index provider", () => { rmSync(runtimeStateDir, { force: true, recursive: true }); } }); + + // ADR-0173 D5 / g12: a load failure and a save failure reported for the SAME generation used to + // each mint their own disconnected `randomUUID()`, so an operator (or an agent joining lines by + // correlation id) could never tell they were evidence about the same underlying epoch. Fails + // before the fix — two independent random UUIDs never match — and passes after, once both + // reporters read the one id minted when the generation was created. + it("keeps a generation's load and save failures joined under one correlation id", async () => { + const workspaceRoot = tempDir("keiko-index-workspace-private-"); + const runtimeStateDir = tempDir("keiko-index-state-"); + const records: ServerDiagnosticRecord[] = []; + const key = Buffer.alloc(32, 19).toString("base64"); + try { + const provider = createServerWorkspaceIndexProvider({ + runtimeStateDir, + env: { KEIKO_WORKSPACE_INDEX_KEY: key }, + diagnostics: { record: (record): void => void records.push(record) }, + }); + const index = provider(workspaceRoot); + if (index === undefined) throw new Error("expected workspace index"); + const keyShape = scopeKey(workspaceRoot); + await index.saveSnapshot(keyShape, emptySnapshot()); + const snapshotDir = join(runtimeStateDir, "workspace-index"); + const snapshotName = readdirSync(snapshotDir).find((name) => name.endsWith(".json")); + if (snapshotName === undefined) throw new Error("expected encrypted snapshot"); + const snapshotPath = join(snapshotDir, snapshotName); + + writeFileSync(snapshotPath, "{corrupt", "utf8"); + await expect(index.loadSnapshot(keyShape)).resolves.toBeUndefined(); + + unlinkSync(snapshotPath); + mkdirSync(snapshotPath); + await expect(index.saveSnapshot(keyShape, emptySnapshot())).rejects.toThrow(); + + expect(records).toHaveLength(2); + expect(records[0]).toMatchObject({ operation: "workspace.index.load" }); + expect(records[1]).toMatchObject({ operation: "workspace.index.save" }); + expect(records[0]?.correlationId).toMatch(/^[0-9a-f-]{36}$/u); + expect(records[1]?.correlationId).toBe(records[0]?.correlationId); + } finally { + rmSync(workspaceRoot, { force: true, recursive: true }); + rmSync(runtimeStateDir, { force: true, recursive: true }); + } + }); }); diff --git a/packages/keiko-server/src/workspace-index-provider.ts b/packages/keiko-server/src/workspace-index-provider.ts index 8d885c66b2..92bc968074 100644 --- a/packages/keiko-server/src/workspace-index-provider.ts +++ b/packages/keiko-server/src/workspace-index-provider.ts @@ -46,6 +46,11 @@ interface CachedWorkspaceIndex { interface WorkspaceIndexGeneration { active: boolean; reported: boolean; + // One id per generation (one workspace-root + key-fingerprint epoch), minted once when the + // generation is created — never re-minted per failure. A generation's load failure, save failure + // and eventual stale-generation report are all evidence about the SAME underlying epoch, so they + // must stay joinable under one id instead of each reporter drawing its own disconnected one. + readonly correlationId: string; } interface RuntimeWorkspaceIndexGeneration { @@ -141,14 +146,19 @@ function workspaceIndexKeyFingerprint(key: Buffer): string { return createHash("sha256").update(key).digest("hex"); } +// `correlationId` is minted once by the caller, at the START of whichever operation this failure +// belongs to (the provider-lookup attempt for `reportWorkspaceIndexFailure`, or the owning +// generation for the other three) — never freshly here, so a cascade of related diagnostics about +// the SAME attempt or the SAME generation stays joinable under one id (ADR-0173 D5 / g12). function reportWorkspaceIndexFailure( options: ServerWorkspaceIndexProviderOptions, + correlationId: string, error: unknown, ): void { emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId, operation: "workspace.index.open", source: "workspace-index-provider", error, @@ -159,12 +169,13 @@ function reportWorkspaceIndexFailure( function reportWorkspaceIndexLoadFailure( options: ServerWorkspaceIndexProviderOptions, + generation: WorkspaceIndexGeneration, reason: WorkspaceIndexLoadFailureReason, ): void { emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId: generation.correlationId, operation: "workspace.index.load", source: "workspace-index-provider", error: new WorkspaceIndexSnapshotLoadError(reason), @@ -173,11 +184,14 @@ function reportWorkspaceIndexLoadFailure( ); } -function reportWorkspaceIndexSaveFailure(options: ServerWorkspaceIndexProviderOptions): void { +function reportWorkspaceIndexSaveFailure( + options: ServerWorkspaceIndexProviderOptions, + generation: WorkspaceIndexGeneration, +): void { emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId: generation.correlationId, operation: "workspace.index.save", source: "workspace-index-provider", error: new WorkspaceIndexSnapshotSaveError(), @@ -195,7 +209,7 @@ function reportStaleWorkspaceIndexGeneration( emitServerDiagnostic( options.diagnostics, serverDiagnosticFromError({ - correlationId: randomUUID(), + correlationId: generation.correlationId, operation: "workspace.index.generation", source: "workspace-index-provider", error: new WorkspaceIndexKeyRotatedError(), @@ -243,7 +257,11 @@ function activeRuntimeGeneration( return existing.generation; } if (existing !== undefined) existing.generation.active = false; - const generation: WorkspaceIndexGeneration = { active: true, reported: false }; + const generation: WorkspaceIndexGeneration = { + active: true, + reported: false, + correlationId: randomUUID(), + }; generations.set(runtimeDir, { generation, keyFingerprint }); return generation; } @@ -270,10 +288,10 @@ function createGenerationWorkspaceIndex( encryptionKey: key, isGenerationActive: (): boolean => generation.active, onLoadFailure: (failure): void => { - reportWorkspaceIndexLoadFailure(options, failure.reason); + reportWorkspaceIndexLoadFailure(options, generation, failure.reason); }, onSaveFailure: (): void => { - reportWorkspaceIndexSaveFailure(options); + reportWorkspaceIndexSaveFailure(options, generation); }, }), ); @@ -292,6 +310,10 @@ export function createServerWorkspaceIndexProvider( } const cacheKey = `${resolve(workspaceRoot)}\u0000${runtimeDir}`; const existing = indexes.get(cacheKey); + // Minted once, at the start of THIS lookup attempt, rather than inside the catch below: the + // attempt has exactly one failure point (key resolution or generation construction), so this + // is the id that failure — and only that failure — is reported under. + const correlationId = randomUUID(); try { const { key } = resolveLocalVaultKey({ env: options.env ?? process.env, @@ -319,7 +341,7 @@ export function createServerWorkspaceIndexProvider( } catch (error) { if (existing !== undefined) existing.generation.active = false; retireRuntimeGeneration(generations, runtimeDir); - reportWorkspaceIndexFailure(options, error); + reportWorkspaceIndexFailure(options, correlationId, error); return undefined; } };