fix(mcp): make agent failures diagnosable from the log, not just from the source (#2087)
* fix(mcp): make agent failures diagnosable from the log, not just from the source Mining event_log for mcp.tool_called: VALIDATION_ERROR ran at about one a day until 2026-08-25, then jumped to a hundred a day and stayed there. One integration's gnubok_get_kpi_report has been refused 604 times over seven days and is still failing. The cause is the unknown-parameter guard from #1856, which is correct and stays. The caller is even told precisely what is wrong: getStructuredError puts "Unknown parameter "x" for <tool>. Valid parameters: ..." into message_en, which the agent receives. What was broken is what we recorded about it. Two things, both cheap: - Telemetry logged only message_sv, which for VALIDATION_ERROR is the registry default "Förfrågan innehåller ogiltiga uppgifter." and names neither the parameter nor the tool. A seven-day outage was indistinguishable from a typo, and the cause was only findable by reading the dispatcher source. errorDetail now carries message_en, stored only when it differs from errorMessage, so the many domain failures whose message_sv is already the specific text cost nothing extra. - errorKind said 'company_access_denied' for all 604, because the arg guard throws inside the company-routing try. That is an active misdirection: it sends triage looking for a tenancy bug that does not exist. Exactly two things in that block raise VALIDATION_ERROR, the unknown-parameter guard and a malformed company_id, and neither is a permissions failure, so they now log as 'invalid_arguments'. Tests reproduce the production call shape and were verified to fail when either fix is reverted. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * test(mcp): derive the telemetry payload type from the event contract Two review findings, both valid. The local ToolCalledPayload interface was a hand-maintained duplicate that omitted sessionId and half the errorKind union. That is not cosmetic: it is why errorDetail could be added to the emitter and to lib/events/types.ts while the test file type-checked against a stale shape. Deriving it from EventPayload<'mcp.tool_called'> removes the drift. The null-detail assertion was also conditional, so it would have passed on a wrong-but-present value. Replaced with two determinate cases: a scope denial carries both languages without duplicating either, and the unknown-tool exit, which supplies no diagnostic, stores null. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * test(mcp): pin the scope name in the diagnostic assertion 'A different string' passes on any placeholder. The reason errorDetail is worth storing is that it names what the caller lacks, so assert that. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Jakob Wennberg <311770904+jakobwennberg-oss@users.noreply.github.com> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Jakob Wennberg
@@ -1407,6 +1407,7 @@ One line per decision: `[YYYY-MM-DD] <decision>: <why>`. Appended by agents and
|
||||
[2026-08-31] gnubok-home-ok cache cookie is user-scoped (userId~host) instead of cleared on sign-out: sign-out happens client-side via supabase.auth.signOut so no server surface reliably sees it, while a value bound to the session's user makes any inherited verdict miss the cache by construction. Separator ~ because it is unreserved under encodeURIComponent AND a legal raw cookie octet, so the value round-trips identically whether or not the cookie layer percent-encodes. Old host-only cookies never match and self-heal; found via the amnas account-switch repro (two logins 9 s apart shared the verdict).
|
||||
[2026-08-31] Bookkeeping digest email is per-user per-COMPANY per-day (not one aggregated mail across companies): notification_log.company_id anchors the claim, subject lines stay unambiguous, and most users have one company; consultants can opt in and get one short mail per client. Window is a fixed last-24h (cron cadence) rather than tracking last-sent state. Settings toggle stays hardcoded Swedish like the rest of the push-notifications extension UI (no next-intl wiring in extension components); revisit if that surface is ever translated.
|
||||
[2026-08-31] Own-credentials seam forward-ported into the entitlement partition (skeptic refutation on PR #1747): a self-host serving bank_sync/skatteverket from its OWN env credentials (the same vars the extensions activate on) counts those as local capabilities, so upgrading an own-credentials self-host never dark-launches the connector gate against a working integration (the 2026-08-17 folded-flag incident shape). lib/entitlements/own-credentials.ts mirrors the connector-mode seam arriving in the instance-wiring PR (connector mode = key AND no own creds) and must stay in sync with it. org_lookup/migration have no own-credentials form. capability_blocked copy now has a self-host variant naming GNUBOK_CONNECTOR_KEY instead of the hosted subscription upsell, which misled operators toward a product they cannot buy for a self-host.
|
||||
[2026-08-31] MCP tool telemetry now logs errorDetail (structured.error.message_en) alongside errorMessage (message_sv), and splits errorKind 'invalid_arguments' out of 'company_access_denied'. Found by mining event_log: the 2026-08-25 unknown-parameter guard (#1856) refused one integration's gnubok_get_kpi_report 604 times over seven days, and every row logged a permissions-shaped errorKind with the generic registry message "Förfrågan innehåller ogiltiga uppgifter.". The caller was told exactly which parameter was wrong (message_en carries it); only our own telemetry was blind. errorDetail is stored only when it differs from errorMessage, so domain failures whose message_sv is already specific cost nothing.
|
||||
[2026-08-31] Connector key validation maps a database/RPC error to 503 CONNECTOR_VALIDATION_UNAVAILABLE, never 401 (skeptic refutation on PR #1748): the instance sync deletes its entire connector grant cache on 401/403 (revocation semantics), so the api-keys fail-closed-to-401 precedent would let a transient hosted DB blip destroy a paying instance's 72h offline grace; 503 lands in the sync's keep-grants branch. In the same pass X-Connector-Key now wins over Authorization in extractConnectorKey: the header exists solely for proxied calls where Authorization carries an upstream token (the SKV data proxy sends both), and Bearer-first hashed the upstream token and 401'd exactly that shape.
|
||||
[2026-08-31] Connector sync deletes its grant cache only on a 401/403 whose JSON body carries a connector rejection code (CONNECTOR_KEY_MISSING/INVALID/SUSPENDED), never on status alone (second skeptic refutation on PR #1748, same failure class as the RPC-error mapping one layer up): a Vercel WAF challenge page, edge deployment protection, or a self-host egress proxy all answer 401/403 without the hosted app running, and status-trusting deletion let any of them wipe a paying instance's 72h offline grace within the hour. A codeless 401/403 now lands in the keep-grants server_error branch and the cache expires naturally if the condition persists.
|
||||
[2026-08-31] Connector usage metering redacts opaque path segments to ':id' before insert (skeptic refutation on PR #1751): the proxied bank paths carry the raw EB session id and account uid as segments, so persisting the raw pathname in connector_usage_events put the cleartext handle next to the ledger that exists precisely to store only sha256(handle). redactEndpoint() replaces UUID/long-hex/long-base64url segments; literal route words survive so metering keys stay useful.
|
||||
|
||||
@@ -7,6 +7,7 @@
|
||||
*/
|
||||
import { describe, it, expect, vi, beforeEach } from 'vitest'
|
||||
import { eventBus } from '@/lib/events/bus'
|
||||
import type { EventPayload } from '@/lib/events/types'
|
||||
|
||||
// ── Mocks (mirrors receipt-matcher.test.ts setup) ────────────
|
||||
|
||||
@@ -109,23 +110,16 @@ function mcpRequest(
|
||||
})
|
||||
}
|
||||
|
||||
interface ToolCalledPayload {
|
||||
tool: string
|
||||
requiredScope: string | null
|
||||
actorType: string
|
||||
actorId: string | null
|
||||
actorLabel: string | null
|
||||
latencyMs: number
|
||||
success: boolean
|
||||
isError: boolean
|
||||
errorCode: string | null
|
||||
errorKind: 'execution' | 'scope_denied' | 'unknown_tool' | null
|
||||
errorMessage: string | null
|
||||
requestId: string | number | null
|
||||
userId: string
|
||||
companyId: string
|
||||
client: string | null
|
||||
}
|
||||
/**
|
||||
* The shared event contract, not a local copy.
|
||||
*
|
||||
* This used to be a hand-maintained duplicate interface, which silently
|
||||
* omitted sessionId and half the errorKind union. A new field added to
|
||||
* lib/events/types.ts and to the emitter then type-checked here against the
|
||||
* stale local shape, so the tests passed while the payload type was wrong.
|
||||
* Deriving it removes the drift entirely.
|
||||
*/
|
||||
type ToolCalledPayload = EventPayload<'mcp.tool_called'>
|
||||
|
||||
interface ToolsListCalledPayload {
|
||||
toolCount: number
|
||||
@@ -241,6 +235,86 @@ describe('mcp.tool_called telemetry', () => {
|
||||
expect(event.latencyMs).toBe(0)
|
||||
})
|
||||
|
||||
/**
|
||||
* Regression tests for the 2026-08-25 unknown-parameter rejection.
|
||||
*
|
||||
* That guard is correct and stays. What was wrong is what we RECORDED about
|
||||
* it: one integration sent an unknown parameter to gnubok_get_kpi_report and
|
||||
* was refused 604 times over seven days, and every one of those rows logged
|
||||
* errorKind 'company_access_denied' with the message "Förfrågan innehåller
|
||||
* ogiltiga uppgifter." The caller was told exactly which parameter was
|
||||
* wrong; our own telemetry recorded a permissions problem that never existed.
|
||||
*/
|
||||
it('logs an unknown parameter as invalid_arguments, not company_access_denied', async () => {
|
||||
const eventPromise = captureNextToolCalledEvent()
|
||||
|
||||
await handleMcpRequest(
|
||||
mcpRequest('tools/call', {
|
||||
name: 'gnubok_get_trial_balance',
|
||||
arguments: { totally_not_a_parameter: 1 },
|
||||
})
|
||||
)
|
||||
|
||||
const event = await eventPromise
|
||||
expect(event.errorCode).toBe('VALIDATION_ERROR')
|
||||
expect(event.errorKind).toBe('invalid_arguments')
|
||||
expect(event.errorKind).not.toBe('company_access_denied')
|
||||
})
|
||||
|
||||
it('records the specific diagnostic in errorDetail when errorMessage is the generic default', async () => {
|
||||
const eventPromise = captureNextToolCalledEvent()
|
||||
|
||||
await handleMcpRequest(
|
||||
mcpRequest('tools/call', {
|
||||
name: 'gnubok_get_trial_balance',
|
||||
arguments: { totally_not_a_parameter: 1 },
|
||||
})
|
||||
)
|
||||
|
||||
const event = await eventPromise
|
||||
// Unchanged: the Swedish user-facing message, which for VALIDATION_ERROR
|
||||
// is the registry default and says nothing about the cause.
|
||||
expect(event.errorMessage).toBe('Förfrågan innehåller ogiltiga uppgifter.')
|
||||
// New: what actually went wrong, enough to fix the caller from the log
|
||||
// alone without reading the source.
|
||||
expect(event.errorDetail).toContain('totally_not_a_parameter')
|
||||
expect(event.errorDetail).toContain('gnubok_get_trial_balance')
|
||||
})
|
||||
|
||||
it('carries both languages on a scope denial, without duplicating either', async () => {
|
||||
const eventPromise = captureNextToolCalledEvent()
|
||||
|
||||
await handleMcpRequest(
|
||||
mcpRequest('tools/call', {
|
||||
name: 'gnubok_create_invoice',
|
||||
arguments: { customer_id: 'x', items: [] },
|
||||
})
|
||||
)
|
||||
|
||||
const event = await eventPromise
|
||||
expect(event.errorKind).toBe('scope_denied')
|
||||
// Asserted directly rather than behind an `if`: a conditional assertion
|
||||
// would also pass on a wrong-but-present value, which is no assertion.
|
||||
// And "some other string" is barely stronger, so pin the content that
|
||||
// makes the field worth storing: the scope the caller actually lacks.
|
||||
expect(event.errorDetail).toContain('invoices:write')
|
||||
expect(event.errorDetail).not.toBe(event.errorMessage)
|
||||
})
|
||||
|
||||
it('stores null when the call site supplies no diagnostic', async () => {
|
||||
const eventPromise = captureNextToolCalledEvent()
|
||||
|
||||
// The unknown-tool exit passes errorMessage only. Nothing may be
|
||||
// invented to fill errorDetail.
|
||||
await handleMcpRequest(
|
||||
mcpRequest('tools/call', { name: 'gnubok_not_a_real_tool', arguments: {} })
|
||||
)
|
||||
|
||||
const event = await eventPromise
|
||||
expect(event.errorKind).toBe('unknown_tool')
|
||||
expect(event.errorDetail).toBeNull()
|
||||
})
|
||||
|
||||
it('applies the canonical scope gate to an Accounted alias', async () => {
|
||||
const eventPromise = captureNextToolCalledEvent()
|
||||
|
||||
|
||||
@@ -20398,8 +20398,14 @@ function emitToolCallTelemetry(payload: {
|
||||
success: boolean
|
||||
isError: boolean
|
||||
errorCode: string | null
|
||||
errorKind: 'execution' | 'scope_denied' | 'capability_denied' | 'company_access_denied' | 'unknown_tool' | 'test_key_write_blocked' | 'bridge_refused' | null
|
||||
errorKind: 'execution' | 'scope_denied' | 'capability_denied' | 'company_access_denied' | 'invalid_arguments' | 'unknown_tool' | 'test_key_write_blocked' | 'bridge_refused' | null
|
||||
errorMessage: string | null
|
||||
/**
|
||||
* The specific English diagnostic, passed as `structured.error.message_en`.
|
||||
* Stored only when it differs from errorMessage, so the common case where
|
||||
* message_sv is already the domain message costs nothing.
|
||||
*/
|
||||
errorDetail?: string | null
|
||||
requestId: string | number | null
|
||||
userId: string
|
||||
// null/empty while the key's user has no company yet (issue #1814): the
|
||||
@@ -20426,6 +20432,13 @@ function emitToolCallTelemetry(payload: {
|
||||
// validation messages can embed long lists. 500 chars is plenty for
|
||||
// clustering failures into gotchas without bloating event_log rows.
|
||||
errorMessage: payload.errorMessage ? payload.errorMessage.slice(0, 500) : null,
|
||||
// Only when it adds something. For most domain failures message_sv IS
|
||||
// the specific text and this is null; for the generic registry
|
||||
// defaults it is the difference between a usable log and a shrug.
|
||||
errorDetail:
|
||||
payload.errorDetail && payload.errorDetail !== payload.errorMessage
|
||||
? payload.errorDetail.slice(0, 500)
|
||||
: null,
|
||||
requestId: payload.requestId,
|
||||
userId: payload.userId,
|
||||
companyId,
|
||||
@@ -21049,6 +21062,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
errorCode: bridgeError.error.code,
|
||||
errorKind: 'bridge_refused',
|
||||
errorMessage: bridgeError.error.message_sv,
|
||||
errorDetail: bridgeError.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId,
|
||||
@@ -21112,6 +21126,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
errorCode: scopeError.error.code,
|
||||
errorKind: 'scope_denied',
|
||||
errorMessage: scopeError.error.message_sv,
|
||||
errorDetail: scopeError.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId,
|
||||
@@ -21176,8 +21191,17 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
success: false,
|
||||
isError: true,
|
||||
errorCode: structured.error.code,
|
||||
errorKind: 'company_access_denied',
|
||||
// Argument problems are not access problems. Exactly two things in
|
||||
// this try raise VALIDATION_ERROR (the unknown-parameter guard and a
|
||||
// malformed company_id) and neither is a permissions failure. Both
|
||||
// used to log as company_access_denied, which is how 604 rejected
|
||||
// calls read as a tenancy bug for a week.
|
||||
errorKind:
|
||||
structured.error.code === 'VALIDATION_ERROR'
|
||||
? 'invalid_arguments'
|
||||
: 'company_access_denied',
|
||||
errorMessage: structured.error.message_sv,
|
||||
errorDetail: structured.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
// Keep denied attempts attributed to the key default. An arbitrary,
|
||||
@@ -21217,6 +21241,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
errorCode: capError.error.code,
|
||||
errorKind: 'capability_denied',
|
||||
errorMessage: capError.error.message_sv,
|
||||
errorDetail: capError.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId: effectiveCompanyId,
|
||||
@@ -21258,6 +21283,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
errorCode: blocked.error.code,
|
||||
errorKind: 'test_key_write_blocked',
|
||||
errorMessage: blocked.error.message_sv,
|
||||
errorDetail: blocked.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId: effectiveCompanyId,
|
||||
@@ -21347,6 +21373,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
errorCode: structured.error.code,
|
||||
errorKind: 'execution',
|
||||
errorMessage: structured.error.message_sv,
|
||||
errorDetail: structured.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId: effectiveCompanyId,
|
||||
@@ -21439,6 +21466,7 @@ export async function handleMcpRequest(request: Request): Promise<Response> {
|
||||
// balanserar inte", "Perioden är låst", …): the text worth
|
||||
// clustering when mining failures for gotchas.
|
||||
errorMessage: structured.error.message_sv,
|
||||
errorDetail: structured.error.message_en,
|
||||
requestId: id ?? null,
|
||||
userId,
|
||||
companyId: effectiveCompanyId,
|
||||
|
||||
+10
-1
@@ -242,11 +242,20 @@ export type CoreEvent =
|
||||
success: boolean // true iff the tool returned without throwing AND was invoked (not denied)
|
||||
isError: boolean // matches the JSON-RPC tool-result isError flag returned to the client
|
||||
errorCode: string | null // structured error code from tool-result.toToolError when applicable
|
||||
errorKind: 'execution' | 'scope_denied' | 'capability_denied' | 'company_access_denied' | 'unknown_tool' | 'test_key_write_blocked' | 'bridge_refused' | null
|
||||
errorKind: 'execution' | 'scope_denied' | 'capability_denied' | 'company_access_denied' | 'invalid_arguments' | 'unknown_tool' | 'test_key_write_blocked' | 'bridge_refused' | null
|
||||
// bridge_refused: gnubok_call_tool was pointed at a write tool, or at nothing.
|
||||
// invalid_arguments: the call never reached the tool because its arguments
|
||||
// were rejected (unknown parameter, malformed company_id). Split out of
|
||||
// company_access_denied, which used to swallow both and send triage
|
||||
// looking for a permissions problem that did not exist.
|
||||
errorMessage: string | null // human-readable error message (truncated to 500 chars), null on success.
|
||||
// Raw material for clustering real agent failures into curated gotchas:
|
||||
// errorCode alone can't distinguish "period locked" from "unbalanced".
|
||||
errorDetail: string | null // The specific English diagnostic, when message_sv is a generic registry
|
||||
// default that says nothing (VALIDATION_ERROR -> "Förfrågan innehåller
|
||||
// ogiltiga uppgifter."). Null when it would only repeat errorMessage.
|
||||
// Without it a 604-call outage looked identical to a typo in the logs:
|
||||
// the agent was told exactly what was wrong, and we were not.
|
||||
requestId: string | number | null // JSON-RPC request id (helps correlate with client-side logs)
|
||||
userId: string
|
||||
companyId: string
|
||||
|
||||
Reference in New Issue
Block a user