From b29644fecf897459430a5a3f0897c92819432640 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Sat, 15 Aug 2026 18:57:52 +0300 Subject: [PATCH 1/5] feat(telemetry): preflight baseline counters (filter-diagnostics engagement + availability blocks) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase 0 of the required-tools-preflight roadmap. These counters ship ONE RELEASE AHEAD of the preflight feature on purpose: the metric preflight is meant to move is "how often does an agent silently fail to reach a tool that exists", and without a live pre-feature window there is nothing to compare the post-feature numbers against — "did preflight help?" would degrade into an argument about anecdotes. Shipping the measurement first buys a real before/after out of the normal release cadence. Two counter families, both on the existing Phase-H 24h-counter substrate (BBolt bucket, encodeCounter/readCounterWithDecay, closed enum keys, capped cardinality, counts only): 1. Filter-diagnostics engagement (spec 094 shipped with zero usage measurement): filter_diag_emitted_24h at the attach site, filter_diag_missing_annotation_24h / filter_diag_explicit_24h summed from the counts the block already computes, and filter_diag_followed_24h — a later retrieve_tools call in the same MCP session that dropped or relaxed a filter the block blamed. The follow-through note is in-memory, per session, TTL-bounded, capacity-capped and consumed on first use; it holds only the filter keys the response already named, and never leaves the process. 2. Availability / discovery-omission classes, derived from the STRUCTURED decision points rather than from error strings: every call site of the single policy-decision funnel now declares a reason key from a closed enum, feeding availability_block_24h plus availability_block_reasons_24h; and discovery_omission_24h counts retrieve_tools responses that withheld locked or quarantined matches the caller could not see. Privacy: counts only. The operator-facing block reason — which embeds server and tool names — stays in the activity log; a key outside the enum is folded into "other" at write time, filtered again at read time and in MarshalJSON, and a new anonymity-scanner rule (preflight_field_invalid) blocks the heartbeat if a non-enum key ever reaches the serialized payload. Counters are gated at EVENT time, so nothing is persisted while telemetry is opted out. The whole preflight sub-object is omitted when every counter is zero, so an install that never trips one emits a payload shape-identical to today's. Related #969 --- docs/features/telemetry.md | 53 ++ internal/runtime/runtime.go | 52 ++ internal/server/mcp.go | 77 ++- internal/server/mcp_routing.go | 3 +- internal/server/output_sanitisation.go | 7 +- internal/server/preflight_telemetry.go | 181 ++++++ internal/server/preflight_telemetry_test.go | 347 +++++++++++ internal/telemetry/anonymity.go | 123 ++++ internal/telemetry/payload_preflight_test.go | 233 +++++++ internal/telemetry/preflight_counters.go | 448 ++++++++++++++ internal/telemetry/preflight_counters_test.go | 575 ++++++++++++++++++ internal/telemetry/telemetry.go | 126 ++++ 12 files changed, 2208 insertions(+), 17 deletions(-) create mode 100644 internal/server/preflight_telemetry.go create mode 100644 internal/server/preflight_telemetry_test.go create mode 100644 internal/telemetry/payload_preflight_test.go create mode 100644 internal/telemetry/preflight_counters.go create mode 100644 internal/telemetry/preflight_counters_test.go diff --git a/docs/features/telemetry.md b/docs/features/telemetry.md index 66397ef1..f1cb2795 100644 --- a/docs/features/telemetry.md +++ b/docs/features/telemetry.md @@ -34,6 +34,7 @@ MCPProxy sends a **daily heartbeat** containing only aggregate, non-identifying | `last_error_code` | `MCPX_DOCKER_CLI_NOT_FOUND` | Most recent stable `MCPX_*` diagnostic code (schema v7). Enum code only, never error text | | `tpa_scanner` | `{"scans_completed":4,"scans_failed":0,"scans_with_findings":1,"findings":{"high":2}}` | Security/TPA scanner activity (schema v8) — counts only, keyed by the fixed severity enum. Omitted entirely when no scan ran | | `feature_flags.deep_scan_enabled` | `false` | Whether the opt-in deep-scan layer is turned on (schema v8) | +| `preflight` | `{"filter_diag_emitted_24h":3,"availability_block_24h":2,"availability_block_reasons_24h":{"server_quarantined":2},"discovery_omission_24h":5}` | Preflight baseline counters (issue #969) — counts only, reason map keyed by a fixed enum. Omitted entirely when nothing was counted. See below | The `server_protocol_counts` map uses a **fixed enum of keys** (`stdio`, `http`, `sse`, `streamable_http`, `auto`) — server names and URLs are never included. Unknown or misconfigured protocol values are bucketed into `auto`. @@ -158,6 +159,58 @@ The whole `tpa_scanner` object is **omitted** when every counter is zero, so an **Never transmitted**: the scanned server's name, the scanner id, rule ids, finding titles or descriptions, matched content, file paths, and scan error messages. +## Preflight baseline counters (issue #969) + +The `preflight` sub-object measures two things the proxy currently does silently: +how often a `retrieve_tools` response **explains a filter** it applied (spec 094's +`filter_diagnostics` block) and whether the agent then acted on that explanation, +and how often a tool the caller asked for **existed but was withheld**. + +These counters ship **one release ahead** of the required-tools-preflight feature +on purpose. Without a live pre-feature window there is nothing to compare the +post-feature numbers against, and "did preflight help?" degrades into an argument +about anecdotes. + +| Field | Type | What it counts | +|-------|------|----------------| +| `preflight.filter_diag_emitted_24h` | non-negative integer | `retrieve_tools` responses that carried a `filter_diagnostics` block in the last 24h — the denominator for the rest | +| `preflight.filter_diag_missing_annotation_24h` | non-negative integer | Omissions in those blocks caused by **absent upstream annotations** ("fix the server" class), summed across filters | +| `preflight.filter_diag_explicit_24h` | non-negative integer | Omissions caused by an **explicitly unsafe hint** ("the filter is working" class), summed across filters | +| `preflight.filter_diag_followed_24h` | non-negative integer | Blocks the agent **acted on**: a later `retrieve_tools` call in the same MCP session dropped or relaxed a filter the block blamed | +| `preflight.availability_block_24h` | non-negative integer | Policy **blocks** (quarantine, scope, permissions, tool approval, output policy) in the last 24h | +| `preflight.availability_block_reasons_24h` | map, **fixed enum keys only** → non-negative integer | The same total split by reason: `intent_invalid`, `intent_rejected`, `profile_scope`, `token_scope`, `token_permission`, `server_quarantined`, `tool_pending_approval`, `tool_changed_approval`, `tool_not_callable`, `output_sanitisation`, `output_schema`, `other` | +| `preflight.discovery_omission_24h` | non-negative integer | `retrieve_tools` responses that **withheld locked or quarantined matches** the caller could not see (`include_disabled` unset) — the silent-unavailability substrate | + +**How the reason keys stay safe.** The classification comes from the gate that +fired, not from parsing the message it wrote: every call site of the single +policy-decision funnel (`emitActivityPolicyDecision`) declares a key from the +closed enum above, while the operator-facing prose — which embeds server and tool +names — stays in the activity log and never reaches telemetry. A key outside the +enum is folded into `other` at write time, filtered again at read time and in the +wire form, and the anonymity scanner (rule `preflight_field_invalid`) blocks the +heartbeat outright if a non-enum key ever reaches the serialized payload. + +**The follow-through signal holds no identity.** Detecting "the agent relaxed the +filter" needs only the previous call's blamed filter *keys* plus the session it +belonged to. That note is in-memory, per session, expires after 15 minutes, +is capped, is consumed on first use (one block can be followed at most once), and +is never persisted or transmitted — only the resulting count is. + +Because that note is keyed by session, a transport that mints no session id +cannot be credited with a follow-through, while its emissions still count. Read +`filter_diag_followed_24h / filter_diag_emitted_24h` as a **lower bound** on +engagement, not an exact rate. + +The whole `preflight` object is **omitted** when every counter is zero, so an +install that never trips one emits a payload shape-identical to one from before +the field existed. Counters are gated at **event time**: nothing is written while +telemetry is opted out, so an occurrence observed during opt-out can never become +transmissible if telemetry is re-enabled later. + +**Never transmitted**: the query text, tool or server names, filter values, the +session id, the number of tools in the response, or any part of the suggestion +string the agent saw. + ## One-time opt-out signal When telemetry transitions from **enabled to disabled** (via the CLI, the config diff --git a/internal/runtime/runtime.go b/internal/runtime/runtime.go index 666b0c28..0dd51130 100644 --- a/internal/runtime/runtime.go +++ b/internal/runtime/runtime.go @@ -2789,6 +2789,14 @@ func (r *Runtime) SetTelemetry(version, edition string) { diagStore := telemetry.NewDiagnosticsCounterStore() r.telemetryService.SetDiagnosticsCounterStore(diagStore, db) + // Issue #969 (Phase 0): wire the preflight baseline counter store + // on the same DB, pre-creating its bucket for the same + // first-write-race reason as the diagnostics bucket above. + if err := telemetry.EnsurePreflightCountersBucket(db); err != nil { + r.logger.Warn("Failed to ensure preflight_counters bucket", zap.Error(err)) + } + r.telemetryService.SetPreflightCounterStore(telemetry.NewPreflightCounterStore(), db) + // Wire error-code notifier into supervisor so every classified // DiagnosticError increments the 24h per-code counter. Spec 080 // (US3, FR-012): the same stream also refreshes last_error_code — @@ -2902,6 +2910,50 @@ func (r *Runtime) RecordRetrieveToolsCallForActivation() { } } +// --- Issue #969 (Phase 0): preflight baseline counters --- +// +// These forwarders keep internal/server unaware of BBolt, exactly like +// RecordRetrieveToolsCallForActivation above. Each is nil-safe and the +// telemetry service applies the event-time opt-out gate, so a counter is never +// persisted for an install that has telemetry off. + +// RecordFilterDiagnosticsEmitted counts one retrieve_tools response that +// attached a spec-094 filter_diagnostics block, plus that block's summed +// per-reason-class counts. +func (r *Runtime) RecordFilterDiagnosticsEmitted(missingAnnotation, explicit int) { + if r == nil || r.telemetryService == nil { + return + } + r.telemetryService.RecordFilterDiagnosticsEmitted(missingAnnotation, explicit) +} + +// RecordFilterDiagnosticsFollowed counts one diagnostics block the agent acted +// on within the same MCP session. +func (r *Runtime) RecordFilterDiagnosticsFollowed() { + if r == nil || r.telemetryService == nil { + return + } + r.telemetryService.RecordFilterDiagnosticsFollowed() +} + +// RecordAvailabilityBlock counts one policy block by its structured reason key +// (closed enum; see telemetry.BlockReason*). +func (r *Runtime) RecordAvailabilityBlock(reason string) { + if r == nil || r.telemetryService == nil { + return + } + r.telemetryService.RecordAvailabilityBlock(reason) +} + +// RecordDiscoveryOmission counts one retrieve_tools response that withheld +// locked/quarantined matches the caller could not see. +func (r *Runtime) RecordDiscoveryOmission() { + if r == nil || r.telemetryService == nil { + return + } + r.telemetryService.RecordDiscoveryOmission() +} + // SetSessionClientResolver wires the session -> MCP client lookup that stamps // client_name / client_version onto every activity record at write time. // No-op if the activity service is not wired. diff --git a/internal/server/mcp.go b/internal/server/mcp.go index 29beff01..e37af41e 100644 --- a/internal/server/mcp.go +++ b/internal/server/mcp.go @@ -178,6 +178,14 @@ type MCPProxyServer struct { // when observability is disabled; all use sites must nil-guard. observability *observability.Manager + // Issue #969 (Phase 0): per-session note of the last retrieve_tools call + // that carried a spec-094 filter_diagnostics block, used to detect whether + // the agent then RELAXED a blamed filter. In-memory only, never persisted, + // and it holds no query text or tool identities — only the filter keys the + // block already named plus a timestamp. See preflight_telemetry.go. + filterDiagMu sync.Mutex + filterDiagNotes map[string]filterDiagNote + // configFilePath is the ACTIVE configuration FILE this server belongs to, // handed in at construction (Spec 097). It is the authority for anything // derived from the config directory — today the stored-scripts directory. @@ -674,10 +682,23 @@ func (p *MCPProxyServer) emitActivityToolCallCompleted(serverName, toolName, ses // event and the record persisted from it are recognisably one thing. Gates that // fire before a handler would otherwise mint an id have to mint it earlier // rather than pass "" — see mintActivityRequestID. -func (p *MCPProxyServer) emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, decision, reason string) { +// +// reasonKey is the STRUCTURED classification of this decision, declared by the +// call site from the closed telemetry.BlockReason* enum (issue #969). `reason` +// is operator-facing prose that embeds server and tool names and must never +// reach telemetry; reasonKey is what the availability counters aggregate on, so +// the classification comes from the gate that fired rather than from parsing +// the message it wrote. A key outside the enum is folded into "other" by the +// store. +func (p *MCPProxyServer) emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, decision, reason, reasonKey string) { if p.mainServer != nil && p.mainServer.runtime != nil { p.mainServer.runtime.EmitActivityPolicyDecision(serverName, toolName, sessionID, requestID, decision, reason) } + // Issue #969 (Phase 0): availability baseline. Only outright blocks count — + // a warning or a redaction still delivered the call. + if decision == "blocked" { + p.recordAvailabilityBlock(reasonKey) + } } // activityRequestIDSeq disambiguates ids minted within the same nanosecond. @@ -1452,6 +1473,17 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques excludeDestructive := request.GetBool("exclude_destructive", false) excludeOpenWorld := request.GetBool("exclude_open_world", false) + // Issue #969 (Phase 0): filter-diagnostics FOLLOW-THROUGH. If the previous + // retrieve_tools call in this session was handed a spec-094 diagnostics + // block, this call counts as "followed" when it dropped or relaxed at least + // one of the filters that block blamed. The note is consumed either way, so + // one block can be followed at most once. Evaluated here — before this + // call can write a note of its own — and never blocks the request. + if p.consumeFilterDiagFollowUp(sessionID, + activeFilterKeys(readOnlyOnly, excludeDestructive, excludeOpenWorld), startTime) { + p.recordFilterDiagnosticsFollowed() + } + // Build arguments map for activity logging (Spec 024) args := map[string]interface{}{ "query": query, @@ -1727,6 +1759,12 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques // to the pre-feature one. if filterDiag != nil && filterDiag.OmittedTotal >= 1 { response["filter_diagnostics"] = filterDiag + + // Issue #969 (Phase 0): baseline engagement counters, hooked at the + // ATTACH site so "emitted" means "the agent actually received a block". + // Counts only; the note is in-memory and identity-free. + p.recordFilterDiagnosticsEmitted(filterDiag) + p.noteFilterDiagnostics(sessionID, filterDiag, startTime) } // Spec 085 (FR-009): compact responses carry one deterministic hint line @@ -1767,6 +1805,17 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques droppedCount) } + // Issue #969 (Phase 0): silent-unavailability baseline. droppedCount is the + // authoritative tally of locked/quarantined matches this response withheld + // (index hits that failed the visibility gate, plus the quarantined + // second-pass entries) — out-of-scope servers are excluded upstream, so this + // counts only tools the caller could have had. Without include_disabled the + // caller never sees them, which is exactly the invisibility preflight exists + // to remove. One increment per response, never per tool. + if !includeDisabled && droppedCount > 0 { + p.recordDiscoveryOmission() + } + // Spec 035 F2: Session risk analysis — analyze all connected servers' tool annotations // to detect the "lethal trifecta" risk combination. // @@ -1962,7 +2011,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. if logTool == "" { logTool = toolName } - p.emitActivityPolicyDecision(logServer, logTool, getSessionID(), requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(logServer, logTool, getSessionID(), requestID, "blocked", errMsg, telemetry.BlockReasonIntentInvalid) return mcp.NewToolResultError(errMsg), nil } @@ -1978,7 +2027,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. if logTool == "" { logTool = toolName } - p.emitActivityPolicyDecision(logServer, logTool, getSessionID(), requestID, "blocked", "Intent validation failed") + p.emitActivityPolicyDecision(logServer, logTool, getSessionID(), requestID, "blocked", "Intent validation failed", telemetry.BlockReasonIntentRejected) return errResult, nil } @@ -2016,7 +2065,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. // filtered, and so a base /mcp session that ran set_profile is bounded too. if _, profileScope := p.resolveActiveProfile(ctx); profileScope != nil && !profileScope.Allows(serverName) { errMsg := fmt.Sprintf("server '%s' is not in profile '%s'", serverName, profileScope.Name) - p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg, telemetry.BlockReasonProfileScope) return mcp.NewToolResultError(errMsg), nil } @@ -2025,7 +2074,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. // Check server scope if !authCtx.CanAccessServer(serverName) { errMsg := fmt.Sprintf("Server '%s' is not in scope for this agent token", serverName) - p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg, telemetry.BlockReasonTokenScope) return mcp.NewToolResultError(errMsg), nil } // Check permission scope — map tool variant to required permission @@ -2040,7 +2089,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. } if requiredPerm != "" && !authCtx.HasPermission(requiredPerm) { errMsg := fmt.Sprintf("Insufficient permissions: '%s' requires '%s' permission", toolVariant, requiredPerm) - p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", errMsg, telemetry.BlockReasonTokenPermission) return mcp.NewToolResultError(errMsg), nil } } @@ -2067,7 +2116,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. if errResult := p.validateIntentAgainstServer(intent, toolVariant, serverName, actualToolName, annotations); errResult != nil { // Record activity error for server annotation mismatch reason := fmt.Sprintf("Intent rejected: tool variant '%s' conflicts with server annotations for %s:%s", toolVariant, serverName, actualToolName) - p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", reason) + p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", reason, telemetry.BlockReasonIntentRejected) return errResult, nil } @@ -2114,7 +2163,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. zap.String("server_name", serverName)) // Emit policy decision event for quarantine block - p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", "Server is quarantined for security review") + p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", "Server is quarantined for security review", telemetry.BlockReasonServerQuarantined) // Server is in quarantine - return security warning with tool analysis return p.handleQuarantinedToolCall(ctx, serverName, actualToolName, activityArgs), nil @@ -2130,7 +2179,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. zap.String("tool_name", actualToolName)) p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", - "Tool is pending approval (new unapproved tool)") + "Tool is pending approval (new unapproved tool)", telemetry.BlockReasonToolPendingApproval) return toolPendingApprovalResult(serverName, actualToolName, approval), nil } @@ -2140,7 +2189,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. zap.String("tool_name", actualToolName)) p.emitActivityPolicyDecision(serverName, actualToolName, getSessionID(), requestID, "blocked", - "Tool description/schema changed since last approval") + "Tool description/schema changed since last approval", telemetry.BlockReasonToolChanged) return toolChangedApprovalResult(serverName, actualToolName, approval), nil } @@ -2150,7 +2199,7 @@ func (p *MCPProxyServer) handleCallToolVariant(ctx context.Context, request mcp. if !p.isToolCallable(serverName, actualToolName) { errMsg := p.blockedToolMessage(serverName, actualToolName) - p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", errMsg, telemetry.BlockReasonToolNotCallable) return mcp.NewToolResultError(errMsg), nil } @@ -2633,7 +2682,7 @@ func (p *MCPProxyServer) handleCallTool(ctx context.Context, request mcp.CallToo zap.String("server_name", serverName)) // Emit policy decision event for quarantine block - p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", "Server is quarantined for security review") + p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", "Server is quarantined for security review", telemetry.BlockReasonServerQuarantined) // Server is in quarantine - return security warning with tool analysis return p.handleQuarantinedToolCall(ctx, serverName, actualToolName, args), nil @@ -2644,7 +2693,7 @@ func (p *MCPProxyServer) handleCallTool(ctx context.Context, request mcp.CallToo if !p.isToolCallable(serverName, actualToolName) { errMsg := p.blockedToolMessage(serverName, actualToolName) - p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", errMsg) + p.emitActivityPolicyDecision(serverName, actualToolName, sessionID, requestID, "blocked", errMsg, telemetry.BlockReasonToolNotCallable) return mcp.NewToolResultError(errMsg), nil } @@ -6206,7 +6255,7 @@ func (p *MCPProxyServer) applyOutputValidation(ctx context.Context, serverName, if sess := mcpserver.ClientSessionFromContext(ctx); sess != nil { sessionID = sess.SessionID() } - p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, d.decision, d.reason) + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, d.decision, d.reason, telemetry.BlockReasonOutputSchema) if d.block { return mcp.NewToolResultError("output schema validation failed: " + d.reason) } diff --git a/internal/server/mcp_routing.go b/internal/server/mcp_routing.go index 0e2710a2..4d7da6e2 100644 --- a/internal/server/mcp_routing.go +++ b/internal/server/mcp_routing.go @@ -16,6 +16,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/contracts" "github.com/smart-mcp-proxy/mcpproxy-go/internal/reqcontext" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/telemetry" ) const ( @@ -199,7 +200,7 @@ func (p *MCPProxyServer) makeDirectModeHandler(serverName, toolName string, anno // invoking upstream. Direct mode must not bypass disabled, quarantine, or // approval controls enforced by call_tool_* variants. if blocked := p.directToolCallabilityBlock(ctx, serverName, toolName, enrichedArgs); blocked != nil { - p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", "direct tool is not callable") + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", "direct tool is not callable", telemetry.BlockReasonToolNotCallable) return blocked, nil } diff --git a/internal/server/output_sanitisation.go b/internal/server/output_sanitisation.go index 92debf2b..fc0201cf 100644 --- a/internal/server/output_sanitisation.go +++ b/internal/server/output_sanitisation.go @@ -13,6 +13,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/contracts" "github.com/smart-mcp-proxy/mcpproxy-go/internal/security" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/telemetry" ) // osDecision is the pure outcome of the output-sanitisation decision core @@ -109,7 +110,7 @@ func (p *MCPProxyServer) applyOutputSanitisation(ctx context.Context, serverName } if d.block { - p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", d.reason) + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", d.reason, telemetry.BlockReasonOutputSanitisation) return mcp.NewToolResultError("tool output blocked by sanitisation policy: " + d.reason) } @@ -151,7 +152,9 @@ func (p *MCPProxyServer) applyOutputSanitisation(ctx context.Context, serverName if redactedCount > 0 || len(strippedClasses) > 0 { action, reason := summariseSanitisation(redactedCount, redactedCats, strippedClasses) - p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, action, reason) + // Redact/strip are not blocks — the availability counter ignores them — + // but the key is still declared so the funnel has no unclassified sites. + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, action, reason, telemetry.BlockReasonOutputSanitisation) } return nil diff --git a/internal/server/preflight_telemetry.go b/internal/server/preflight_telemetry.go new file mode 100644 index 00000000..6174923e --- /dev/null +++ b/internal/server/preflight_telemetry.go @@ -0,0 +1,181 @@ +package server + +import ( + "sort" + "time" +) + +// Issue #969 (Phase 0) — preflight BASELINE counters. +// +// These ship one release AHEAD of the required-tools-preflight feature so a +// real live before/after window exists: without it, "did preflight reduce +// silent unavailability?" can only be argued from anecdotes. Everything here is +// counts-only — no tool name, server name, query, session id, or free text ever +// reaches telemetry (see internal/telemetry/preflight_counters.go for the +// enforced contract). + +// recordFilterDiagnosticsEmitted counts one retrieve_tools response that +// attached a spec-094 filter_diagnostics block, summing the block's per-reason +// classes across every filter it blamed. The counts are already computed by +// filterByAnnotationsWithDiagnostics — this only adds them up. nil-safe. +func (p *MCPProxyServer) recordFilterDiagnosticsEmitted(diag *filterDiagnostics) { + if diag == nil || p.mainServer == nil || p.mainServer.runtime == nil { + return + } + missing, explicit := 0, 0 + for _, counts := range diag.OmittedByFilter { + missing += counts.MissingAnnotation + explicit += counts.Explicit + } + p.mainServer.runtime.RecordFilterDiagnosticsEmitted(missing, explicit) +} + +// recordDiscoveryOmission counts one retrieve_tools response that withheld +// locked/quarantined matches the caller could not see. nil-safe. +func (p *MCPProxyServer) recordDiscoveryOmission() { + if p.mainServer == nil || p.mainServer.runtime == nil { + return + } + p.mainServer.runtime.RecordDiscoveryOmission() +} + +// recordFilterDiagnosticsFollowed counts one diagnostics block the agent acted +// on. nil-safe. +func (p *MCPProxyServer) recordFilterDiagnosticsFollowed() { + if p.mainServer == nil || p.mainServer.runtime == nil { + return + } + p.mainServer.runtime.RecordFilterDiagnosticsFollowed() +} + +// recordAvailabilityBlock counts one policy block under its structured reason +// key. nil-safe. +func (p *MCPProxyServer) recordAvailabilityBlock(reason string) { + if p.mainServer == nil || p.mainServer.runtime == nil { + return + } + p.mainServer.runtime.RecordAvailabilityBlock(reason) +} + +// --- filter-diagnostics follow-through, per session --- + +// filterDiagNote remembers the filters a diagnostics block blamed on the last +// retrieve_tools call of one MCP session. It deliberately carries nothing else: +// no query, no tool ids, no counts — just the closed set of filter parameter +// names the response already told the agent about, plus when it was written so +// stale notes expire. +type filterDiagNote struct { + // filters are the filter keys the block blamed (filterKeyReadOnlyOnly &c), + // sorted so comparisons are order-independent. + filters []string + at time.Time +} + +const ( + // filterDiagNoteTTL bounds how long a note stays eligible. A follow-up an + // hour later is a new task, not a reaction to the diagnostics block. + filterDiagNoteTTL = 15 * time.Minute + + // maxFilterDiagNotes bounds the in-memory note map. Sessions are pruned + // oldest-first past this; a proxy serving thousands of sessions must not + // grow an unbounded map for a telemetry counter. + maxFilterDiagNotes = 256 +) + +// activeFilterKeys renders the filter parameters active on THIS call as the +// same key strings the diagnostics block uses. +func activeFilterKeys(readOnlyOnly, excludeDestructive, excludeOpenWorld bool) []string { + keys := make([]string, 0, 3) + if readOnlyOnly { + keys = append(keys, filterKeyReadOnlyOnly) + } + if excludeDestructive { + keys = append(keys, filterKeyExcludeDestruct) + } + if excludeOpenWorld { + keys = append(keys, filterKeyExcludeOpenWorld) + } + return keys +} + +// noteFilterDiagnostics remembers that this session was just handed a +// diagnostics block blaming `diag`'s filters. Sessions without an id (stdio +// transports that do not mint one) are skipped rather than pooled under "", +// which would let one client's call count as another's follow-up. +func (p *MCPProxyServer) noteFilterDiagnostics(sessionID string, diag *filterDiagnostics, at time.Time) { + if sessionID == "" || diag == nil || len(diag.OmittedByFilter) == 0 { + return + } + filters := make([]string, 0, len(diag.OmittedByFilter)) + for key := range diag.OmittedByFilter { + filters = append(filters, key) + } + sort.Strings(filters) + + p.filterDiagMu.Lock() + defer p.filterDiagMu.Unlock() + if p.filterDiagNotes == nil { + p.filterDiagNotes = make(map[string]filterDiagNote) + } + p.pruneFilterDiagNotesLocked(at) + p.filterDiagNotes[sessionID] = filterDiagNote{filters: filters, at: at} +} + +// consumeFilterDiagFollowUp reports whether THIS call is a follow-up that +// relaxed or dropped at least one filter the previous call's diagnostics block +// blamed. The note is consumed either way: a block gets exactly one chance to +// be followed, so a session that keeps re-running the same filtered query can +// never inflate the counter. +func (p *MCPProxyServer) consumeFilterDiagFollowUp(sessionID string, activeKeys []string, at time.Time) bool { + if sessionID == "" { + return false + } + + p.filterDiagMu.Lock() + defer p.filterDiagMu.Unlock() + note, ok := p.filterDiagNotes[sessionID] + if !ok { + return false + } + delete(p.filterDiagNotes, sessionID) + if at.Sub(note.at) > filterDiagNoteTTL { + return false + } + + active := make(map[string]struct{}, len(activeKeys)) + for _, k := range activeKeys { + active[k] = struct{}{} + } + for _, blamed := range note.filters { + if _, still := active[blamed]; !still { + return true // a blamed filter was dropped → the agent acted on it + } + } + return false +} + +// pruneFilterDiagNotesLocked drops expired notes and, if the map is still at +// capacity, the oldest entries. Caller holds filterDiagMu. +func (p *MCPProxyServer) pruneFilterDiagNotesLocked(now time.Time) { + for sid, note := range p.filterDiagNotes { + if now.Sub(note.at) > filterDiagNoteTTL { + delete(p.filterDiagNotes, sid) + } + } + if len(p.filterDiagNotes) < maxFilterDiagNotes { + return + } + type entry struct { + sid string + at time.Time + } + entries := make([]entry, 0, len(p.filterDiagNotes)) + for sid, note := range p.filterDiagNotes { + entries = append(entries, entry{sid, note.at}) + } + sort.Slice(entries, func(i, j int) bool { return entries[i].at.Before(entries[j].at) }) + // Evict down to capacity-1 so the caller's insert stays within the bound. + for i := 0; i <= len(entries)-maxFilterDiagNotes; i++ { + delete(p.filterDiagNotes, entries[i].sid) + } +} diff --git a/internal/server/preflight_telemetry_test.go b/internal/server/preflight_telemetry_test.go new file mode 100644 index 00000000..a2fc7665 --- /dev/null +++ b/internal/server/preflight_telemetry_test.go @@ -0,0 +1,347 @@ +package server + +import ( + "context" + "testing" + "time" + + "github.com/mark3labs/mcp-go/mcp" + mcpserver "github.com/mark3labs/mcp-go/server" + "github.com/stretchr/testify/require" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/runtime" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/telemetry" +) + +// Issue #969 (Phase 0) — preflight baseline counters, server side. + +// pinTelemetryEnvEnabledForServer neutralises the env opt-outs so these tests +// exercise the ENABLED path even on a CI machine (CI=true is a telemetry +// opt-out, which would silently turn every increment into a no-op). +func pinTelemetryEnvEnabledForServer(t *testing.T) { + t.Helper() + t.Setenv("CI", "") + t.Setenv("DO_NOT_TRACK", "") + t.Setenv("MCPPROXY_TELEMETRY", "") +} + +// --- follow-through bookkeeping (pure, no runtime needed) --- + +func TestActiveFilterKeys(t *testing.T) { + require.Empty(t, activeFilterKeys(false, false, false)) + require.Equal(t, []string{filterKeyReadOnlyOnly}, activeFilterKeys(true, false, false)) + require.Equal(t, + []string{filterKeyReadOnlyOnly, filterKeyExcludeDestruct, filterKeyExcludeOpenWorld}, + activeFilterKeys(true, true, true)) +} + +func diagBlaming(filters ...string) *filterDiagnostics { + d := &filterDiagnostics{OmittedByFilter: map[string]reasonCounts{}} + for _, f := range filters { + d.OmittedByFilter[f] = reasonCounts{MissingAnnotation: 1} + d.OmittedTotal++ + } + return d +} + +// A follow-up that DROPS the blamed filter counts as followed. +func TestFilterDiagFollowUp_DroppedFilterCounts(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), now) + require.True(t, p.consumeFilterDiagFollowUp("sess-1", nil, now.Add(5*time.Second))) +} + +// A follow-up that RELAXES one of several blamed filters still counts. +func TestFilterDiagFollowUp_RelaxedSubsetCounts(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", + diagBlaming(filterKeyReadOnlyOnly, filterKeyExcludeOpenWorld), now) + // exclude_open_world dropped, read_only_only kept. + require.True(t, p.consumeFilterDiagFollowUp("sess-1", + activeFilterKeys(true, false, false), now.Add(time.Second))) +} + +// Re-running the SAME filters is not a follow-up. +func TestFilterDiagFollowUp_SameFiltersDoNotCount(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), now) + require.False(t, p.consumeFilterDiagFollowUp("sess-1", + activeFilterKeys(true, false, false), now.Add(time.Second))) +} + +// The note is consumed once: a second relaxed call cannot double-count the +// same diagnostics block. +func TestFilterDiagFollowUp_NoteConsumedOnce(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), now) + require.True(t, p.consumeFilterDiagFollowUp("sess-1", nil, now.Add(time.Second))) + require.False(t, p.consumeFilterDiagFollowUp("sess-1", nil, now.Add(2*time.Second))) +} + +// Follow-ups from a DIFFERENT session never match. +func TestFilterDiagFollowUp_SessionScoped(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), now) + require.False(t, p.consumeFilterDiagFollowUp("sess-2", nil, now.Add(time.Second))) + // sess-1's note is untouched by sess-2's call. + require.True(t, p.consumeFilterDiagFollowUp("sess-1", nil, now.Add(2*time.Second))) +} + +// Sessions without an id are never pooled together under "". +func TestFilterDiagFollowUp_AnonymousSessionsIgnored(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("", diagBlaming(filterKeyReadOnlyOnly), now) + require.Empty(t, p.filterDiagNotes) + require.False(t, p.consumeFilterDiagFollowUp("", nil, now)) +} + +// A stale note expires rather than crediting an unrelated later task. +func TestFilterDiagFollowUp_TTLExpiry(t *testing.T) { + p := &MCPProxyServer{} + now := time.Now() + + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), now) + require.False(t, p.consumeFilterDiagFollowUp("sess-1", nil, now.Add(filterDiagNoteTTL+time.Minute))) +} + +// The note map is bounded: a proxy serving many sessions must not grow it +// without limit for a telemetry counter. +func TestFilterDiagNotes_Bounded(t *testing.T) { + p := &MCPProxyServer{} + base := time.Now() + + for i := 0; i < maxFilterDiagNotes*3; i++ { + sid := "sess-" + time.Duration(i).String() + p.noteFilterDiagnostics(sid, diagBlaming(filterKeyReadOnlyOnly), base.Add(time.Duration(i)*time.Millisecond)) + } + require.LessOrEqual(t, len(p.filterDiagNotes), maxFilterDiagNotes) +} + +// --- end-to-end through retrieve_tools --- + +// newPreflightCountedProxy builds the spec-094 fixture proxy with a telemetry +// service (and therefore the preflight counter store) wired onto the runtime's +// BBolt DB, so the counters the handler bumps can be read back. +func newPreflightCountedProxy(t *testing.T) (*MCPProxyServer, *runtime.Runtime) { + t.Helper() + pinTelemetryEnvEnabledForServer(t) + + proxy, rt := newFilterDiagnosticsProxy(t) + rt.SetTelemetry("v1.0.0", "personal") + ts := rt.TelemetryService() + require.NotNil(t, ts, "telemetry service must be wired") + require.NotNil(t, ts.PreflightCounterStore(), "preflight counter store must be wired") + return proxy, rt +} + +func preflightSnapshot(t *testing.T, rt *runtime.Runtime) telemetry.PreflightCounters { + t.Helper() + ts := rt.TelemetryService() + require.NotNil(t, ts) + snap, err := ts.PreflightCounterStore().Snapshot(ts.PreflightCounterDB()) + require.NoError(t, err) + return snap +} + +func retrieveWithSession(t *testing.T, proxy *MCPProxyServer, sessionID string, args map[string]interface{}) { + t.Helper() + helper := mcpserver.NewMCPServer("test", "1.0.0") + ctx := helper.WithContext(context.Background(), &fakeClientSession{id: sessionID}) + req := mcp.CallToolRequest{} + req.Params.Arguments = args + _, err := proxy.handleRetrieveTools(ctx, req) + require.NoError(t, err) +} + +// A response that carries a filter_diagnostics block bumps the emitted counter +// and both reason-class sums. +func TestPreflightCounters_FilterDiagnosticsEmitted(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + "read_only_only": true, + }) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 1, snap.FilterDiagEmitted24h) + require.Positive(t, snap.FilterDiagMissingAnnotation24h, + "the fixture omits unannotated tools, so the missing class must be non-zero") + require.Positive(t, snap.FilterDiagExplicit24h, + "the fixture omits an explicitly non-read-only tool") + require.Equal(t, 0, snap.FilterDiagFollowed24h) +} + +// The happy path (no filters) attaches no block and therefore counts nothing. +func TestPreflightCounters_NoDiagnosticsNoCount(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{"query": diagQueryAll}) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 0, snap.FilterDiagEmitted24h) + require.Equal(t, 0, snap.FilterDiagFollowed24h) +} + +// A second call in the SAME session that drops the blamed filter is counted as +// a follow-through; a same-session repeat of the same filters is not. +func TestPreflightCounters_FilterDiagnosticsFollowed(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + "read_only_only": true, + }) + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + }) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 1, snap.FilterDiagEmitted24h) + require.Equal(t, 1, snap.FilterDiagFollowed24h) +} + +func TestPreflightCounters_FilterDiagnosticsNotFollowedWhenFiltersRepeat(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + for i := 0; i < 3; i++ { + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + "read_only_only": true, + }) + } + + snap := preflightSnapshot(t, rt) + require.Equal(t, 3, snap.FilterDiagEmitted24h) + require.Equal(t, 0, snap.FilterDiagFollowed24h, + "re-running the same filters is not a follow-through") +} + +// A different session's later call must not be credited as a follow-through. +func TestPreflightCounters_FollowThroughIsSessionScoped(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + "read_only_only": true, + }) + retrieveWithSession(t, proxy, "sess-2", map[string]interface{}{ + "query": diagQueryAll, + }) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 0, snap.FilterDiagFollowed24h) +} + +// A retrieve_tools response that withheld locked matches bumps the +// silent-unavailability counter; one that withheld nothing does not. +func TestPreflightCounters_DiscoveryOmission(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + // Disable a server so its indexed tools become locked (not callable) and + // are dropped from the default (include_disabled=false) response. + require.NoError(t, proxy.storage.SaveUpstreamServer(&config.ServerConfig{ + Name: "plain", Enabled: false, + })) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{"query": diagQueryAll}) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 1, snap.DiscoveryOmission24h) +} + +func TestPreflightCounters_NoDiscoveryOmissionWhenNothingWithheld(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{"query": diagQueryAll}) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 0, snap.DiscoveryOmission24h) +} + +// --- availability blocks --- + +// A policy BLOCK increments the total and its structured reason bucket; a +// non-block decision (warn / redact) on the same funnel does not. +func TestPreflightCounters_AvailabilityBlockByReason(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + proxy.emitActivityPolicyDecision("srv", "tool", "sess-1", "req-1", + "blocked", "Server is quarantined for security review", + telemetry.BlockReasonServerQuarantined) + proxy.emitActivityPolicyDecision("srv", "tool", "sess-1", "req-2", + "blocked", "Server 'srv' is not in scope for this agent token", + telemetry.BlockReasonTokenScope) + proxy.emitActivityPolicyDecision("srv", "tool", "sess-1", "req-3", + "redacted", "1 secret redacted", telemetry.BlockReasonOutputSanitisation) + + snap := preflightSnapshot(t, rt) + require.Equal(t, 2, snap.AvailabilityBlock24h, "only blocks count") + require.Equal(t, 1, snap.AvailabilityBlockReasons24h[telemetry.BlockReasonServerQuarantined]) + require.Equal(t, 1, snap.AvailabilityBlockReasons24h[telemetry.BlockReasonTokenScope]) + require.Zero(t, snap.AvailabilityBlockReasons24h[telemetry.BlockReasonOutputSanitisation]) +} + +// The operator-facing prose (which embeds server and tool names) never becomes +// a counter key — an unclassified site lands in "other". +func TestPreflightCounters_UnclassifiedBlockFoldsIntoOther(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + + proxy.emitActivityPolicyDecision("acme-internal", "purge_all", "sess-1", "req-1", + "blocked", "Server 'acme-internal' is not in scope for this agent token", + "some-future-unregistered-key") + + snap := preflightSnapshot(t, rt) + require.Equal(t, 1, snap.AvailabilityBlock24h) + require.Equal(t, 1, snap.AvailabilityBlockReasons24h[telemetry.BlockReasonOther]) + for key := range snap.AvailabilityBlockReasons24h { + require.True(t, telemetry.IsAvailabilityBlockReason(key), + "non-enum key %q reached the counters", key) + } +} + +// Every counter path is a no-op when telemetry is opted out at event time. +func TestPreflightCounters_OptOutRecordsNothing(t *testing.T) { + proxy, rt := newPreflightCountedProxy(t) + t.Setenv("DO_NOT_TRACK", "1") + + retrieveWithSession(t, proxy, "sess-1", map[string]interface{}{ + "query": diagQueryAll, + "read_only_only": true, + }) + proxy.emitActivityPolicyDecision("srv", "tool", "sess-1", "req-1", + "blocked", "quarantined", telemetry.BlockReasonServerQuarantined) + + snap := preflightSnapshot(t, rt) + require.Equal(t, telemetry.PreflightCounters{}, snap, + "nothing may be persisted while telemetry is opted out") +} + +// The hooks must be safe on a proxy with no runtime at all (the CLI's +// in-process server), and on a runtime whose telemetry service was never set. +func TestPreflightCounters_NilSafe(t *testing.T) { + bare := &MCPProxyServer{} + bare.recordFilterDiagnosticsEmitted(diagBlaming(filterKeyReadOnlyOnly)) + bare.recordFilterDiagnosticsFollowed() + bare.recordDiscoveryOmission() + bare.recordAvailabilityBlock(telemetry.BlockReasonOther) + + proxy, _ := newFilterDiagnosticsProxy(t) // runtime, but no telemetry service + proxy.recordFilterDiagnosticsEmitted(diagBlaming(filterKeyReadOnlyOnly)) + proxy.recordFilterDiagnosticsFollowed() + proxy.recordDiscoveryOmission() + proxy.recordAvailabilityBlock(telemetry.BlockReasonOther) +} diff --git a/internal/telemetry/anonymity.go b/internal/telemetry/anonymity.go index 0edc95dc..e52629e4 100644 --- a/internal/telemetry/anonymity.go +++ b/internal/telemetry/anonymity.go @@ -97,6 +97,11 @@ type anonymityScanEnvelope struct { // error_code_counts_24h map must be cataloged codes → non-negative counts. // Same not-a-pointer reasoning as TPAScanner. Diagnostics json.RawMessage `json:"diagnostics"` + + // Issue #969 structural check: the preflight baseline counter sub-object, + // whose availability_block_reasons_24h map must be closed-enum reason keys + // → non-negative counts. Same not-a-pointer reasoning as TPAScanner. + Preflight json.RawMessage `json:"preflight"` } // v7FieldViolation builds the violation for a Spec 080 field that broke its @@ -347,6 +352,114 @@ func scanDiagnosticsCounters(raw json.RawMessage) *AnonymityViolation { return nil } +// preflightFieldViolation builds the violation for a preflight counter field +// that broke its documented shape (closed-enum reason keys, non-negative +// counts). +func preflightFieldViolation(field, reason string) *AnonymityViolation { + return &AnonymityViolation{ + Rule: "preflight_field_invalid", + Pattern: field, + Reason: fmt.Sprintf("preflight field %s %s", field, reason), + } +} + +// scanPreflightCounters asserts the preflight sub-object (if present) is a +// CLOSED object of non-negative integer counts whose +// availability_block_reasons_24h map is keyed EXCLUSIVELY by the closed +// availability-block reason enum (issue #969). +// The producer folds unknown reasons into "other" and MarshalJSON filters again; +// this is the wire-form backstop, so a regression that let a reason STRING +// (which embeds server and tool names) become a key is caught before transmit. +// Keys are where identifying strings would leak, so the violation deliberately +// never echoes the offending key. +func scanPreflightCounters(raw json.RawMessage) *AnonymityViolation { + if len(raw) == 0 { + return nil + } + var obj map[string]json.RawMessage + // json.Unmarshal accepts `null` into a nil map; the field, when present, + // must be a real object. + if err := json.Unmarshal(raw, &obj); err != nil || obj == nil { + return preflightFieldViolation("preflight", "must be an object") + } + + // The sub-object is CLOSED: only the documented count keys plus the reason + // map may appear. Validating the known scalars alone would let a future + // field that carries free text (a server name, a query, an error message) + // ride along unchecked — exactly the leak this rule exists to stop. A new + // counter must be added to preflightAllowedKeys deliberately, which is the + // point at which its shape gets reviewed. + for key := range obj { + if !isPreflightAllowedKey(key) { + return preflightFieldViolation("preflight", + "carries a key outside the fixed preflight counter set") + } + } + + // Every scalar the sub-object carries is a non-negative count. + for _, key := range preflightScalarKeys { + v, ok := obj[key] + if !ok { + continue + } + msg := json.RawMessage(v) + if viol := scanNonNegativeInt(&msg, "preflight."+key, preflightFieldViolation); viol != nil { + return viol + } + } + + rawCounts, ok := obj[preflightReasonsKey] + if !ok { + return nil + } + var counts map[string]json.RawMessage + if err := json.Unmarshal(rawCounts, &counts); err != nil || counts == nil { + return preflightFieldViolation("preflight.availability_block_reasons_24h", "must be an object") + } + for reason, v := range counts { + if !IsAvailabilityBlockReason(reason) { + return preflightFieldViolation("preflight.availability_block_reasons_24h", + "carries a key outside the fixed availability-block reason enum") + } + msg := json.RawMessage(v) + if viol := scanNonNegativeInt(&msg, "preflight.availability_block_reasons_24h", preflightFieldViolation); viol != nil { + return viol + } + } + return nil +} + +// preflightScalarKeys is the fixed set of non-negative-integer keys allowed in +// the preflight sub-object. +var preflightScalarKeys = []string{ + "filter_diag_emitted_24h", + "filter_diag_missing_annotation_24h", + "filter_diag_explicit_24h", + "filter_diag_followed_24h", + "availability_block_24h", + "discovery_omission_24h", +} + +// preflightReasonsKey is the one non-scalar key the preflight sub-object may +// carry (a closed-enum map, validated separately). +const preflightReasonsKey = "availability_block_reasons_24h" + +// preflightAllowedKeys is the CLOSED key set of the preflight sub-object: +// preflightScalarKeys plus the reason map. Anything else is a violation. +var preflightAllowedKeys = func() map[string]struct{} { + m := make(map[string]struct{}, len(preflightScalarKeys)+1) + for _, k := range preflightScalarKeys { + m[k] = struct{}{} + } + m[preflightReasonsKey] = struct{}{} + return m +}() + +func isPreflightAllowedKey(key string) bool { + _, ok := preflightAllowedKeys[key] + return ok +} + // ScanForPII scans a serialized telemetry payload (v3+) for PII leaks and // structural violations. Returns nil when the payload is clean; otherwise // returns an *AnonymityViolation. The returned error satisfies @@ -366,6 +479,10 @@ func scanDiagnosticsCounters(raw json.RawMessage) *AnonymityViolation { // exclusively by the fixed severity enum. // 6. diagnostics.error_code_counts_24h, if present, is not a map of // catalog-registered MCPX_* codes to non-negative integer counts. +// 7. preflight (issue #969), if present, is not a CLOSED object of +// non-negative integer counts (keys drawn from preflightAllowedKeys) whose +// availability_block_reasons_24h map is keyed exclusively by the closed +// availability-block reason enum. // // The implementation never logs the payload — it only reports which rule // tripped and the offending pattern (a small literal). Callers should log at @@ -436,6 +553,12 @@ func ScanForPII(payloadJSON []byte) error { return v } + // Rule 7: preflight counters must be closed-enum reason keys → non-negative + // ints, and every scalar a non-negative count. + if v := scanPreflightCounters(env.Preflight); v != nil { + return v + } + return nil } diff --git a/internal/telemetry/payload_preflight_test.go b/internal/telemetry/payload_preflight_test.go new file mode 100644 index 00000000..7d87be31 --- /dev/null +++ b/internal/telemetry/payload_preflight_test.go @@ -0,0 +1,233 @@ +package telemetry + +import ( + "encoding/json" + "path/filepath" + "testing" + "time" + + "go.etcd.io/bbolt" + "go.uber.org/zap" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" +) + +// newPreflightService stands up a telemetry Service with the preflight counter +// store wired onto a throwaway BBolt DB (issue #969). +func newPreflightService(t *testing.T, cfg *config.Config) (*Service, *bbolt.DB) { + t.Helper() + dir := t.TempDir() + db, err := bbolt.Open(filepath.Join(dir, "preflight_payload.db"), 0600, &bbolt.Options{Timeout: 2 * time.Second}) + if err != nil { + t.Fatalf("bbolt.Open: %v", err) + } + t.Cleanup(func() { _ = db.Close() }) + + svc := New(cfg, "", "v1.0.0", "personal", zap.NewNop()) + svc.SetRuntimeStats(&mockRuntimeStats{}) + svc.SetPreflightCounterStore(NewPreflightCounterStore(), db) + return svc, db +} + +// pinTelemetryEnvEnabled neutralises the three env opt-outs so a test that is +// asserting the ENABLED path is not silently turned into a no-op by CI=true on +// a build machine. +func pinTelemetryEnvEnabled(t *testing.T) { + t.Helper() + t.Setenv("CI", "") + t.Setenv("DO_NOT_TRACK", "") + t.Setenv("MCPPROXY_TELEMETRY", "") +} + +func enabledTelemetryConfig() *config.Config { + enabled := true + return &config.Config{ + Telemetry: &config.TelemetryConfig{AnonymousID: "test-id", Enabled: &enabled}, + } +} + +// PF001: the preflight sub-object is omitted entirely when the store is not +// wired — a short-lived CLI process produces a payload shaped exactly like one +// from before this field existed. +func TestBuildPayload_PreflightOmittedWhenStoreNil(t *testing.T) { + pinTelemetryEnvEnabled(t) + svc := New(enabledTelemetryConfig(), "", "v1.0.0", "personal", zap.NewNop()) + svc.SetRuntimeStats(&mockRuntimeStats{}) + + payload := svc.BuildPayload() + if payload.Preflight != nil { + t.Errorf("expected Preflight nil when store is not wired, got %+v", payload.Preflight) + } + + raw, _ := json.Marshal(payload) + var m map[string]json.RawMessage + _ = json.Unmarshal(raw, &m) + if _, ok := m["preflight"]; ok { + t.Error("preflight key present in JSON despite nil pointer (omitempty broken)") + } +} + +// PF002: wired but never incremented → still omitted. +func TestBuildPayload_PreflightOmittedWhenAllZero(t *testing.T) { + pinTelemetryEnvEnabled(t) + svc, _ := newPreflightService(t, enabledTelemetryConfig()) + + if payload := svc.BuildPayload(); payload.Preflight != nil { + t.Errorf("expected Preflight nil when all counters zero, got %+v", payload.Preflight) + } +} + +// PF003: every counter family reaches the payload, through the Service-level +// Record* entry points the server actually calls. +func TestBuildPayload_PreflightPopulated(t *testing.T) { + pinTelemetryEnvEnabled(t) + svc, _ := newPreflightService(t, enabledTelemetryConfig()) + + svc.RecordFilterDiagnosticsEmitted(3, 2) + svc.RecordFilterDiagnosticsEmitted(1, 1) + svc.RecordFilterDiagnosticsFollowed() + svc.RecordAvailabilityBlock(BlockReasonServerQuarantined) + svc.RecordAvailabilityBlock(BlockReasonServerQuarantined) + svc.RecordAvailabilityBlock(BlockReasonToolNotCallable) + svc.RecordDiscoveryOmission() + svc.RecordDiscoveryOmission() + svc.RecordDiscoveryOmission() + + payload := svc.BuildPayload() + if payload.Preflight == nil { + t.Fatal("expected Preflight non-nil after recording counters") + } + pf := payload.Preflight + if pf.FilterDiagEmitted24h != 2 { + t.Errorf("filter_diag_emitted_24h = %d, want 2", pf.FilterDiagEmitted24h) + } + if pf.FilterDiagMissingAnnotation24h != 4 { + t.Errorf("filter_diag_missing_annotation_24h = %d, want 4", pf.FilterDiagMissingAnnotation24h) + } + if pf.FilterDiagExplicit24h != 3 { + t.Errorf("filter_diag_explicit_24h = %d, want 3", pf.FilterDiagExplicit24h) + } + if pf.FilterDiagFollowed24h != 1 { + t.Errorf("filter_diag_followed_24h = %d, want 1", pf.FilterDiagFollowed24h) + } + if pf.AvailabilityBlock24h != 3 { + t.Errorf("availability_block_24h = %d, want 3", pf.AvailabilityBlock24h) + } + if pf.AvailabilityBlockReasons24h[BlockReasonServerQuarantined] != 2 { + t.Errorf("server_quarantined = %d, want 2", pf.AvailabilityBlockReasons24h[BlockReasonServerQuarantined]) + } + if pf.DiscoveryOmission24h != 3 { + t.Errorf("discovery_omission_24h = %d, want 3", pf.DiscoveryOmission24h) + } +} + +// PF004: JSON round-trip — the sub-object is nested under "preflight" with the +// documented key names, and the payload still passes the anonymity scanner. +func TestBuildPayload_PreflightJSONRoundTrip(t *testing.T) { + pinTelemetryEnvEnabled(t) + svc, _ := newPreflightService(t, enabledTelemetryConfig()) + + svc.RecordFilterDiagnosticsEmitted(2, 0) + svc.RecordAvailabilityBlock(BlockReasonTokenPermission) + svc.RecordDiscoveryOmission() + + raw, err := json.Marshal(svc.BuildPayload()) + if err != nil { + t.Fatalf("json.Marshal: %v", err) + } + var wire struct { + Preflight *struct { + FilterDiagEmitted24h int `json:"filter_diag_emitted_24h"` + FilterDiagMissingAnnotation24h int `json:"filter_diag_missing_annotation_24h"` + FilterDiagExplicit24h int `json:"filter_diag_explicit_24h"` + FilterDiagFollowed24h int `json:"filter_diag_followed_24h"` + AvailabilityBlock24h int `json:"availability_block_24h"` + AvailabilityBlockReasons24h map[string]int `json:"availability_block_reasons_24h"` + DiscoveryOmission24h int `json:"discovery_omission_24h"` + } `json:"preflight"` + } + if err := json.Unmarshal(raw, &wire); err != nil { + t.Fatalf("json.Unmarshal: %v", err) + } + if wire.Preflight == nil { + t.Fatal("preflight absent from JSON") + } + if wire.Preflight.FilterDiagEmitted24h != 1 { + t.Errorf("filter_diag_emitted_24h want 1, got %d", wire.Preflight.FilterDiagEmitted24h) + } + if wire.Preflight.FilterDiagMissingAnnotation24h != 2 { + t.Errorf("filter_diag_missing_annotation_24h want 2, got %d", wire.Preflight.FilterDiagMissingAnnotation24h) + } + if wire.Preflight.AvailabilityBlockReasons24h[BlockReasonTokenPermission] != 1 { + t.Errorf("token_permission want 1, got %d", wire.Preflight.AvailabilityBlockReasons24h[BlockReasonTokenPermission]) + } + if wire.Preflight.DiscoveryOmission24h != 1 { + t.Errorf("discovery_omission_24h want 1, got %d", wire.Preflight.DiscoveryOmission24h) + } + if err := ScanForPII(raw); err != nil { + t.Errorf("payload with preflight counters must pass the anonymity scanner: %v", err) + } +} + +// PF005: telemetry opt-out is honoured at EVENT time — an install with +// telemetry disabled persists nothing, so an occurrence observed while off can +// never become transmissible if telemetry is turned back on later. +func TestPreflightCounters_RespectConfigOptOut(t *testing.T) { + pinTelemetryEnvEnabled(t) + disabled := false + cfg := &config.Config{ + Telemetry: &config.TelemetryConfig{AnonymousID: "test-id", Enabled: &disabled}, + } + svc, db := newPreflightService(t, cfg) + + svc.RecordFilterDiagnosticsEmitted(5, 5) + svc.RecordFilterDiagnosticsFollowed() + svc.RecordAvailabilityBlock(BlockReasonServerQuarantined) + svc.RecordDiscoveryOmission() + + snap, err := NewPreflightCounterStore().Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + if !snap.isZero() { + t.Fatalf("opt-out must persist nothing, got %+v", snap) + } + if payload := svc.BuildPayload(); payload.Preflight != nil { + t.Errorf("expected Preflight nil under opt-out, got %+v", payload.Preflight) + } +} + +// PF006: the env opt-out (DO_NOT_TRACK and friends) is honoured on the same +// event-time gate as the config flag. +func TestPreflightCounters_RespectEnvOptOut(t *testing.T) { + pinTelemetryEnvEnabled(t) + t.Setenv("DO_NOT_TRACK", "1") + + svc, db := newPreflightService(t, enabledTelemetryConfig()) + svc.RecordAvailabilityBlock(BlockReasonToolNotCallable) + svc.RecordDiscoveryOmission() + + snap, err := NewPreflightCounterStore().Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + if !snap.isZero() { + t.Fatalf("env opt-out must persist nothing, got %+v", snap) + } +} + +// PF007: every Record* is a safe no-op when the store was never wired. +func TestPreflightCounters_NoStoreIsNoOp(t *testing.T) { + pinTelemetryEnvEnabled(t) + svc := New(enabledTelemetryConfig(), "", "v1.0.0", "personal", zap.NewNop()) + svc.SetRuntimeStats(&mockRuntimeStats{}) + + svc.RecordFilterDiagnosticsEmitted(1, 1) + svc.RecordFilterDiagnosticsFollowed() + svc.RecordAvailabilityBlock(BlockReasonOther) + svc.RecordDiscoveryOmission() + + if payload := svc.BuildPayload(); payload.Preflight != nil { + t.Errorf("expected Preflight nil with no store wired, got %+v", payload.Preflight) + } +} diff --git a/internal/telemetry/preflight_counters.go b/internal/telemetry/preflight_counters.go new file mode 100644 index 00000000..091555dc --- /dev/null +++ b/internal/telemetry/preflight_counters.go @@ -0,0 +1,448 @@ +package telemetry + +import ( + "encoding/json" + "fmt" + "sort" + "strings" + "time" + + "go.etcd.io/bbolt" +) + +// PreflightCountersBucketName is the BBolt bucket that stores the +// required-tools-preflight BASELINE counters (issue #969, Phase 0). Keys inside +// are defined as constants below and follow the Phase-H counter encoding +// (encodeCounter / readCounterWithDecay), so every counter here is a 24h +// sliding window that decays at read time. +// +// These counters ship ONE RELEASE AHEAD of the preflight feature on purpose: +// without a live pre-feature window there is nothing to compare the post-feature +// numbers against, and "did preflight help?" degrades into an argument about +// anecdotes. +const PreflightCountersBucketName = "preflight_counters" + +const ( + preflightKeyFilterDiagEmitted24h = "filter_diag_emitted_24h" + preflightKeyFilterDiagMissing24h = "filter_diag_missing_annotation_24h" + preflightKeyFilterDiagExplicit24h = "filter_diag_explicit_24h" + preflightKeyFilterDiagFollowed24h = "filter_diag_followed_24h" + preflightKeyAvailabilityBlock24h = "availability_block_24h" + preflightKeyDiscoveryOmission24h = "discovery_omission_24h" + preflightKeyAvailabilityReasonPfx = "availability_block_reason_24h_" +) + +// Availability block reason keys (issue #969). This is a CLOSED enum mirroring +// the structured policy-block sites in internal/server — it is duplicated here +// rather than imported for the same reason tpaSeverityKeys is: the telemetry +// package must not depend on the server package, and the enum IS the anonymity +// contract. Anything outside this list is folded into BlockReasonOther rather +// than transmitted, so a reason STRING (which carries server/tool names) can +// never become a map key. +const ( + BlockReasonIntentInvalid = "intent_invalid" + BlockReasonIntentRejected = "intent_rejected" + BlockReasonProfileScope = "profile_scope" + BlockReasonTokenScope = "token_scope" + BlockReasonTokenPermission = "token_permission" + BlockReasonServerQuarantined = "server_quarantined" + BlockReasonToolPendingApproval = "tool_pending_approval" + BlockReasonToolChanged = "tool_changed_approval" + BlockReasonToolNotCallable = "tool_not_callable" + BlockReasonOutputSanitisation = "output_sanitisation" + BlockReasonOutputSchema = "output_schema" + BlockReasonOther = "other" +) + +// availabilityBlockReasonKeys is the fixed enum emitted under +// preflight.availability_block_reasons_24h. +var availabilityBlockReasonKeys = []string{ + BlockReasonIntentInvalid, + BlockReasonIntentRejected, + BlockReasonProfileScope, + BlockReasonTokenScope, + BlockReasonTokenPermission, + BlockReasonServerQuarantined, + BlockReasonToolPendingApproval, + BlockReasonToolChanged, + BlockReasonToolNotCallable, + BlockReasonOutputSanitisation, + BlockReasonOutputSchema, + BlockReasonOther, +} + +// availabilityBlockReasonAllowList is the set form of availabilityBlockReasonKeys. +var availabilityBlockReasonAllowList = func() map[string]struct{} { + m := make(map[string]struct{}, len(availabilityBlockReasonKeys)) + for _, k := range availabilityBlockReasonKeys { + m[k] = struct{}{} + } + return m +}() + +// IsAvailabilityBlockReason reports whether key is a member of the closed +// availability-block reason enum. +func IsAvailabilityBlockReason(key string) bool { + _, ok := availabilityBlockReasonAllowList[key] + return ok +} + +// NormalizeAvailabilityBlockReason maps any input onto the closed enum: +// members pass through, everything else becomes BlockReasonOther. Callers on +// the hot path use this so a future block site that forgets to declare a key +// still produces a countable — and non-identifying — bucket. +func NormalizeAvailabilityBlockReason(key string) string { + if IsAvailabilityBlockReason(key) { + return key + } + return BlockReasonOther +} + +// maxAvailabilityReasonKeys bounds how many DISTINCT reason keys the bucket +// will ever hold. The allow-list already bounds cardinality at len(enum); this +// is the write-side backstop that keeps a producer regression (or a stale +// bucket written by a newer build) from growing the key set without bound. +// BlockReasonOther is exempt — it is the overflow bucket itself. +const maxAvailabilityReasonKeys = 16 + +// maxPreflightReasonEntries caps availability_block_reasons_24h in +// MarshalJSON: top-N by count desc, key asc on ties. Same posture as +// maxDiagCodeEntries — the wire payload stays bounded regardless of what the +// bucket accumulated. +const maxPreflightReasonEntries = 16 + +// PreflightCounters is the baseline counter snapshot for the required-tools +// preflight roadmap (issue #969, Phase 0). +// +// Privacy contract: counts only. Every field is a non-negative integer, and the +// only map keys that can appear are members of the closed +// availabilityBlockReasonKeys enum. No tool name, server name, query, filter +// value, session id, or free text ever reaches this struct — the Record* +// methods do not accept them. +type PreflightCounters struct { + // FilterDiagEmitted24h counts retrieve_tools responses that carried a + // spec-094 filter_diagnostics block in the last 24h. Spec 094 shipped with + // zero usage measurement; this is the denominator everything else divides by. + FilterDiagEmitted24h int `json:"filter_diag_emitted_24h"` + // FilterDiagMissingAnnotation24h is the sum of the per-filter + // missing_annotation reason counts across every emitted block ("fix the + // upstream server" class). + FilterDiagMissingAnnotation24h int `json:"filter_diag_missing_annotation_24h"` + // FilterDiagExplicit24h is the sum of the per-filter explicit reason counts + // ("the filter is working as intended" class). + FilterDiagExplicit24h int `json:"filter_diag_explicit_24h"` + // FilterDiagFollowed24h counts diagnostics blocks the agent ACTED ON: a + // later retrieve_tools call in the same MCP session dropped or relaxed at + // least one of the filters the block blamed. This is the engagement signal — + // emitted-but-never-followed means the block is being ignored. + FilterDiagFollowed24h int `json:"filter_diag_followed_24h"` + // AvailabilityBlock24h counts policy blocks (the "blocked" decision on the + // single emitActivityPolicyDecision funnel) in the last 24h. + AvailabilityBlock24h int `json:"availability_block_24h"` + // AvailabilityBlockReasons24h splits AvailabilityBlock24h by the closed + // reason enum. Sparse: reasons with a zero count are omitted. + AvailabilityBlockReasons24h map[string]int `json:"availability_block_reasons_24h,omitempty"` + // DiscoveryOmission24h counts retrieve_tools responses that silently + // withheld locked/quarantined matches from the caller (include_disabled + // unset). This is the substrate for the preflight silent-unavailability + // metric: how often an agent was told "no such tool" when the tool exists. + DiscoveryOmission24h int `json:"discovery_omission_24h"` +} + +// isZero reports whether nothing at all was recorded, in which case the +// heartbeat omits the whole sub-object (same posture as DiagnosticsCounters). +func (p PreflightCounters) isZero() bool { + if p.FilterDiagEmitted24h != 0 || + p.FilterDiagMissingAnnotation24h != 0 || + p.FilterDiagExplicit24h != 0 || + p.FilterDiagFollowed24h != 0 || + p.AvailabilityBlock24h != 0 || + p.DiscoveryOmission24h != 0 { + return false + } + for _, n := range p.AvailabilityBlockReasons24h { + if n != 0 { + return false + } + } + return true +} + +// MarshalJSON drops any reason key outside the closed enum and caps the map to +// maxPreflightReasonEntries before serialising. Both guards are wire-form +// backstops for the producer-side filtering in RecordAvailabilityBlock. +func (p PreflightCounters) MarshalJSON() ([]byte, error) { + counts := p.AvailabilityBlockReasons24h + if len(counts) > 0 { + filtered := make(map[string]int, len(counts)) + for k, v := range counts { + if IsAvailabilityBlockReason(k) { + filtered[k] = v + } + } + counts = filtered + } + if len(counts) > maxPreflightReasonEntries { + type kv struct { + k string + v int + } + entries := make([]kv, 0, len(counts)) + for k, v := range counts { + entries = append(entries, kv{k, v}) + } + sort.Slice(entries, func(i, j int) bool { + if entries[i].v != entries[j].v { + return entries[i].v > entries[j].v // higher count first + } + return entries[i].k < entries[j].k // tie-break by key asc + }) + counts = make(map[string]int, maxPreflightReasonEntries) + for _, e := range entries[:maxPreflightReasonEntries] { + counts[e.k] = e.v + } + } + if len(counts) == 0 { + counts = nil + } + type wire struct { + FilterDiagEmitted24h int `json:"filter_diag_emitted_24h"` + FilterDiagMissingAnnotation24h int `json:"filter_diag_missing_annotation_24h"` + FilterDiagExplicit24h int `json:"filter_diag_explicit_24h"` + FilterDiagFollowed24h int `json:"filter_diag_followed_24h"` + AvailabilityBlock24h int `json:"availability_block_24h"` + AvailabilityBlockReasons24h map[string]int `json:"availability_block_reasons_24h,omitempty"` + DiscoveryOmission24h int `json:"discovery_omission_24h"` + } + return json.Marshal(wire{ + FilterDiagEmitted24h: p.FilterDiagEmitted24h, + FilterDiagMissingAnnotation24h: p.FilterDiagMissingAnnotation24h, + FilterDiagExplicit24h: p.FilterDiagExplicit24h, + FilterDiagFollowed24h: p.FilterDiagFollowed24h, + AvailabilityBlock24h: p.AvailabilityBlock24h, + AvailabilityBlockReasons24h: counts, + DiscoveryOmission24h: p.DiscoveryOmission24h, + }) +} + +// PreflightCounterStore is the persistence contract for the Phase-0 baseline +// counters. Implementations back onto BBolt; every method is individually +// atomic via a bbolt transaction. +type PreflightCounterStore interface { + // RecordFilterDiagnosticsEmitted increments filter_diag_emitted_24h once + // and adds the block's per-reason-class counts (both must be >= 0; negative + // values are clamped to 0). + RecordFilterDiagnosticsEmitted(db *bbolt.DB, missingAnnotation, explicit int) error + + // RecordFilterDiagnosticsFollowed increments filter_diag_followed_24h — a + // later call in the same session relaxed a filter the block blamed. + RecordFilterDiagnosticsFollowed(db *bbolt.DB) error + + // RecordAvailabilityBlock increments availability_block_24h and the + // per-reason counter. Reasons outside the closed enum are folded into + // BlockReasonOther, so free text can never become a key. + RecordAvailabilityBlock(db *bbolt.DB, reason string) error + + // RecordDiscoveryOmission increments discovery_omission_24h. + RecordDiscoveryOmission(db *bbolt.DB) error + + // Snapshot loads the current counter state, applying 24h decay at now. + Snapshot(db *bbolt.DB) (PreflightCounters, error) +} + +// bboltPreflightCounterStore is the production BBolt-backed implementation. +// Zero-value is ready to use; no initialisation required. +type bboltPreflightCounterStore struct{} + +// NewPreflightCounterStore returns a BBolt-backed PreflightCounterStore. +func NewPreflightCounterStore() PreflightCounterStore { + return bboltPreflightCounterStore{} +} + +// EnsurePreflightCountersBucket pre-creates the bucket to avoid write-races on +// first use. Safe to call multiple times. +func EnsurePreflightCountersBucket(db *bbolt.DB) error { + if db == nil { + return fmt.Errorf("nil db") + } + return db.Update(func(tx *bbolt.Tx) error { + _, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + return err + }) +} + +// --- bucket helpers --- + +func preflightBucket(tx *bbolt.Tx) *bbolt.Bucket { + return tx.Bucket([]byte(PreflightCountersBucketName)) +} + +func preflightBucketForWrite(tx *bbolt.Tx) (*bbolt.Bucket, error) { + return tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) +} + +// bumpPreflightCounter adds n (clamped at >= 0) to the 24h counter at key, +// rolling the window when it has expired. +func bumpPreflightCounter(b *bbolt.Bucket, key string, n int, now time.Time) error { + if n <= 0 { + return nil + } + count, windowStart, _ := readCounterWithDecay(b.Get([]byte(key)), now) + count += uint64(n) + return b.Put([]byte(key), encodeCounter(count, windowStart)) +} + +// --- RecordFilterDiagnosticsEmitted --- + +func (bboltPreflightCounterStore) RecordFilterDiagnosticsEmitted(db *bbolt.DB, missingAnnotation, explicit int) error { + if db == nil { + return nil + } + now := time.Now() + return db.Update(func(tx *bbolt.Tx) error { + b, err := preflightBucketForWrite(tx) + if err != nil { + return err + } + if err := bumpPreflightCounter(b, preflightKeyFilterDiagEmitted24h, 1, now); err != nil { + return err + } + if err := bumpPreflightCounter(b, preflightKeyFilterDiagMissing24h, missingAnnotation, now); err != nil { + return err + } + return bumpPreflightCounter(b, preflightKeyFilterDiagExplicit24h, explicit, now) + }) +} + +// --- RecordFilterDiagnosticsFollowed --- + +func (bboltPreflightCounterStore) RecordFilterDiagnosticsFollowed(db *bbolt.DB) error { + if db == nil { + return nil + } + now := time.Now() + return db.Update(func(tx *bbolt.Tx) error { + b, err := preflightBucketForWrite(tx) + if err != nil { + return err + } + return bumpPreflightCounter(b, preflightKeyFilterDiagFollowed24h, 1, now) + }) +} + +// --- RecordAvailabilityBlock --- + +func (bboltPreflightCounterStore) RecordAvailabilityBlock(db *bbolt.DB, reason string) error { + if db == nil { + return nil + } + key := NormalizeAvailabilityBlockReason(reason) + now := time.Now() + return db.Update(func(tx *bbolt.Tx) error { + b, err := preflightBucketForWrite(tx) + if err != nil { + return err + } + if err := bumpPreflightCounter(b, preflightKeyAvailabilityBlock24h, 1, now); err != nil { + return err + } + // Write-side cardinality backstop: a key the bucket has never seen is + // only admitted while the distinct-key budget holds; past it, the count + // still lands (in the overflow bucket) but the key set cannot grow. + if key != BlockReasonOther { + reasonKey := preflightKeyAvailabilityReasonPfx + key + if b.Get([]byte(reasonKey)) == nil && countPreflightReasonKeys(b) >= maxAvailabilityReasonKeys { + key = BlockReasonOther + } + } + return bumpPreflightCounter(b, preflightKeyAvailabilityReasonPfx+key, 1, now) + }) +} + +// countPreflightReasonKeys returns how many distinct reason keys the bucket +// currently holds (decayed-but-not-yet-deleted keys included — the budget is +// about key-set growth, not live counts). +func countPreflightReasonKeys(b *bbolt.Bucket) int { + n := 0 + prefix := []byte(preflightKeyAvailabilityReasonPfx) + c := b.Cursor() + for k, _ := c.Seek(prefix); k != nil && strings.HasPrefix(string(k), preflightKeyAvailabilityReasonPfx); k, _ = c.Next() { + n++ + } + return n +} + +// --- RecordDiscoveryOmission --- + +func (bboltPreflightCounterStore) RecordDiscoveryOmission(db *bbolt.DB) error { + if db == nil { + return nil + } + now := time.Now() + return db.Update(func(tx *bbolt.Tx) error { + b, err := preflightBucketForWrite(tx) + if err != nil { + return err + } + return bumpPreflightCounter(b, preflightKeyDiscoveryOmission24h, 1, now) + }) +} + +// --- Snapshot --- + +func (bboltPreflightCounterStore) Snapshot(db *bbolt.DB) (PreflightCounters, error) { + return snapshotPreflightAt(db, time.Now()) +} + +func snapshotPreflightAt(db *bbolt.DB, now time.Time) (PreflightCounters, error) { + var out PreflightCounters + if db == nil { + return out, nil + } + err := db.View(func(tx *bbolt.Tx) error { + b := preflightBucket(tx) + if b == nil { + return nil // bucket absent → all zero + } + + read := func(key string) int { + raw := b.Get([]byte(key)) + if len(raw) < 16 { + return 0 + } + cnt, _, _ := readCounterWithDecay(raw, now) + return int(cnt) + } + + out.FilterDiagEmitted24h = read(preflightKeyFilterDiagEmitted24h) + out.FilterDiagMissingAnnotation24h = read(preflightKeyFilterDiagMissing24h) + out.FilterDiagExplicit24h = read(preflightKeyFilterDiagExplicit24h) + out.FilterDiagFollowed24h = read(preflightKeyFilterDiagFollowed24h) + out.AvailabilityBlock24h = read(preflightKeyAvailabilityBlock24h) + out.DiscoveryOmission24h = read(preflightKeyDiscoveryOmission24h) + + // per-reason 24h counts + c := b.Cursor() + prefix := []byte(preflightKeyAvailabilityReasonPfx) + for k, v := c.Seek(prefix); k != nil && strings.HasPrefix(string(k), preflightKeyAvailabilityReasonPfx); k, v = c.Next() { + reason := strings.TrimPrefix(string(k), preflightKeyAvailabilityReasonPfx) + // Read-side twin of the producer guard: a key that is not a member + // of the closed enum never becomes part of the snapshot. + if !IsAvailabilityBlockReason(reason) { + continue + } + if len(v) < 16 { + continue + } + cnt, _, _ := readCounterWithDecay(v, now) + if cnt > 0 { + if out.AvailabilityBlockReasons24h == nil { + out.AvailabilityBlockReasons24h = make(map[string]int) + } + out.AvailabilityBlockReasons24h[reason] = int(cnt) + } + } + return nil + }) + return out, err +} diff --git a/internal/telemetry/preflight_counters_test.go b/internal/telemetry/preflight_counters_test.go new file mode 100644 index 00000000..8755267b --- /dev/null +++ b/internal/telemetry/preflight_counters_test.go @@ -0,0 +1,575 @@ +package telemetry + +import ( + "encoding/json" + "fmt" + "path/filepath" + "strings" + "testing" + "time" + + "go.etcd.io/bbolt" +) + +// newTestPreflightDB creates a temporary BBolt DB for preflight counter tests. +func newTestPreflightDB(t *testing.T) (*bbolt.DB, func()) { + t.Helper() + dir := t.TempDir() + path := filepath.Join(dir, "preflight_test.db") + db, err := bbolt.Open(path, 0600, &bbolt.Options{Timeout: 2 * time.Second}) + if err != nil { + t.Fatalf("bbolt.Open: %v", err) + } + return db, func() { _ = db.Close() } +} + +// P001: an empty DB snapshots to the zero value (and is therefore omitted from +// the heartbeat). +func TestPreflightCounterStore_Empty(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + snap, err := s.Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + if !snap.isZero() { + t.Fatalf("expected zero snapshot on empty DB, got %+v", snap) + } +} + +// P002: filter-diagnostics emission bumps the response counter once and adds +// the per-reason-class counts. +func TestPreflightCounterStore_FilterDiagnosticsEmitted(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + if err := s.RecordFilterDiagnosticsEmitted(db, 3, 2); err != nil { + t.Fatalf("RecordFilterDiagnosticsEmitted: %v", err) + } + if err := s.RecordFilterDiagnosticsEmitted(db, 1, 0); err != nil { + t.Fatalf("RecordFilterDiagnosticsEmitted: %v", err) + } + + snap, err := s.Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + if snap.FilterDiagEmitted24h != 2 { + t.Errorf("FilterDiagEmitted24h = %d, want 2", snap.FilterDiagEmitted24h) + } + if snap.FilterDiagMissingAnnotation24h != 4 { + t.Errorf("FilterDiagMissingAnnotation24h = %d, want 4", snap.FilterDiagMissingAnnotation24h) + } + if snap.FilterDiagExplicit24h != 2 { + t.Errorf("FilterDiagExplicit24h = %d, want 2", snap.FilterDiagExplicit24h) + } +} + +// P003: a block with zero on one reason class still counts the emission, and +// negative inputs (a caller bug) can never decrement a counter. +func TestPreflightCounterStore_EmittedClampsNegatives(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + _ = s.RecordFilterDiagnosticsEmitted(db, 5, 5) + _ = s.RecordFilterDiagnosticsEmitted(db, -100, -100) + + snap, _ := s.Snapshot(db) + if snap.FilterDiagEmitted24h != 2 { + t.Errorf("FilterDiagEmitted24h = %d, want 2", snap.FilterDiagEmitted24h) + } + if snap.FilterDiagMissingAnnotation24h != 5 || snap.FilterDiagExplicit24h != 5 { + t.Errorf("negative deltas must be dropped, got missing=%d explicit=%d", + snap.FilterDiagMissingAnnotation24h, snap.FilterDiagExplicit24h) + } +} + +// P004: followed / discovery-omission increment paths. +func TestPreflightCounterStore_FollowedAndOmission(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + for i := 0; i < 4; i++ { + if err := s.RecordFilterDiagnosticsFollowed(db); err != nil { + t.Fatalf("RecordFilterDiagnosticsFollowed: %v", err) + } + } + for i := 0; i < 7; i++ { + if err := s.RecordDiscoveryOmission(db); err != nil { + t.Fatalf("RecordDiscoveryOmission: %v", err) + } + } + + snap, _ := s.Snapshot(db) + if snap.FilterDiagFollowed24h != 4 { + t.Errorf("FilterDiagFollowed24h = %d, want 4", snap.FilterDiagFollowed24h) + } + if snap.DiscoveryOmission24h != 7 { + t.Errorf("DiscoveryOmission24h = %d, want 7", snap.DiscoveryOmission24h) + } +} + +// P005: availability blocks increment the total and the per-reason map. +func TestPreflightCounterStore_AvailabilityBlockByReason(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + _ = s.RecordAvailabilityBlock(db, BlockReasonServerQuarantined) + _ = s.RecordAvailabilityBlock(db, BlockReasonServerQuarantined) + _ = s.RecordAvailabilityBlock(db, BlockReasonTokenScope) + + snap, _ := s.Snapshot(db) + if snap.AvailabilityBlock24h != 3 { + t.Errorf("AvailabilityBlock24h = %d, want 3", snap.AvailabilityBlock24h) + } + if got := snap.AvailabilityBlockReasons24h[BlockReasonServerQuarantined]; got != 2 { + t.Errorf("server_quarantined = %d, want 2", got) + } + if got := snap.AvailabilityBlockReasons24h[BlockReasonTokenScope]; got != 1 { + t.Errorf("token_scope = %d, want 1", got) + } +} + +// P006: a reason OUTSIDE the closed enum — e.g. the operator-facing prose that +// embeds a server name — is folded into "other" and never becomes a key. +func TestPreflightCounterStore_UnknownReasonFoldedIntoOther(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + leaky := []string{ + "", + "Server 'acme-internal' is not in scope for this agent token", + "/Users/algis/.mcpproxy/config.db", + "SERVER_QUARANTINED", + } + for _, r := range leaky { + if err := s.RecordAvailabilityBlock(db, r); err != nil { + t.Fatalf("RecordAvailabilityBlock(%q): %v", r, err) + } + } + + snap, _ := s.Snapshot(db) + if snap.AvailabilityBlock24h != len(leaky) { + t.Errorf("AvailabilityBlock24h = %d, want %d", snap.AvailabilityBlock24h, len(leaky)) + } + if got := snap.AvailabilityBlockReasons24h[BlockReasonOther]; got != len(leaky) { + t.Errorf("other = %d, want %d", got, len(leaky)) + } + for key := range snap.AvailabilityBlockReasons24h { + if !IsAvailabilityBlockReason(key) { + t.Errorf("non-enum key %q leaked into the snapshot", key) + } + } +} + +// P007: 24h windowing — a counter whose window opened more than 24h ago reads +// as zero (same decay contract as the Phase H counters). +func TestPreflightCounterStore_24hDecay(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + pastStart := time.Now().Add(-25 * time.Hour) + err := db.Update(func(tx *bbolt.Tx) error { + b, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + if err != nil { + return err + } + if err := b.Put([]byte(preflightKeyFilterDiagEmitted24h), encodeCounter(42, pastStart.Unix())); err != nil { + return err + } + if err := b.Put([]byte(preflightKeyDiscoveryOmission24h), encodeCounter(17, pastStart.Unix())); err != nil { + return err + } + if err := b.Put([]byte(preflightKeyAvailabilityBlock24h), encodeCounter(9, pastStart.Unix())); err != nil { + return err + } + return b.Put([]byte(preflightKeyAvailabilityReasonPfx+BlockReasonToolNotCallable), + encodeCounter(9, pastStart.Unix())) + }) + if err != nil { + t.Fatalf("seeding stale counters: %v", err) + } + + var s bboltPreflightCounterStore + snap, err := s.Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + if !snap.isZero() { + t.Fatalf("expected everything decayed to zero, got %+v", snap) + } + if _, ok := snap.AvailabilityBlockReasons24h[BlockReasonToolNotCallable]; ok { + t.Errorf("decayed reason key must not appear in the snapshot") + } +} + +// P008: 24h windowing — a stale window ROLLS on the next write instead of +// accumulating on top of the expired count. +func TestPreflightCounterStore_StaleWindowRolls(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + pastStart := time.Now().Add(-30 * time.Hour) + err := db.Update(func(tx *bbolt.Tx) error { + b, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + if err != nil { + return err + } + return b.Put([]byte(preflightKeyFilterDiagFollowed24h), encodeCounter(1000, pastStart.Unix())) + }) + if err != nil { + t.Fatalf("seeding stale counter: %v", err) + } + + var s bboltPreflightCounterStore + if err := s.RecordFilterDiagnosticsFollowed(db); err != nil { + t.Fatalf("RecordFilterDiagnosticsFollowed: %v", err) + } + snap, _ := s.Snapshot(db) + if snap.FilterDiagFollowed24h != 1 { + t.Errorf("FilterDiagFollowed24h = %d, want 1 (window must roll, not accumulate)", snap.FilterDiagFollowed24h) + } +} + +// P009: a counter written INSIDE the window survives. +func TestPreflightCounterStore_WithinWindowSurvives(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + recentStart := time.Now().Add(-23 * time.Hour) + err := db.Update(func(tx *bbolt.Tx) error { + b, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + if err != nil { + return err + } + return b.Put([]byte(preflightKeyDiscoveryOmission24h), encodeCounter(5, recentStart.Unix())) + }) + if err != nil { + t.Fatalf("seeding counter: %v", err) + } + + var s bboltPreflightCounterStore + if err := s.RecordDiscoveryOmission(db); err != nil { + t.Fatalf("RecordDiscoveryOmission: %v", err) + } + snap, _ := s.Snapshot(db) + if snap.DiscoveryOmission24h != 6 { + t.Errorf("DiscoveryOmission24h = %d, want 6", snap.DiscoveryOmission24h) + } +} + +// P010: write-side key cap — once the bucket holds maxAvailabilityReasonKeys +// distinct reason keys, a further NEW key folds into "other" instead of growing +// the key set. (The allow-list already bounds this; the cap is the backstop for +// a bucket written by a future build with a wider enum.) +func TestPreflightCounterStore_ReasonKeyCapEnforced(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + // Seed the bucket to the cap with synthetic keys (as a newer build might). + err := db.Update(func(tx *bbolt.Tx) error { + b, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + if err != nil { + return err + } + for i := 0; i < maxAvailabilityReasonKeys; i++ { + key := fmt.Sprintf("%sfuture_reason_%02d", preflightKeyAvailabilityReasonPfx, i) + if err := b.Put([]byte(key), encodeCounter(1, time.Now().Unix())); err != nil { + return err + } + } + return nil + }) + if err != nil { + t.Fatalf("seeding reason keys: %v", err) + } + + var s bboltPreflightCounterStore + if err := s.RecordAvailabilityBlock(db, BlockReasonProfileScope); err != nil { + t.Fatalf("RecordAvailabilityBlock: %v", err) + } + + // The new key must NOT have been created; the count went to "other". + err = db.View(func(tx *bbolt.Tx) error { + b := tx.Bucket([]byte(PreflightCountersBucketName)) + if raw := b.Get([]byte(preflightKeyAvailabilityReasonPfx + BlockReasonProfileScope)); raw != nil { + t.Errorf("key set grew past the cap: profile_scope key was created") + } + if raw := b.Get([]byte(preflightKeyAvailabilityReasonPfx + BlockReasonOther)); raw == nil { + t.Errorf("overflow bucket 'other' was not written") + } + return nil + }) + if err != nil { + t.Fatalf("View: %v", err) + } + + snap, _ := s.Snapshot(db) + if snap.AvailabilityBlock24h != 1 { + t.Errorf("AvailabilityBlock24h = %d, want 1", snap.AvailabilityBlock24h) + } + if got := snap.AvailabilityBlockReasons24h[BlockReasonOther]; got != 1 { + t.Errorf("other = %d, want 1", got) + } + // The synthetic (non-enum) keys are filtered out on the read side too. + for key := range snap.AvailabilityBlockReasons24h { + if strings.HasPrefix(key, "future_reason_") { + t.Errorf("non-enum key %q leaked into the snapshot", key) + } + } +} + +// P011: MarshalJSON caps the reason map to maxPreflightReasonEntries and drops +// any key outside the closed enum — the wire-form backstop. +func TestPreflightCounters_MarshalJSON_CapsAndFilters(t *testing.T) { + counts := make(map[string]int, len(availabilityBlockReasonKeys)+5) + for i, k := range availabilityBlockReasonKeys { + counts[k] = 100 - i + } + // Keys that must never reach the wire. + counts["Server 'acme' is not in scope"] = 999 + counts["/Users/algis/secret"] = 998 + + p := PreflightCounters{AvailabilityBlockReasons24h: counts} + raw, err := json.Marshal(p) + if err != nil { + t.Fatalf("MarshalJSON: %v", err) + } + var out struct { + Reasons map[string]int `json:"availability_block_reasons_24h"` + } + if err := json.Unmarshal(raw, &out); err != nil { + t.Fatalf("Unmarshal: %v", err) + } + if len(out.Reasons) > maxPreflightReasonEntries { + t.Errorf("map has %d entries, cap is %d", len(out.Reasons), maxPreflightReasonEntries) + } + for key := range out.Reasons { + if !IsAvailabilityBlockReason(key) { + t.Errorf("non-enum key %q reached the wire", key) + } + } + if strings.Contains(string(raw), "acme") || strings.Contains(string(raw), "/Users/") { + t.Errorf("PII leaked into the wire form: %s", raw) + } +} + +// P012: MarshalJSON caps deterministically (top-N by count desc, key asc). +func TestPreflightCounters_MarshalJSON_Deterministic(t *testing.T) { + counts := make(map[string]int, len(availabilityBlockReasonKeys)) + for _, k := range availabilityBlockReasonKeys { + counts[k] = 10 // pure alphabetic tie-break + } + p := PreflightCounters{AvailabilityBlock24h: 120, AvailabilityBlockReasons24h: counts} + + var results [3][]byte + for i := range results { + raw, err := json.Marshal(p) + if err != nil { + t.Fatalf("MarshalJSON run %d: %v", i, err) + } + results[i] = raw + } + for i := 1; i < len(results); i++ { + if string(results[i]) != string(results[0]) { + t.Errorf("MarshalJSON is non-deterministic: run 0 != run %d", i) + } + } +} + +// P013: the sub-object is omitted from the wire when nothing was recorded, and +// carries every documented key when it is present. +func TestPreflightCounters_IsZeroAndWireKeys(t *testing.T) { + var zero PreflightCounters + if !zero.isZero() { + t.Fatalf("zero value must report isZero") + } + // A reason key with a zero count is still "nothing recorded". + zero.AvailabilityBlockReasons24h = map[string]int{BlockReasonOther: 0} + if !zero.isZero() { + t.Fatalf("all-zero reason map must still report isZero") + } + + full := PreflightCounters{ + FilterDiagEmitted24h: 1, + FilterDiagMissingAnnotation24h: 2, + FilterDiagExplicit24h: 3, + FilterDiagFollowed24h: 4, + AvailabilityBlock24h: 5, + AvailabilityBlockReasons24h: map[string]int{BlockReasonToolChanged: 5}, + DiscoveryOmission24h: 6, + } + if full.isZero() { + t.Fatalf("populated counters must not report isZero") + } + raw, err := json.Marshal(full) + if err != nil { + t.Fatalf("MarshalJSON: %v", err) + } + var out map[string]json.RawMessage + if err := json.Unmarshal(raw, &out); err != nil { + t.Fatalf("Unmarshal: %v", err) + } + for _, key := range []string{ + "filter_diag_emitted_24h", + "filter_diag_missing_annotation_24h", + "filter_diag_explicit_24h", + "filter_diag_followed_24h", + "availability_block_24h", + "availability_block_reasons_24h", + "discovery_omission_24h", + } { + if _, ok := out[key]; !ok { + t.Errorf("wire form is missing %q", key) + } + } +} + +// P014: the store never persists anything that looks like an identity, even +// when every enum member is exercised. +func TestPreflightCounters_NoLeakPII(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + var s bboltPreflightCounterStore + for _, reason := range availabilityBlockReasonKeys { + _ = s.RecordAvailabilityBlock(db, reason) + } + _ = s.RecordFilterDiagnosticsEmitted(db, 2, 3) + _ = s.RecordFilterDiagnosticsFollowed(db) + _ = s.RecordDiscoveryOmission(db) + + snap, _ := s.Snapshot(db) + raw, err := json.Marshal(snap) + if err != nil { + t.Fatalf("MarshalJSON: %v", err) + } + js := string(raw) + for _, forbidden := range []string{ + "/home/", "/Users/", "C:\\", + "localhost", "127.0.0.1", + "password", "secret", "token:", + } { + if strings.Contains(js, forbidden) { + t.Errorf("PII leak: JSON contains %q\nJSON: %s", forbidden, js) + } + } + envelope := []byte(`{"preflight":` + js + `}`) + if err := ScanForPII(envelope); err != nil { + t.Errorf("preflight sub-object must pass the anonymity scanner: %v", err) + } +} + +// P015: the anonymity scanner rejects a preflight sub-object whose reason map +// carries a key outside the closed enum — the wire-form backstop for a producer +// regression that let operator prose (server/tool names) become a key. +func TestScanForPII_RejectsNonEnumPreflightReasonKey(t *testing.T) { + payload := []byte(`{"preflight":{"availability_block_24h":1,` + + `"availability_block_reasons_24h":{"server acme-internal is quarantined":1}}}`) + err := ScanForPII(payload) + if err == nil { + t.Fatalf("expected an anonymity violation for a non-enum reason key") + } + if !strings.Contains(err.Error(), "availability_block_reasons_24h") { + t.Errorf("violation should name the offending field, got: %v", err) + } + if strings.Contains(err.Error(), "acme-internal") { + t.Errorf("violation must never echo the offending key: %v", err) + } +} + +// P016: the scanner also rejects non-integer / negative preflight scalars. +func TestScanForPII_RejectsMalformedPreflightScalars(t *testing.T) { + cases := []string{ + `{"preflight":{"filter_diag_emitted_24h":-1}}`, + `{"preflight":{"discovery_omission_24h":"3"}}`, + `{"preflight":{"availability_block_24h":1.5}}`, + `{"preflight":null}`, + } + for _, payload := range cases { + if err := ScanForPII([]byte(payload)); err == nil { + t.Errorf("expected a violation for %s", payload) + } + } +} + +// P016b: the preflight sub-object is CLOSED — a key outside the documented +// counter set is rejected before transmit, whatever it carries. This is the +// backstop for a future field that smuggles free text (a server name, a query, +// an error message) into a sub-object whose whole contract is "counts only". +func TestScanForPII_RejectsUnknownPreflightKey(t *testing.T) { + cases := []struct { + payload string + // mustNotEcho is content the violation message may never repeat. The + // generic prefix/regex rules run first and legitimately name their own + // literal pattern, so only rule-7-specific cases assert this. + mustNotEcho string + }{ + {`{"preflight":{"availability_block_24h":1,"last_blocked_server":"acme-internal"}}`, "acme-internal"}, + {`{"preflight":{"availability_block_24h":1,"top_query":"list the deploy keys"}}`, "deploy keys"}, + {`{"preflight":{"filter_diag_emitted_24h":1,"filter_diag_emitted_48h":2}}`, ""}, + } + for _, tc := range cases { + err := ScanForPII([]byte(tc.payload)) + if err == nil { + t.Errorf("expected a violation for an unknown preflight key: %s", tc.payload) + continue + } + if tc.mustNotEcho != "" && strings.Contains(err.Error(), tc.mustNotEcho) { + t.Errorf("violation must never echo the offending content: %v", err) + } + } +} + +// P016c: the closed-key set is exactly what MarshalJSON emits, so a populated +// payload can never trip the rule it is guarded by. +func TestScanForPII_PreflightAllowedKeysMatchWireForm(t *testing.T) { + full := PreflightCounters{ + FilterDiagEmitted24h: 1, + FilterDiagMissingAnnotation24h: 2, + FilterDiagExplicit24h: 3, + FilterDiagFollowed24h: 4, + AvailabilityBlock24h: 5, + AvailabilityBlockReasons24h: map[string]int{BlockReasonOther: 5}, + DiscoveryOmission24h: 6, + } + raw, err := json.Marshal(full) + if err != nil { + t.Fatalf("MarshalJSON: %v", err) + } + var out map[string]json.RawMessage + if err := json.Unmarshal(raw, &out); err != nil { + t.Fatalf("Unmarshal: %v", err) + } + for key := range out { + if !isPreflightAllowedKey(key) { + t.Errorf("wire form emits %q, which the scanner would reject", key) + } + } + if len(out) != len(preflightAllowedKeys) { + t.Errorf("wire form has %d keys, allow-list has %d — they must stay in sync", + len(out), len(preflightAllowedKeys)) + } + if err := ScanForPII([]byte(`{"preflight":` + string(raw) + `}`)); err != nil { + t.Errorf("fully populated preflight must pass the scanner: %v", err) + } +} + +// P017: a well-formed preflight sub-object passes the scanner untouched. +func TestScanForPII_AcceptsWellFormedPreflight(t *testing.T) { + payload := []byte(`{"preflight":{"filter_diag_emitted_24h":3,` + + `"filter_diag_missing_annotation_24h":7,"filter_diag_explicit_24h":2,` + + `"filter_diag_followed_24h":1,"availability_block_24h":4,` + + `"availability_block_reasons_24h":{"server_quarantined":3,"token_scope":1},` + + `"discovery_omission_24h":9}}`) + if err := ScanForPII(payload); err != nil { + t.Errorf("well-formed preflight must pass, got: %v", err) + } +} diff --git a/internal/telemetry/telemetry.go b/internal/telemetry/telemetry.go index aefc08b7..4583ff82 100644 --- a/internal/telemetry/telemetry.go +++ b/internal/telemetry/telemetry.go @@ -276,6 +276,14 @@ type HeartbeatPayload struct { // MCPX_* enum strings, non-negative int counts. Diagnostics *DiagnosticsCounters `json:"diagnostics,omitempty"` + // Issue #969 (Phase 0): required-tools-preflight BASELINE counters — + // filter-diagnostics engagement + availability/discovery-omission classes. + // Omitted entirely when all counters are zero (omitempty on the pointer), + // so an install that never trips one is shape-identical to a payload from + // before this field existed. No PII: non-negative counts, plus a reason map + // keyed exclusively by the closed availabilityBlockReasonKeys enum. + Preflight *PreflightCounters `json:"preflight,omitempty"` + // Schema v8: anonymous TPA / security-scanner outcome counters. Omitted // entirely when all counters are zero (omitempty on the pointer) — an // install that never scans is shape-identical to a v7 payload. No PII: @@ -353,6 +361,12 @@ type Service struct { diagCounterStore DiagnosticsCounterStore diagCounterDB *bbolt.DB + // Issue #969 (Phase 0): preflight baseline counter store + DB handle. + // Optional — same nil-safety guarantee as activationStore. When nil, the + // preflight sub-object is omitted and every Record* below is a no-op. + preflightStore PreflightCounterStore + preflightDB *bbolt.DB + // Spec 080 (US2): funnel observability store + DB handle. Optional — // same nil-safety guarantee as activationStore. When nil, web_ui_opened, // days_since_install, and active_days_30d are omitted (short-lived CLI @@ -545,6 +559,104 @@ func (s *Service) DiagnosticsCounterDB() *bbolt.DB { return s.diagCounterDB } +// SetPreflightCounterStore wires the BBolt-backed preflight baseline counter +// store (issue #969, Phase 0). Optional; when unset, heartbeat payloads omit +// the preflight object and every Record* below is a no-op. Safe to call once +// during startup. +func (s *Service) SetPreflightCounterStore(store PreflightCounterStore, db *bbolt.DB) { + s.preflightStore = store + s.preflightDB = db +} + +// PreflightCounterStore returns the wired preflight counter store (or nil). +func (s *Service) PreflightCounterStore() PreflightCounterStore { + return s.preflightStore +} + +// PreflightCounterDB returns the BBolt DB handle associated with the preflight +// counter store (or nil). +func (s *Service) PreflightCounterDB() *bbolt.DB { + return s.preflightDB +} + +// preflightSink returns the store/DB pair to write to, or (nil, nil) when +// nothing may be recorded. +// +// The opt-out is evaluated at EVENT time, not only at heartbeat time — the +// strictest of the existing postures (recordUpdateFailure, spec 095 FR-013). +// An occurrence observed while telemetry is off is never persisted, so it can +// never become transmissible if the user turns telemetry back on later. +func (s *Service) preflightSink() (PreflightCounterStore, *bbolt.DB) { + if s == nil || s.preflightStore == nil || s.preflightDB == nil { + return nil, nil + } + if s.optedOut.Load() { + return nil, nil + } + s.mu.Lock() + cfg := s.config + s.mu.Unlock() + if !EffectiveTelemetryEnabled(cfg) { + return nil, nil + } + return s.preflightStore, s.preflightDB +} + +// preflightDebug logs a counter-persistence failure without ever propagating it +// — a telemetry counter must never break the request path that produced it. +func (s *Service) preflightDebug(msg string, err error) { + if err == nil || s.logger == nil { + return + } + s.logger.Debug(msg, zap.Error(err)) +} + +// RecordFilterDiagnosticsEmitted counts one retrieve_tools response that +// carried a spec-094 filter_diagnostics block, plus that block's per-reason +// class totals. Counts only — the filter keys and tool identities stay in the +// response and never reach telemetry. +func (s *Service) RecordFilterDiagnosticsEmitted(missingAnnotation, explicit int) { + store, db := s.preflightSink() + if store == nil { + return + } + s.preflightDebug("Failed to record filter_diagnostics emission", + store.RecordFilterDiagnosticsEmitted(db, missingAnnotation, explicit)) +} + +// RecordFilterDiagnosticsFollowed counts one diagnostics block the agent acted +// on (a later same-session retrieve_tools relaxed a blamed filter). +func (s *Service) RecordFilterDiagnosticsFollowed() { + store, db := s.preflightSink() + if store == nil { + return + } + s.preflightDebug("Failed to record filter_diagnostics follow-up", + store.RecordFilterDiagnosticsFollowed(db)) +} + +// RecordAvailabilityBlock counts one policy block by its structured reason key. +// Reasons outside the closed enum are folded into "other" by the store. +func (s *Service) RecordAvailabilityBlock(reason string) { + store, db := s.preflightSink() + if store == nil { + return + } + s.preflightDebug("Failed to record availability block", + store.RecordAvailabilityBlock(db, reason)) +} + +// RecordDiscoveryOmission counts one retrieve_tools response that withheld +// locked/quarantined matches from the caller. +func (s *Service) RecordDiscoveryOmission() { + store, db := s.preflightSink() + if store == nil { + return + } + s.preflightDebug("Failed to record discovery omission", + store.RecordDiscoveryOmission(db)) +} + // SetConfiguredIDECountProvider wires a function that returns the number of // IDE client config files mcpproxy has registered itself into (Spec 044). // Typically supplied by internal/connect.Service. @@ -989,6 +1101,20 @@ func (s *Service) buildHeartbeat() HeartbeatPayload { } } + // Issue #969 (Phase 0): preflight baseline counters. Same flush shape as + // the Phase H diagnostics block above — load from BBolt (decay applied at + // read time), omit entirely when all counters are zero or the store is not + // wired (short-lived CLI commands). + if s.preflightStore != nil && s.preflightDB != nil { + if snap, err := s.preflightStore.Snapshot(s.preflightDB); err == nil { + if !snap.isZero() { + payload.Preflight = &snap + } + } else { + s.logger.Debug("Failed to load preflight counters for heartbeat", zap.Error(err)) + } + } + return payload } From 5db7652358fe2ea36442de0126367f61875e5850 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Sat, 15 Aug 2026 22:32:56 +0300 Subject: [PATCH 2/5] fix(telemetry): correct preflight counter attribution from cross-model review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Related #969 Cross-model (opencode/gpt-5.6-sol) review of the Phase-0 baseline counters found five accounting defects. All are in the *attribution* of the counters, not their privacy posture — no payload shape changed. Filter-diagnostics follow-through (in-memory session notes): - Two retrieve_tools calls of one session can be in flight at once and finish out of order. A late-landing EARLIER call overwrote the note describing the block the agent most recently received, which both compared the next call against the wrong filter set and back-dated the TTL. noteFilterDiagnostics now keeps the newer note. - The read side had the mirror defect: a call that STARTED before the note was written passed the TTL check (a negative age is never > TTL), counted itself as a follow-up to a block it never saw, and consumed the note the genuinely later call needed. consumeFilterDiagFollowUp now leaves such a note in place. - Refreshing a session that already had a note ran the capacity prune even though replacing a key cannot grow the map, evicting an unrelated session's still-eligible note. Emission accounting: - The emitted counter and the note were hooked at the ATTACH site, before tool_response_limit truncation, which can cut the block back out of the delivered payload (SimpleTruncate is a plain tail cut). A block the agent never received was counted as emitted and could be "followed". Both now run after truncation, guarded by filterDiagnosticsSurvived. Since emitted is the denominator of the followed/emitted ratio, overcounting it understated the one number these counters exist to measure. Availability block reasons: - Direct mode funnels server-quarantine, pending approval, changed approval and plain not-callable through one emit site, so every direct-mode block was counted as tool_not_callable. directBlockReasonKey now derives the key from the gate that fired, mirroring directToolCallabilityResult's branches. - Direct-mode agent-token scope and permission denials returned with no policy decision at all — no activity record and no counter. They now emit the same decision the call_tool_* variants emit at the equivalent gate; sessionID and requestID resolution moved above those gates so the records stay correlatable. Reviewer findings not acted on: the opt-out check/send non-atomicity in Service.sendHeartbeat is a pre-existing property of the whole telemetry service (the preflight sink already applies the strictest existing gate, event-time opt-out), and the synchronous BBolt writes follow the established precedent — handleRetrieveToolsWithMode already performs two unconditional counter commits per call on main. Both belong in their own change. --- docs/features/telemetry.md | 2 +- internal/server/mcp.go | 26 +++- internal/server/mcp_direct_callability.go | 39 ++++- internal/server/mcp_routing.go | 56 ++++--- internal/server/preflight_telemetry.go | 46 ++++++ internal/server/preflight_telemetry_test.go | 154 ++++++++++++++++++++ 6 files changed, 290 insertions(+), 33 deletions(-) diff --git a/docs/features/telemetry.md b/docs/features/telemetry.md index f1cb2795..f2b9d4c6 100644 --- a/docs/features/telemetry.md +++ b/docs/features/telemetry.md @@ -173,7 +173,7 @@ about anecdotes. | Field | Type | What it counts | |-------|------|----------------| -| `preflight.filter_diag_emitted_24h` | non-negative integer | `retrieve_tools` responses that carried a `filter_diagnostics` block in the last 24h — the denominator for the rest | +| `preflight.filter_diag_emitted_24h` | non-negative integer | `retrieve_tools` responses that **delivered** a `filter_diagnostics` block in the last 24h — the denominator for the rest. Counted after response truncation, so a block that `tool_response_limit` cut back out of the payload is not counted (and cannot be "followed") | | `preflight.filter_diag_missing_annotation_24h` | non-negative integer | Omissions in those blocks caused by **absent upstream annotations** ("fix the server" class), summed across filters | | `preflight.filter_diag_explicit_24h` | non-negative integer | Omissions caused by an **explicitly unsafe hint** ("the filter is working" class), summed across filters | | `preflight.filter_diag_followed_24h` | non-negative integer | Blocks the agent **acted on**: a later `retrieve_tools` call in the same MCP session dropped or relaxed a filter the block blamed | diff --git a/internal/server/mcp.go b/internal/server/mcp.go index e37af41e..65cb3070 100644 --- a/internal/server/mcp.go +++ b/internal/server/mcp.go @@ -1477,8 +1477,11 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques // retrieve_tools call in this session was handed a spec-094 diagnostics // block, this call counts as "followed" when it dropped or relaxed at least // one of the filters that block blamed. The note is consumed either way, so - // one block can be followed at most once. Evaluated here — before this - // call can write a note of its own — and never blocks the request. + // one block can be followed at most once. Evaluated here — before this call + // can write a note of its own. The lookup itself is an in-memory map read + // under a dedicated mutex; only the rare positive result reaches the + // counter store, whose write shares the cost profile of the activation + // counters this handler already bumps unconditionally above. if p.consumeFilterDiagFollowUp(sessionID, activeFilterKeys(readOnlyOnly, excludeDestructive, excludeOpenWorld), startTime) { p.recordFilterDiagnosticsFollowed() @@ -1759,12 +1762,6 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques // to the pre-feature one. if filterDiag != nil && filterDiag.OmittedTotal >= 1 { response["filter_diagnostics"] = filterDiag - - // Issue #969 (Phase 0): baseline engagement counters, hooked at the - // ATTACH site so "emitted" means "the agent actually received a block". - // Counts only; the note is in-memory and identity-free. - p.recordFilterDiagnosticsEmitted(filterDiag) - p.noteFilterDiagnostics(sessionID, filterDiag, startTime) } // Spec 085 (FR-009): compact responses carry one deterministic hint line @@ -1910,6 +1907,19 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques ) } + // Issue #969 (Phase 0): baseline engagement counters. Hooked HERE, after + // truncation, rather than at the attach site: tool_response_limit can cut + // the block back out of the payload (SimpleTruncate is a plain tail cut), + // and a block the agent never received is neither an emission to count nor + // something a later call can "follow". `emitted` is the denominator the + // followed/emitted ratio divides by, so overcounting it would silently + // understate engagement — the one number these counters exist to measure. + // Counts only; the note is in-memory and identity-free. + if filterDiag != nil && filterDiag.OmittedTotal >= 1 && filterDiagnosticsSurvived(text, wasTruncated) { + p.recordFilterDiagnosticsEmitted(filterDiag) + p.noteFilterDiagnostics(sessionID, filterDiag, startTime) + } + // Emit success event with args and response (Spec 024). The FULL response // goes to the activity log — truncation only shapes what the agent sees // (same order handleReadCache uses). diff --git a/internal/server/mcp_direct_callability.go b/internal/server/mcp_direct_callability.go index d2618709..a9c13458 100644 --- a/internal/server/mcp_direct_callability.go +++ b/internal/server/mcp_direct_callability.go @@ -9,6 +9,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/auth" "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/storage" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/telemetry" ) type directCallabilityDecision struct { @@ -75,19 +76,51 @@ func (p *MCPProxyServer) filterDirectToolsForAgentCallability(ctx context.Contex // is not callable. It mirrors the call_tool_* policy boundary so direct mode // cannot bypass disabled-tool, server-quarantine, or tool-approval controls. func (p *MCPProxyServer) directToolCallabilityBlock(ctx context.Context, serverName, toolName string, args map[string]interface{}) *mcp.CallToolResult { + result, _ := p.directToolCallabilityBlockWithReason(ctx, serverName, toolName, args) + return result +} + +// directToolCallabilityBlockWithReason is directToolCallabilityBlock plus the +// structured reason key of the gate that fired (issue #969). Direct mode routes +// server-quarantine, pending approval, changed approval, and plain +// not-callable through a SINGLE emit site, so without carrying the key out of +// the evaluator every direct-mode block would be counted as +// tool_not_callable — the availability reason distribution these counters exist +// to measure would be wrong for the whole direct surface. Returns ("" ) when +// the tool is callable. +func (p *MCPProxyServer) directToolCallabilityBlockWithReason(ctx context.Context, serverName, toolName string, args map[string]interface{}) (*mcp.CallToolResult, string) { // Unit tests historically construct a minimal MCPProxyServer with no // storage. Preserve that narrow behavior; production servers always have // storage and therefore enforce the policy below. if p.storage == nil { - return nil + return nil, "" } decision := newDirectCallabilityEvaluator(p).evaluate(serverName, toolName) if decision.callable { - return nil + return nil, "" } - return p.directToolCallabilityResult(ctx, decision, args) + return p.directToolCallabilityResult(ctx, decision, args), directBlockReasonKey(decision) +} + +// directBlockReasonKey classifies a direct-mode callability block onto the +// closed telemetry.BlockReason* enum. The branches mirror +// directToolCallabilityResult exactly, so the counted reason always matches the +// payload the caller was handed. +func directBlockReasonKey(decision directCallabilityDecision) string { + switch { + case decision.serverConfig != nil && decision.serverConfig.Quarantined: + return telemetry.BlockReasonServerQuarantined + case decision.approvalStatus == storage.ToolApprovalStatusPending: + return telemetry.BlockReasonToolPendingApproval + case decision.approvalStatus == storage.ToolApprovalStatusChanged: + return telemetry.BlockReasonToolChanged + default: + // Disabled server, config-denied tool, per-tool disable, and the + // storage-error fallback all present as "not callable". + return telemetry.BlockReasonToolNotCallable + } } func (e *directCallabilityEvaluator) evaluate(serverName, toolName string) directCallabilityDecision { diff --git a/internal/server/mcp_routing.go b/internal/server/mcp_routing.go index 4d7da6e2..e186eef2 100644 --- a/internal/server/mcp_routing.go +++ b/internal/server/mcp_routing.go @@ -155,12 +155,38 @@ func (p *MCPProxyServer) makeDirectModeHandler(serverName, toolName string, anno return func(ctx context.Context, request mcp.CallToolRequest) (*mcp.CallToolResult, error) { startTime := time.Now() + // Get session ID for activity logging + var sessionID string + if sess := mcpserver.ClientSessionFromContext(ctx); sess != nil { + sessionID = sess.SessionID() + } + + // Get request ID from context. Direct-mode calls that did not arrive + // over an HTTP transport carry none, and every activity this handler + // emits — including the agent-token and callability blocks below, which + // fire before anything else — needs an id a consumer can correlate on. + // Mint one rather than emit anonymously; a transport-supplied id always + // wins so the records still line up with the access log. + // + // Both ids are resolved BEFORE the agent-token gates so those denials + // can emit a correlatable policy decision like every other block. + requestID := reqcontext.GetRequestID(ctx) + if requestID == "" { + requestID = mintActivityRequestID(serverName, toolName) + } + // Check auth context for server access and permissions authCtx := auth.AuthContextFromContext(ctx) if authCtx != nil { // Check server access if !authCtx.CanAccessServer(serverName) { - return mcp.NewToolResultError(fmt.Sprintf("Access denied: token does not have access to server '%s'", serverName)), nil + errMsg := fmt.Sprintf("Access denied: token does not have access to server '%s'", serverName) + // Direct mode denied these silently: no activity record and, + // since issue #969, no availability counter either. Emit the + // same policy decision the call_tool_* variants emit at the + // equivalent gate so the funnel has no blind spot. + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", errMsg, telemetry.BlockReasonTokenScope) + return mcp.NewToolResultError(errMsg), nil } // Determine required permission from annotations @@ -171,27 +197,12 @@ func (p *MCPProxyServer) makeDirectModeHandler(serverName, toolName string, anno } if !authCtx.HasPermission(requiredPerm) { - return mcp.NewToolResultError(fmt.Sprintf("Permission denied: token does not have '%s' permission required for tool '%s:%s'", requiredPerm, serverName, toolName)), nil + errMsg := fmt.Sprintf("Permission denied: token does not have '%s' permission required for tool '%s:%s'", requiredPerm, serverName, toolName) + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", errMsg, telemetry.BlockReasonTokenPermission) + return mcp.NewToolResultError(errMsg), nil } } - // Get session ID for activity logging - var sessionID string - if sess := mcpserver.ClientSessionFromContext(ctx); sess != nil { - sessionID = sess.SessionID() - } - - // Get request ID from context. Direct-mode calls that did not arrive - // over an HTTP transport carry none, and every activity this handler - // emits — including the callability block below, which fires before - // anything else — needs an id a consumer can correlate on. Mint one - // rather than emit anonymously; a transport-supplied id always wins so - // the records still line up with the access log. - requestID := reqcontext.GetRequestID(ctx) - if requestID == "" { - requestID = mintActivityRequestID(serverName, toolName) - } - // Get arguments from the request args := request.GetArguments() enrichedArgs := injectAuthMetadata(ctx, args) @@ -199,8 +210,11 @@ func (p *MCPProxyServer) makeDirectModeHandler(serverName, toolName string, anno // Enforce direct-mode callability before emitting a tool-started event or // invoking upstream. Direct mode must not bypass disabled, quarantine, or // approval controls enforced by call_tool_* variants. - if blocked := p.directToolCallabilityBlock(ctx, serverName, toolName, enrichedArgs); blocked != nil { - p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", "direct tool is not callable", telemetry.BlockReasonToolNotCallable) + // The reason key comes from the gate that actually fired (quarantine, + // pending/changed approval, or plain not-callable) rather than from + // this one funnel site — see directBlockReasonKey. + if blocked, reasonKey := p.directToolCallabilityBlockWithReason(ctx, serverName, toolName, enrichedArgs); blocked != nil { + p.emitActivityPolicyDecision(serverName, toolName, sessionID, requestID, "blocked", "direct tool is not callable", reasonKey) return blocked, nil } diff --git a/internal/server/preflight_telemetry.go b/internal/server/preflight_telemetry.go index 6174923e..5b87861d 100644 --- a/internal/server/preflight_telemetry.go +++ b/internal/server/preflight_telemetry.go @@ -2,6 +2,7 @@ package server import ( "sort" + "strings" "time" ) @@ -57,6 +58,21 @@ func (p *MCPProxyServer) recordAvailabilityBlock(reason string) { p.mainServer.runtime.RecordAvailabilityBlock(reason) } +// filterDiagnosticsResponseKey is the response key the spec-094 block is +// attached under. Used to confirm the block survived response truncation. +const filterDiagnosticsResponseKey = `"filter_diagnostics"` + +// filterDiagnosticsSurvived reports whether the diagnostics block is still in +// the payload the agent will actually receive. An untruncated response always +// carries it (the caller only asks when it was attached), so the string search +// is confined to the truncated path and never runs on the common case. +func filterDiagnosticsSurvived(deliveredText string, wasTruncated bool) bool { + if !wasTruncated { + return true + } + return strings.Contains(deliveredText, filterDiagnosticsResponseKey) +} + // --- filter-diagnostics follow-through, per session --- // filterDiagNote remembers the filters a diagnostics block blamed on the last @@ -117,6 +133,23 @@ func (p *MCPProxyServer) noteFilterDiagnostics(sessionID string, diag *filterDia if p.filterDiagNotes == nil { p.filterDiagNotes = make(map[string]filterDiagNote) } + + // Two retrieve_tools calls of one session can be in flight at once and + // finish out of order, so an EARLIER call may land here after a later one. + // The note must describe the block the agent most recently received: + // letting the stale write win would both compare the next call against the + // wrong filter set and back-date the TTL, expiring the note early. + if prev, exists := p.filterDiagNotes[sessionID]; exists { + if !at.After(prev.at) { + return + } + // Replacing an existing key cannot grow the map, so skip the prune — + // at capacity it would evict an unrelated session's still-eligible + // note to make room that is not needed. + p.filterDiagNotes[sessionID] = filterDiagNote{filters: filters, at: at} + return + } + p.pruneFilterDiagNotesLocked(at) p.filterDiagNotes[sessionID] = filterDiagNote{filters: filters, at: at} } @@ -137,6 +170,19 @@ func (p *MCPProxyServer) consumeFilterDiagFollowUp(sessionID string, activeKeys if !ok { return false } + + // Mirror of the write-side ordering guard: overlapping calls in one session + // mean this call may have STARTED before the note was written, in which + // case the block had not been delivered yet and this call cannot be a + // reaction to it. Leave the note for the call that genuinely follows — + // consuming it here would both miscount this call and rob the real + // follow-up of its one chance. (A negative age also slips past the TTL + // check below, which compares an unsigned intent against a signed + // duration.) + if !at.After(note.at) { + return false + } + delete(p.filterDiagNotes, sessionID) if at.Sub(note.at) > filterDiagNoteTTL { return false diff --git a/internal/server/preflight_telemetry_test.go b/internal/server/preflight_telemetry_test.go index a2fc7665..8ccbbed0 100644 --- a/internal/server/preflight_telemetry_test.go +++ b/internal/server/preflight_telemetry_test.go @@ -2,6 +2,7 @@ package server import ( "context" + "fmt" "testing" "time" @@ -11,6 +12,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" "github.com/smart-mcp-proxy/mcpproxy-go/internal/runtime" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/storage" "github.com/smart-mcp-proxy/mcpproxy-go/internal/telemetry" ) @@ -130,6 +132,158 @@ func TestFilterDiagNotes_Bounded(t *testing.T) { require.LessOrEqual(t, len(p.filterDiagNotes), maxFilterDiagNotes) } +// Concurrent retrieve_tools calls in ONE session can complete out of order. +// The note the agent most recently received must win, so a LATE-finishing +// earlier call may not clobber it (opencode review, round 1, finding 3). +func TestFilterDiagNotes_StaleWriteDoesNotClobberNewer(t *testing.T) { + p := &MCPProxyServer{} + base := time.Now() + + // Call B (started later) lands first, then call A (started earlier) lands. + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyExcludeDestruct), base.Add(time.Second)) + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), base) + + p.filterDiagMu.Lock() + note := p.filterDiagNotes["sess-1"] + p.filterDiagMu.Unlock() + require.Equal(t, []string{filterKeyExcludeDestruct}, note.filters, + "the newer note must survive the late-landing older write") + require.True(t, note.at.Equal(base.Add(time.Second)), + "the newer timestamp must survive, else the TTL expires early") + + // The follow-up is therefore judged against the filters the agent actually + // saw last: dropping exclude_destructive counts. + require.True(t, p.consumeFilterDiagFollowUp("sess-1", + []string{filterKeyReadOnlyOnly}, base.Add(2*time.Second))) +} + +// Refreshing a session that ALREADY has a note cannot grow the map, so it must +// not evict an unrelated session's still-eligible note (finding 4). +func TestFilterDiagNotes_RefreshAtCapacityEvictsNothing(t *testing.T) { + p := &MCPProxyServer{} + base := time.Now() + + // Fill exactly to capacity; sess-0 is the oldest and therefore the entry a + // capacity eviction would take. + for i := 0; i < maxFilterDiagNotes; i++ { + p.noteFilterDiagnostics(fmt.Sprintf("sess-%d", i), + diagBlaming(filterKeyReadOnlyOnly), base.Add(time.Duration(i)*time.Millisecond)) + } + require.Len(t, p.filterDiagNotes, maxFilterDiagNotes) + + // The NEWEST session gets a second diagnostics block. This replaces its own + // key, so nothing needs to be evicted. + newest := fmt.Sprintf("sess-%d", maxFilterDiagNotes-1) + p.noteFilterDiagnostics(newest, diagBlaming(filterKeyExcludeDestruct), base.Add(time.Hour)) + + require.Len(t, p.filterDiagNotes, maxFilterDiagNotes) + p.filterDiagMu.Lock() + _, oldestSurvived := p.filterDiagNotes["sess-0"] + p.filterDiagMu.Unlock() + require.True(t, oldestSurvived, + "replacing an existing key must not cost an unrelated session its note") +} + +// The consume side has the same out-of-order hazard as the write side: a call +// that STARTED before the note was written cannot be a reaction to it, so it +// must neither count itself as a follow-up nor destroy the note the genuinely +// later call still needs (opencode review, round 2, finding 2). +func TestFilterDiagFollowUp_EarlierCallCannotConsumeNewerNote(t *testing.T) { + p := &MCPProxyServer{} + base := time.Now() + + // Call B is handed the block at base+1s. + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), base.Add(time.Second)) + + // Call A started at base — before that block existed — and drops the + // blamed filter for unrelated reasons. It must not count. + require.False(t, p.consumeFilterDiagFollowUp("sess-1", nil, base), + "a call that predates the block cannot be a reaction to it") + + // And the note must still be there for the call that genuinely follows. + require.True(t, p.consumeFilterDiagFollowUp("sess-1", nil, base.Add(2*time.Second)), + "the stale call must not have consumed the note") +} + +// A block that tool_response_limit cut back out of the payload was never +// received, so it is neither an emission nor something a later call can follow +// (opencode review, round 2, finding 3). +func TestFilterDiagnosticsSurvived(t *testing.T) { + withBlock := `{"filter_diagnostics":{"omitted_total":3},"tools":[]}` + cutAway := `{"tools":[{"name":"a"}]}... [truncated]` + + // Untruncated responses always carry what was attached — no scan needed. + require.True(t, filterDiagnosticsSurvived(cutAway, false), + "an untruncated response carries the block the handler attached") + + require.True(t, filterDiagnosticsSurvived(withBlock, true), + "truncation that preserved the block still counts as emitted") + require.False(t, filterDiagnosticsSurvived(cutAway, true), + "a block truncated out of the payload was never delivered") +} + +// --- direct-mode block reason classification (finding 5) --- + +// Direct mode funnels every callability block through ONE emit site. The reason +// key must still come from what actually fired, or the whole availability +// reason distribution collapses into tool_not_callable. +func TestDirectBlockReasonKey_ClassifiesPerGate(t *testing.T) { + quarantined := directCallabilityDecision{ + serverConfig: &config.ServerConfig{Name: "github", Enabled: true, Quarantined: true}, + } + require.Equal(t, telemetry.BlockReasonServerQuarantined, directBlockReasonKey(quarantined)) + + pending := directCallabilityDecision{ + serverConfig: &config.ServerConfig{Name: "github", Enabled: true}, + approvalStatus: storage.ToolApprovalStatusPending, + } + require.Equal(t, telemetry.BlockReasonToolPendingApproval, directBlockReasonKey(pending)) + + changed := directCallabilityDecision{ + serverConfig: &config.ServerConfig{Name: "github", Enabled: true}, + approvalStatus: storage.ToolApprovalStatusChanged, + } + require.Equal(t, telemetry.BlockReasonToolChanged, directBlockReasonKey(changed)) + + disabled := directCallabilityDecision{ + serverConfig: &config.ServerConfig{Name: "github", Enabled: false}, + } + require.Equal(t, telemetry.BlockReasonToolNotCallable, directBlockReasonKey(disabled)) + + // Every key the classifier can produce is a member of the closed enum, so a + // direct-mode block can never land in the "other" overflow bucket. + for _, d := range []directCallabilityDecision{quarantined, pending, changed, disabled} { + require.True(t, telemetry.IsAvailabilityBlockReason(directBlockReasonKey(d))) + } +} + +// The reason travels with the block result, so the routing handler emits the +// key that matches the gate that fired. +func TestDirectToolCallabilityBlockWithReason_Quarantine(t *testing.T) { + proxy := createTestMCPProxyServer(t) + require.NoError(t, proxy.storage.SaveUpstreamServer(&config.ServerConfig{ + Name: "github", Enabled: true, Quarantined: true, + })) + + result, reasonKey := proxy.directToolCallabilityBlockWithReason( + context.Background(), "github", "list_repos", map[string]interface{}{}) + require.NotNil(t, result) + require.Equal(t, telemetry.BlockReasonServerQuarantined, reasonKey) +} + +// A callable tool yields no block and no reason key. +func TestDirectToolCallabilityBlockWithReason_CallableIsSilent(t *testing.T) { + proxy := createTestMCPProxyServer(t) + require.NoError(t, proxy.storage.SaveUpstreamServer(&config.ServerConfig{ + Name: "github", Enabled: true, + })) + + result, reasonKey := proxy.directToolCallabilityBlockWithReason( + context.Background(), "github", "list_repos", map[string]interface{}{}) + require.Nil(t, result) + require.Empty(t, reasonKey) +} + // --- end-to-end through retrieve_tools --- // newPreflightCountedProxy builds the spec-094 fixture proxy with a telemetry From 77113e4214ae1b1fd9809bb19953c655b04269c0 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Sat, 15 Aug 2026 22:50:14 +0300 Subject: [PATCH 3/5] fix(telemetry): order diagnostics notes by delivery, require an intact block MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Related #969 Round-3 findings from the cross-model review, both against the round-2 fixes. Partial blocks no longer count as emitted. Checking only that the delivered text still contains the "filter_diagnostics" key was too weak: both truncation paths cut the serialized response at a byte offset and append a plain-text notice, so a cut can land inside the block and leave the key with an unterminated value the agent cannot act on. filterDiagnosticsSurvived now verifies the block's object is balanced and closed within the delivered text. Parsing the payload as a whole is not an option — the appended notice means the delivered text is never valid JSON, so that check would have reported false for every truncated response and traded overcounting for undercounting. Notes are stamped at DELIVERY time rather than request start. Overlapping calls in one session can finish out of order, so start time ordered the notes backwards: a call that started first but returned last is the response the agent saw last, yet its note was rejected as stale. Delivery time makes the follow-through comparison a plain causality test — a reaction can only come from a call that started after the block reached the agent — which also removes the equal-start-timestamp edge case, since the two sides are now sampled at different moments by construction. The TTL is measured from delivery too, which is what the 15-minute window was always meant to mean. --- internal/server/mcp.go | 7 +- internal/server/preflight_telemetry.go | 104 +++++++++++++++----- internal/server/preflight_telemetry_test.go | 65 +++++++++++- 3 files changed, 151 insertions(+), 25 deletions(-) diff --git a/internal/server/mcp.go b/internal/server/mcp.go index 65cb3070..411993a1 100644 --- a/internal/server/mcp.go +++ b/internal/server/mcp.go @@ -1915,9 +1915,14 @@ func (p *MCPProxyServer) handleRetrieveToolsWithMode(ctx context.Context, reques // followed/emitted ratio divides by, so overcounting it would silently // understate engagement — the one number these counters exist to measure. // Counts only; the note is in-memory and identity-free. + // + // The note is stamped with DELIVERY time (now), not the request's start + // time: overlapping calls in one session can finish out of order, so start + // time would order the notes wrongly, and a follow-up can only react to a + // block that had already reached the agent. if filterDiag != nil && filterDiag.OmittedTotal >= 1 && filterDiagnosticsSurvived(text, wasTruncated) { p.recordFilterDiagnosticsEmitted(filterDiag) - p.noteFilterDiagnostics(sessionID, filterDiag, startTime) + p.noteFilterDiagnostics(sessionID, filterDiag, time.Now()) } // Emit success event with args and response (Spec 024). The FULL response diff --git a/internal/server/preflight_telemetry.go b/internal/server/preflight_telemetry.go index 5b87861d..d4d18535 100644 --- a/internal/server/preflight_telemetry.go +++ b/internal/server/preflight_telemetry.go @@ -62,15 +62,68 @@ func (p *MCPProxyServer) recordAvailabilityBlock(reason string) { // attached under. Used to confirm the block survived response truncation. const filterDiagnosticsResponseKey = `"filter_diagnostics"` -// filterDiagnosticsSurvived reports whether the diagnostics block is still in -// the payload the agent will actually receive. An untruncated response always -// carries it (the caller only asks when it was attached), so the string search -// is confined to the truncated path and never runs on the common case. +// filterDiagnosticsSurvived reports whether the diagnostics block is present +// AND COMPLETE in the payload the agent will actually receive. +// +// Both truncation paths cut the serialized response at a byte offset and append +// a plain-text notice, so the delivered text is never parseable JSON as a whole +// — testing the block on its own is the only workable check. Mere key presence +// is not enough either: a cut landing inside the block leaves the key with an +// unterminated value, which no agent can act on, so it must not count as an +// emission. An untruncated response always carries what was attached, so none +// of this runs on the common path. func filterDiagnosticsSurvived(deliveredText string, wasTruncated bool) bool { if !wasTruncated { return true } - return strings.Contains(deliveredText, filterDiagnosticsResponseKey) + idx := strings.Index(deliveredText, filterDiagnosticsResponseKey) + if idx < 0 { + return false + } + rest := deliveredText[idx+len(filterDiagnosticsResponseKey):] + colon := strings.IndexByte(rest, ':') + if colon < 0 { + return false + } + return hasCompleteJSONObject(rest[colon+1:]) +} + +// hasCompleteJSONObject reports whether s opens with a JSON object (after +// optional whitespace) that is also CLOSED within s. String contents are +// skipped, so a brace inside a tool description cannot unbalance the scan. +func hasCompleteJSONObject(s string) bool { + i := 0 + for i < len(s) && (s[i] == ' ' || s[i] == '\t' || s[i] == '\n' || s[i] == '\r') { + i++ + } + if i >= len(s) || s[i] != '{' { + return false + } + + depth := 0 + inString := false + escaped := false + for ; i < len(s); i++ { + c := s[i] + switch { + case escaped: + escaped = false + case inString && c == '\\': + escaped = true + case c == '"': + inString = !inString + case inString: + // Braces inside a JSON string are literal text. + case c == '{': + depth++ + case c == '}': + depth-- + if depth == 0 { + return true + } + } + } + return false } // --- filter-diagnostics follow-through, per session --- @@ -84,7 +137,14 @@ type filterDiagNote struct { // filters are the filter keys the block blamed (filterKeyReadOnlyOnly &c), // sorted so comparisons are order-independent. filters []string - at time.Time + // at is when the block was DELIVERED to the agent, not when the request + // that produced it started. Overlapping calls in one session can finish out + // of order, so start time is not a valid ordering key: the note that must + // win is the one for the response the agent saw last. Delivery time is also + // the honest origin for the TTL, and it makes the follow-up comparison a + // plain causality test — a reaction can only come from a call that started + // after the block reached the agent. + at time.Time } const ( @@ -115,9 +175,10 @@ func activeFilterKeys(readOnlyOnly, excludeDestructive, excludeOpenWorld bool) [ } // noteFilterDiagnostics remembers that this session was just handed a -// diagnostics block blaming `diag`'s filters. Sessions without an id (stdio -// transports that do not mint one) are skipped rather than pooled under "", -// which would let one client's call count as another's follow-up. +// diagnostics block blaming `diag`'s filters. `at` is the DELIVERY time of the +// response carrying the block. Sessions without an id (stdio transports that do +// not mint one) are skipped rather than pooled under "", which would let one +// client's call count as another's follow-up. func (p *MCPProxyServer) noteFilterDiagnostics(sessionID string, diag *filterDiagnostics, at time.Time) { if sessionID == "" || diag == nil || len(diag.OmittedByFilter) == 0 { return @@ -134,11 +195,12 @@ func (p *MCPProxyServer) noteFilterDiagnostics(sessionID string, diag *filterDia p.filterDiagNotes = make(map[string]filterDiagNote) } - // Two retrieve_tools calls of one session can be in flight at once and - // finish out of order, so an EARLIER call may land here after a later one. - // The note must describe the block the agent most recently received: - // letting the stale write win would both compare the next call against the - // wrong filter set and back-date the TTL, expiring the note early. + // Two retrieve_tools calls of one session can be in flight at once. Because + // `at` is delivery time, the later write is by construction the block the + // agent saw last — but goroutine scheduling can still land the two writes + // here in either order, so the comparison is explicit. Letting an older + // delivery win would compare the next call against the wrong filter set and + // back-date the TTL, expiring the note early. if prev, exists := p.filterDiagNotes[sessionID]; exists { if !at.After(prev.at) { return @@ -171,14 +233,12 @@ func (p *MCPProxyServer) consumeFilterDiagFollowUp(sessionID string, activeKeys return false } - // Mirror of the write-side ordering guard: overlapping calls in one session - // mean this call may have STARTED before the note was written, in which - // case the block had not been delivered yet and this call cannot be a - // reaction to it. Leave the note for the call that genuinely follows — - // consuming it here would both miscount this call and rob the real - // follow-up of its one chance. (A negative age also slips past the TTL - // check below, which compares an unsigned intent against a signed - // duration.) + // Causality gate: `at` is when THIS call started and note.at is when the + // block was DELIVERED, so a call that started first cannot be reacting to + // it. Leave the note for the call that genuinely follows — consuming it + // here would both miscount this call and rob the real follow-up of its one + // chance. (A negative age also slips past the TTL check below, which + // compares it against a positive duration.) if !at.After(note.at) { return false } diff --git a/internal/server/preflight_telemetry_test.go b/internal/server/preflight_telemetry_test.go index 8ccbbed0..de15aef9 100644 --- a/internal/server/preflight_telemetry_test.go +++ b/internal/server/preflight_telemetry_test.go @@ -205,12 +205,37 @@ func TestFilterDiagFollowUp_EarlierCallCannotConsumeNewerNote(t *testing.T) { "the stale call must not have consumed the note") } +// Notes are ordered by DELIVERY time, so a call that started first but returned +// last correctly owns the note — start time would order these backwards +// (opencode review, round 3, finding 2). +func TestFilterDiagNotes_OrderedByDeliveryNotStart(t *testing.T) { + p := &MCPProxyServer{} + base := time.Now() + + // A started first but delivers last; B started later and delivered first. + // The handler stamps each note at delivery, so A's is the newer note. + bDelivered := base.Add(1 * time.Second) + aDelivered := base.Add(2 * time.Second) + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyExcludeDestruct), bDelivered) + p.noteFilterDiagnostics("sess-1", diagBlaming(filterKeyReadOnlyOnly), aDelivered) + + p.filterDiagMu.Lock() + note := p.filterDiagNotes["sess-1"] + p.filterDiagMu.Unlock() + require.Equal(t, []string{filterKeyReadOnlyOnly}, note.filters, + "the last-DELIVERED block is the one the agent saw last") + + // A call starting after that delivery, having dropped read_only_only, + // counts as the follow-up. + require.True(t, p.consumeFilterDiagFollowUp("sess-1", nil, aDelivered.Add(time.Millisecond))) +} + // A block that tool_response_limit cut back out of the payload was never // received, so it is neither an emission nor something a later call can follow // (opencode review, round 2, finding 3). func TestFilterDiagnosticsSurvived(t *testing.T) { - withBlock := `{"filter_diagnostics":{"omitted_total":3},"tools":[]}` - cutAway := `{"tools":[{"name":"a"}]}... [truncated]` + withBlock := `{"filter_diagnostics":{"omitted_total":3},"tools":[]}` + simpleTruncateNoticeFixture + cutAway := `{"tools":[{"name":"a"}]}` + simpleTruncateNoticeFixture // Untruncated responses always carry what was attached — no scan needed. require.True(t, filterDiagnosticsSurvived(cutAway, false), @@ -222,6 +247,42 @@ func TestFilterDiagnosticsSurvived(t *testing.T) { "a block truncated out of the payload was never delivered") } +// A cut landing INSIDE the block leaves the key present but its value +// unterminated. The agent cannot act on that, so it is not an emission +// (opencode review, round 3, finding 1). +func TestFilterDiagnosticsSurvived_PartialBlockDoesNotCount(t *testing.T) { + // The key survived the byte cut; its object did not. + cutMidValue := `{"disabled":[],"filter_diagnostics":{"omitted_total":3,"omitted_by_fil` + + simpleTruncateNoticeFixture + require.False(t, filterDiagnosticsSurvived(cutMidValue, true), + "an unterminated block was never usable by the agent") + + // Nested objects must be balanced all the way out, not just to the first + // closing brace. + cutInNested := `{"filter_diagnostics":{"omitted_by_filter":{"read_only_only":{"missing_annotation":2}` + + simpleTruncateNoticeFixture + require.False(t, filterDiagnosticsSurvived(cutInNested, true)) + + complete := `{"filter_diagnostics":{"omitted_by_filter":{"read_only_only":{"missing_annotation":2}}},"tools":[` + + simpleTruncateNoticeFixture + require.True(t, complete != "" && filterDiagnosticsSurvived(complete, true), + "the block is complete even though the payload as a whole was cut") +} + +// Braces and quotes inside a JSON string must not unbalance the scan. +func TestHasCompleteJSONObject_IgnoresBracesInStrings(t *testing.T) { + require.True(t, hasCompleteJSONObject(`{"note":"a } brace and a \" quote"}`)) + require.False(t, hasCompleteJSONObject(`{"note":"unterminated } brace`)) + require.True(t, hasCompleteJSONObject(` {"a":1} trailing junk`)) + require.False(t, hasCompleteJSONObject(` "not an object"`)) + require.False(t, hasCompleteJSONObject(``)) +} + +// simpleTruncateNoticeFixture mirrors the plain-text notice both truncation +// paths append. It is why the delivered payload is never parseable JSON as a +// whole, and therefore why the block is checked on its own. +const simpleTruncateNoticeFixture = "\n\n... [truncated by mcpproxy, cache not available]" + // --- direct-mode block reason classification (finding 5) --- // Direct mode funnels every callability block through ONE emit site. The reason From c59a2d5fece08b9553f44cb25786c1b5d8bd6b6a Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Sat, 15 Aug 2026 22:51:44 +0300 Subject: [PATCH 4/5] test(telemetry): pin the diagnostics brace scanner's escape handling Related #969 Table-drives the hasCompleteJSONObject cases, adding the escape-sequence ones: an escaped backslash must be consumed as data so the quote after it genuinely closes the string, and a payload cut immediately after one must read as incomplete. A scanner that desynchronised on those would call a truncated diagnostics block complete and count an emission the agent never received. --- internal/server/preflight_telemetry_test.go | 34 +++++++++++++++++---- 1 file changed, 28 insertions(+), 6 deletions(-) diff --git a/internal/server/preflight_telemetry_test.go b/internal/server/preflight_telemetry_test.go index de15aef9..dafe4e4c 100644 --- a/internal/server/preflight_telemetry_test.go +++ b/internal/server/preflight_telemetry_test.go @@ -269,13 +269,35 @@ func TestFilterDiagnosticsSurvived_PartialBlockDoesNotCount(t *testing.T) { "the block is complete even though the payload as a whole was cut") } -// Braces and quotes inside a JSON string must not unbalance the scan. +// Braces and quotes inside a JSON string must not unbalance the scan, and an +// escape sequence must not desynchronise it — a scanner that mis-tracks string +// state would call a truncated block complete (or vice versa). func TestHasCompleteJSONObject_IgnoresBracesInStrings(t *testing.T) { - require.True(t, hasCompleteJSONObject(`{"note":"a } brace and a \" quote"}`)) - require.False(t, hasCompleteJSONObject(`{"note":"unterminated } brace`)) - require.True(t, hasCompleteJSONObject(` {"a":1} trailing junk`)) - require.False(t, hasCompleteJSONObject(` "not an object"`)) - require.False(t, hasCompleteJSONObject(``)) + for _, tc := range []struct { + name string + in string + want bool + }{ + {"brace and escaped quote inside string", `{"note":"a } brace and a \" quote"}`, true}, + {"unterminated string swallows the brace", `{"note":"unterminated } brace`, false}, + {"trailing junk after a closed object", ` {"a":1} trailing junk`, true}, + {"not an object", ` "not an object"`, false}, + {"empty input", ``, false}, + {"empty object", `{}`, true}, + {"balanced nested", `{"a":{"b":1}}`, true}, + {"unbalanced nested closes only the inner object", `{"a":{"b":1}`, false}, + // An escaped backslash is consumed as data: the quote that follows + // genuinely closes the string, so the trailing brace must be seen. + {"escaped backslash ends the string", `{"a":"x\\"}`, true}, + {"cut immediately after an escaped backslash", `{"a":"x\\`, false}, + {"escaped quote does not end the string", `{"a":"x\""}`, true}, + {"brace inside string", `{"a":"}"}`, true}, + {"escaped quote then brace inside string", `{"a":"\"}"}`, true}, + } { + t.Run(tc.name, func(t *testing.T) { + require.Equal(t, tc.want, hasCompleteJSONObject(tc.in)) + }) + } } // simpleTruncateNoticeFixture mirrors the plain-text notice both truncation From e9c5f23041336e975cb3a64b73ee3232da6519a5 Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Sat, 15 Aug 2026 23:12:41 +0300 Subject: [PATCH 5/5] fix(telemetry): derive availability_block_24h from its reason split Related #969 Every counter key carries its own window start, so the aggregate availability_block_24h and the per-reason keys it summarises decayed independently. A reason first seen at t=23h opened a window that outlived the total's: at t=25h the total reset to 0 while that reason still reported 1, emitting a payload whose reason counts sum to more than the total they split. The docs call that field "the same total split by reason", so the two disagreeing corrupts exactly the baseline ratios these counters exist to establish. The total is now derived at snapshot time as the sum of the reason counts instead of being stored. Every block bumps exactly one reason key (unknown and over-budget keys fold into "other"), so the sum IS the total by construction and the two can no longer drift apart. This also drops one BBolt write per blocked call. There is deliberately no availability_block_24h storage key any more. Test: TestPreflightSnapshot_TotalAlwaysMatchesReasonSplit, which fails against the previous stored-total implementation. --- docs/features/telemetry.md | 2 +- internal/telemetry/preflight_counters.go | 22 +++++--- internal/telemetry/preflight_counters_test.go | 56 ++++++++++++++++++- 3 files changed, 69 insertions(+), 11 deletions(-) diff --git a/docs/features/telemetry.md b/docs/features/telemetry.md index f2b9d4c6..b00310a3 100644 --- a/docs/features/telemetry.md +++ b/docs/features/telemetry.md @@ -177,7 +177,7 @@ about anecdotes. | `preflight.filter_diag_missing_annotation_24h` | non-negative integer | Omissions in those blocks caused by **absent upstream annotations** ("fix the server" class), summed across filters | | `preflight.filter_diag_explicit_24h` | non-negative integer | Omissions caused by an **explicitly unsafe hint** ("the filter is working" class), summed across filters | | `preflight.filter_diag_followed_24h` | non-negative integer | Blocks the agent **acted on**: a later `retrieve_tools` call in the same MCP session dropped or relaxed a filter the block blamed | -| `preflight.availability_block_24h` | non-negative integer | Policy **blocks** (quarantine, scope, permissions, tool approval, output policy) in the last 24h | +| `preflight.availability_block_24h` | non-negative integer | Policy **blocks** (quarantine, scope, permissions, tool approval, output policy) in the last 24h. Derived as the sum of the reason split below — each reason is stored with its own 24h window, and a separate stored total would drift out of agreement with the split it summarises | | `preflight.availability_block_reasons_24h` | map, **fixed enum keys only** → non-negative integer | The same total split by reason: `intent_invalid`, `intent_rejected`, `profile_scope`, `token_scope`, `token_permission`, `server_quarantined`, `tool_pending_approval`, `tool_changed_approval`, `tool_not_callable`, `output_sanitisation`, `output_schema`, `other` | | `preflight.discovery_omission_24h` | non-negative integer | `retrieve_tools` responses that **withheld locked or quarantined matches** the caller could not see (`include_disabled` unset) — the silent-unavailability substrate | diff --git a/internal/telemetry/preflight_counters.go b/internal/telemetry/preflight_counters.go index 091555dc..0ea77fc1 100644 --- a/internal/telemetry/preflight_counters.go +++ b/internal/telemetry/preflight_counters.go @@ -27,9 +27,11 @@ const ( preflightKeyFilterDiagMissing24h = "filter_diag_missing_annotation_24h" preflightKeyFilterDiagExplicit24h = "filter_diag_explicit_24h" preflightKeyFilterDiagFollowed24h = "filter_diag_followed_24h" - preflightKeyAvailabilityBlock24h = "availability_block_24h" preflightKeyDiscoveryOmission24h = "discovery_omission_24h" preflightKeyAvailabilityReasonPfx = "availability_block_reason_24h_" + // NOTE: there is deliberately no availability_block_24h storage key. The + // wire field of that name is the SUM of the per-reason keys, computed at + // snapshot time so the total and its split can never disagree. ) // Availability block reason keys (issue #969). This is a CLOSED enum mirroring @@ -137,7 +139,9 @@ type PreflightCounters struct { // emitted-but-never-followed means the block is being ignored. FilterDiagFollowed24h int `json:"filter_diag_followed_24h"` // AvailabilityBlock24h counts policy blocks (the "blocked" decision on the - // single emitActivityPolicyDecision funnel) in the last 24h. + // single emitActivityPolicyDecision funnel) in the last 24h. Derived: it is + // exactly the sum of AvailabilityBlockReasons24h, since every block bumps + // one reason key. AvailabilityBlock24h int `json:"availability_block_24h"` // AvailabilityBlockReasons24h splits AvailabilityBlock24h by the closed // reason enum. Sparse: reasons with a zero count are omitted. @@ -343,9 +347,13 @@ func (bboltPreflightCounterStore) RecordAvailabilityBlock(db *bbolt.DB, reason s if err != nil { return err } - if err := bumpPreflightCounter(b, preflightKeyAvailabilityBlock24h, 1, now); err != nil { - return err - } + // Only the per-reason key is written. The total is DERIVED from the + // reason counts at snapshot time (see snapshotPreflightAt) rather than + // kept as its own counter: every block bumps exactly one reason key, so + // the sum is the total by construction — whereas a separate aggregate + // key carries its own independent 24h window and would drift out of + // agreement with the split it is supposed to summarise. + // // Write-side cardinality backstop: a key the bucket has never seen is // only admitted while the distinct-key budget holds; past it, the count // still lands (in the overflow bucket) but the key set cannot grow. @@ -418,10 +426,9 @@ func snapshotPreflightAt(db *bbolt.DB, now time.Time) (PreflightCounters, error) out.FilterDiagMissingAnnotation24h = read(preflightKeyFilterDiagMissing24h) out.FilterDiagExplicit24h = read(preflightKeyFilterDiagExplicit24h) out.FilterDiagFollowed24h = read(preflightKeyFilterDiagFollowed24h) - out.AvailabilityBlock24h = read(preflightKeyAvailabilityBlock24h) out.DiscoveryOmission24h = read(preflightKeyDiscoveryOmission24h) - // per-reason 24h counts + // per-reason 24h counts; AvailabilityBlock24h is their sum c := b.Cursor() prefix := []byte(preflightKeyAvailabilityReasonPfx) for k, v := c.Seek(prefix); k != nil && strings.HasPrefix(string(k), preflightKeyAvailabilityReasonPfx); k, v = c.Next() { @@ -440,6 +447,7 @@ func snapshotPreflightAt(db *bbolt.DB, now time.Time) (PreflightCounters, error) out.AvailabilityBlockReasons24h = make(map[string]int) } out.AvailabilityBlockReasons24h[reason] = int(cnt) + out.AvailabilityBlock24h += int(cnt) } } return nil diff --git a/internal/telemetry/preflight_counters_test.go b/internal/telemetry/preflight_counters_test.go index 8755267b..4b253858 100644 --- a/internal/telemetry/preflight_counters_test.go +++ b/internal/telemetry/preflight_counters_test.go @@ -187,9 +187,8 @@ func TestPreflightCounterStore_24hDecay(t *testing.T) { if err := b.Put([]byte(preflightKeyDiscoveryOmission24h), encodeCounter(17, pastStart.Unix())); err != nil { return err } - if err := b.Put([]byte(preflightKeyAvailabilityBlock24h), encodeCounter(9, pastStart.Unix())); err != nil { - return err - } + // availability_block_24h has no storage key of its own — it is the sum + // of the reason keys, so seeding a stale reason covers it. return b.Put([]byte(preflightKeyAvailabilityReasonPfx+BlockReasonToolNotCallable), encodeCounter(9, pastStart.Unix())) }) @@ -573,3 +572,54 @@ func TestScanForPII_AcceptsWellFormedPreflight(t *testing.T) { t.Errorf("well-formed preflight must pass, got: %v", err) } } + +// The total and its per-reason split must never disagree. Each counter key +// carries its OWN window start, so a total whose window opened earlier can +// decay to zero while a reason key that started later survives — producing a +// payload whose reason counts sum to more than the total they supposedly split +// (opencode review, round 4, finding 3). +func TestPreflightSnapshot_TotalAlwaysMatchesReasonSplit(t *testing.T) { + db, cleanup := newTestPreflightDB(t) + defer cleanup() + + now := time.Now() + // reason A's window opened 25h ago (expired); reason B's opened 2h ago. + expired := now.Add(-25 * time.Hour) + recent := now.Add(-2 * time.Hour) + + err := db.Update(func(tx *bbolt.Tx) error { + b, err := tx.CreateBucketIfNotExists([]byte(PreflightCountersBucketName)) + if err != nil { + return err + } + if err := b.Put([]byte(preflightKeyAvailabilityReasonPfx+BlockReasonServerQuarantined), + encodeCounter(1, expired.Unix())); err != nil { + return err + } + return b.Put([]byte(preflightKeyAvailabilityReasonPfx+BlockReasonTokenScope), + encodeCounter(1, recent.Unix())) + }) + if err != nil { + t.Fatalf("seeding counters: %v", err) + } + + var s bboltPreflightCounterStore + snap, err := s.Snapshot(db) + if err != nil { + t.Fatalf("Snapshot: %v", err) + } + + sum := 0 + for _, n := range snap.AvailabilityBlockReasons24h { + sum += n + } + if snap.AvailabilityBlock24h != sum { + t.Errorf("availability_block_24h = %d but its reason split sums to %d; "+ + "the total and the split must be the same number", + snap.AvailabilityBlock24h, sum) + } + // The expired reason is gone, the recent one survives. + if sum != 1 { + t.Errorf("reason split sums to %d, want 1 (the expired reason must decay out)", sum) + } +}