From 2e4a79ca5022e4a564b94d3361ef5dd3e57652f0 Mon Sep 17 00:00:00 2001 From: Markus Hartung Date: Thu, 3 Sep 2026 18:01:25 +0200 Subject: [PATCH] fix(quality): detect duplicate tool_calls entries in one response (#12446) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Validado em lote numa worktree combinada com os 9 PRs desta leva sobre o tip de `release/v3.8.51` (já com a leva anterior dentro): os nove boardaram **sem um único conflito**, `typecheck:core` limpo e **80/80** nos 6 arquivos de teste que os PRs trazem. O crescimento de arquivo próprio da leva foi rebaselinado num registro datado (`_rebaseline_2026_09_03_hartmark_batch`): `combos/page.tsx` 5012→5018 (#12355, tratar o estado degradado quando o bundling de tiktoken de um provider sem relação falha) e `open-sse/services/combo.ts` 4023→4036 (#12338, os fixes do universal-handoff). As violações restantes (`codex.ts`, `stream.ts`) foram medidas também no tip puro e são drift da base, não desta leva. Obrigado, @hartmark. --- open-sse/handlers/chatCore/attemptLogging.ts | 10 ++++ .../chatCore/toolCallSpecViolationAudit.ts | 46 +++++++++++++++ open-sse/services/combo/validateQuality.ts | 50 +++++++++++++++- tests/unit/chatcore-attempt-logging.test.ts | 59 +++++++++++++++++++ 4 files changed, 162 insertions(+), 3 deletions(-) create mode 100644 open-sse/handlers/chatCore/toolCallSpecViolationAudit.ts diff --git a/open-sse/handlers/chatCore/attemptLogging.ts b/open-sse/handlers/chatCore/attemptLogging.ts index 65a492a541..07de9f19b2 100644 --- a/open-sse/handlers/chatCore/attemptLogging.ts +++ b/open-sse/handlers/chatCore/attemptLogging.ts @@ -13,6 +13,7 @@ import { extractProviderWarnings } from "@/lib/compliance/providerAudit"; import { logAuditEvent } from "@/lib/compliance"; import { emit } from "@/lib/events/eventBus"; +import { maybeLogToolCallSpecViolation } from "./toolCallSpecViolationAudit.ts"; import type { RequestCompletedPayload, RequestFailedPayload } from "@/lib/events/types"; import { saveCallLog } from "@/lib/usageDb"; import type { VideoBridgeLogRedactionEntry } from "@/lib/guardrails/videoBridge"; @@ -392,6 +393,15 @@ export function persistAttemptLogs(args: PersistAttemptLogsArgs, ctx: PersistAtt }); } + maybeLogToolCallSpecViolation({ + responseBody, + provider, + model, + connectionId: finalConnectionId, + httpStatus: status, + requestId: skillRequestId, + }); + const capturedPipeline = reqLogger?.getPipelinePayloads?.() ?? null; const pipelinePayloads = detailedLoggingEnabled ? (capturedPipeline ?? {}) diff --git a/open-sse/handlers/chatCore/toolCallSpecViolationAudit.ts b/open-sse/handlers/chatCore/toolCallSpecViolationAudit.ts new file mode 100644 index 0000000000..573daae59e --- /dev/null +++ b/open-sse/handlers/chatCore/toolCallSpecViolationAudit.ts @@ -0,0 +1,46 @@ +/** + * Post-request on-spec audit for duplicated tool_calls. + * + * Extracted from persistAttemptLogs so attemptLogging.ts stays at the frozen + * complexity count. validateResponseQuality's streaming peek only sees the + * START of a stream, so a duplicate that arrives after real content has + * already been relayed cannot fail the attempt over — this is the first + * point the fully assembled body is available. Too late to retry; a durable + * audit row still beats a clean HTTP 200 with no trace. + * + * Observed: minimax-m3:free via OpenRouter/GMICloud, 2026-09-02, duplicated + * a heartbeat_respond call byte-for-byte. + */ + +import { logAuditEvent } from "@/lib/compliance"; +import { findToolCallSpecViolation } from "../../services/combo/validateQuality.ts"; + +export function maybeLogToolCallSpecViolation(input: { + responseBody: unknown; + provider: string | null | undefined; + model: string | null | undefined; + connectionId: string | null; + httpStatus: number; + requestId: string; +}): void { + const violation = findToolCallSpecViolation(input.responseBody); + if (!violation) return; + logAuditEvent({ + action: "provider.spec_violation", + actor: "system", + target: + [input.provider, input.connectionId].filter(Boolean).join(":") || + input.provider || + input.model, + resourceType: "provider_spec_violation", + status: "warning", + requestId: input.requestId, + details: { + provider: input.provider, + model: input.model, + connectionId: input.connectionId, + httpStatus: input.httpStatus, + violation, + }, + }); +} diff --git a/open-sse/services/combo/validateQuality.ts b/open-sse/services/combo/validateQuality.ts index be70038994..723a10b614 100644 --- a/open-sse/services/combo/validateQuality.ts +++ b/open-sse/services/combo/validateQuality.ts @@ -16,6 +16,45 @@ import { evaluateResponseValidation, type ResponseValidationConfig } from "./res import { getReasoningTokens } from "../../../src/lib/usage/tokenAccounting.ts"; import type { ComboRetryAfter } from "./types.ts"; +/** + * Detects tool_calls entries within one assistant message that repeat the + * exact same function name + arguments verbatim -- always a bug (no + * legitimate use calls one tool twice with identical arguments in the same + * turn), and a real observed failure mode of at least one free-tier + * streaming model (minimax-m3:free via OpenRouter/GMICloud, 2026-09-02: + * duplicated a heartbeat_respond call byte-for-byte, confirmed at the raw + * SSE wire level -- an upstream bug, not an OmniRoute reconstruction + * artifact). Used two ways: to fail a non-streaming response over to a + * sibling combo target (see validateResponseQuality below), and, post- + * stream, to flag an already-relayed streaming response as an on-spec + * violation despite its clean HTTP 200 (see attemptLogging.ts's + * persistAttemptLogs) -- a streaming response can't be retried once real + * content has started reaching the client (the quality-gate peek below only + * ever validates the START of a stream, by design, to avoid buffering the + * whole response and defeating streaming's latency purpose), so flagging it + * after the fact is what's actually achievable for that path. + */ +export function findToolCallSpecViolation(responseBody: unknown): string | null { + const json = isRecord(responseBody) ? responseBody : null; + const choices = json?.choices; + const firstChoice = Array.isArray(choices) ? choices[0] : null; + const message = isRecord(firstChoice) ? firstChoice.message : null; + const toolCalls = isRecord(message) ? message.tool_calls : null; + if (!Array.isArray(toolCalls) || toolCalls.length < 2) return null; + + const seen = new Set(); + for (const call of toolCalls) { + const fn = isRecord(call) ? call.function : null; + if (!isRecord(fn) || typeof fn.name !== "string" || typeof fn.arguments !== "string") { + continue; + } + const signature = `${fn.name}\u0000${fn.arguments}`; + if (seen.has(signature)) return `duplicate tool_calls entry for "${fn.name}"`; + seen.add(signature); + } + return null; +} + export function toRetryAfterDisplayValue(value: ComboRetryAfter): string | Date { if (typeof value !== "number") return value; if (value > 0 && value < 1_000_000_000) { @@ -327,9 +366,9 @@ export async function validateResponseQuality( function isTerminalUsageOnlyChunk(parsed: Record, eventType: string): boolean { return Boolean( parsed.usage && - typeof parsed.usage === "object" && - !Array.isArray(parsed.choices) && - !eventType.startsWith("response.") + typeof parsed.usage === "object" && + !Array.isArray(parsed.choices) && + !eventType.startsWith("response.") ); } @@ -734,6 +773,11 @@ export async function validateResponseQuality( } const hasToolCalls = Array.isArray(toolCalls) && toolCalls.length > 0; + const specViolation = findToolCallSpecViolation(json); + if (specViolation) { + return { valid: false, reason: specViolation }; + } + if (!hasContent && !hasToolCalls) { return { valid: false, reason: "empty content and no tool_calls in response" }; } diff --git a/tests/unit/chatcore-attempt-logging.test.ts b/tests/unit/chatcore-attempt-logging.test.ts index b9fe57fbd3..2af6bbd41c 100644 --- a/tests/unit/chatcore-attempt-logging.test.ts +++ b/tests/unit/chatcore-attempt-logging.test.ts @@ -16,6 +16,7 @@ process.env.DATA_DIR = testDataDir; const coreDb = await import("../../src/lib/db/core.ts"); const { getCallLogById } = await import("../../src/lib/usage/callLogs.ts"); const { persistAttemptLogs } = await import("../../open-sse/handlers/chatCore/attemptLogging.ts"); +const { getAuditLog } = await import("../../src/lib/compliance/index.ts"); type CodexRotationEnvelope = { _omniroute?: { @@ -136,3 +137,61 @@ test("connectionId falls back to credentials.connectionId when null, and error i assert.equal(row.status, 502); assert.match(String(row.error ?? ""), /upstream boom/); }); + +function duplicateHeartbeatBody() { + return { + choices: [ + { + message: { + tool_calls: [ + { function: { name: "heartbeat_respond", arguments: "{}" } }, + { function: { name: "heartbeat_respond", arguments: "{}" } }, + ], + }, + }, + ], + }; +} + +test("duplicate tool_calls in the assembled body writes provider.spec_violation audit", () => { + persistAttemptLogs( + { status: 200, responseBody: duplicateHeartbeatBody() }, + baseCtx({ pendingRequestId: "attempt-spec-violation-1", skillRequestId: "skill-spec-1" }) + ); + // logAuditEvent is synchronous; do not wait on the fire-and-forget saveCallLog. + const rows = getAuditLog({ action: "provider.spec_violation", requestId: "skill-spec-1" }); + assert.equal(rows.length, 1); + assert.equal(rows[0]?.resourceType, "provider_spec_violation"); + const details = rows[0]?.details; + assert.ok(details && typeof details === "object"); + assert.equal( + (details as { violation?: string }).violation, + 'duplicate tool_calls entry for "heartbeat_respond"' + ); +}); + +test("unique tool_calls do not write provider.spec_violation audit", () => { + persistAttemptLogs( + { + status: 200, + responseBody: { + choices: [ + { + message: { + tool_calls: [ + { function: { name: "heartbeat_respond", arguments: "{}" } }, + { function: { name: "other_tool", arguments: "{}" } }, + ], + }, + }, + ], + }, + }, + baseCtx({ pendingRequestId: "attempt-spec-clean-1", skillRequestId: "skill-spec-clean-1" }) + ); + const rows = getAuditLog({ + action: "provider.spec_violation", + requestId: "skill-spec-clean-1", + }); + assert.equal(rows.length, 0); +});