diff --git a/.claude/agents/site-reliability-engineer.md b/.claude/agents/site-reliability-engineer.md index 6bd2d7c5d5..7f8393ea77 100644 --- a/.claude/agents/site-reliability-engineer.md +++ b/.claude/agents/site-reliability-engineer.md @@ -20,7 +20,8 @@ Defer to: code-reviewer (general review), golang-code-writer (business logic), s ### Key Packages - **`pkg/telemetry/`**: Core infrastructure — middleware, OTEL provider setup, context propagation, exporters -- **`pkg/vmcp/server/telemetry.go`**: vMCP telemetry — MCP request/response metrics, backend routing traces, session tracking +- **`pkg/vmcp/internal/backendtelemetry/`**: vMCP backend telemetry — the backend-client decorator recording `mcp.client.operation.duration`, backend routing traces, and the live per-backend health gauge +- **`pkg/vmcp/core/core_telemetry.go`**: vMCP composite-tool (workflow) execution metrics and traces ### Instrumentation Patterns diff --git a/docs/arch/10-virtual-mcp-architecture.md b/docs/arch/10-virtual-mcp-architecture.md index 4bcb07d17b..d6f3b73575 100644 --- a/docs/arch/10-virtual-mcp-architecture.md +++ b/docs/arch/10-virtual-mcp-architecture.md @@ -882,7 +882,7 @@ Middleware is applied by wrapping handlers, so execution order is outer-to-inner | 7 | Annotation Enrichment | Optional | Injects tool annotations into context for annotation-aware authz (only when Authorization is configured) | | 8 | Authorization | Optional | Evaluates Cedar policies after discovery and annotation enrichment | | 9 | Backend Enrichment | Optional | Adds backend name to audit context (only when Audit is configured) | -| 10 | MCP Parsing | Always | Second application is a no-op when auth already parsed; ensures telemetry can label metrics with `mcp_method` when auth is nil | +| 10 | MCP Parsing | Always | Second application is a no-op when auth already parsed; ensures telemetry can label metrics with `mcp_method_name` when auth is nil | | 11 | Telemetry | Optional | OpenTelemetry instrumentation | | 12 | Pre-dispatch authorization gate | Optional | Innermost: runs inside the Streamable HTTP transport before session validation and SDK dispatch. Rejects a Cedar-denied `tools/call` / `resources/read` / `prompts/get` with HTTP 403 + JSON-RPC code 403, reusing the core admission decision. Installed only when Authorization is configured. See "Authorization Enforcement" below. | diff --git a/docs/observability.md b/docs/observability.md index 5dc1543cbc..44ccb5d9cb 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -188,43 +188,38 @@ For VirtualMCPServer telemetry, see the ### MCP Proxy Metrics These metrics are emitted by the telemetry middleware (`pkg/telemetry/middleware.go`) -for each MCP server proxy. +for each MCP server proxy. Metric and label names follow the shared +`stacklok.*`/OTel semantic-convention vocabulary (Metrics Standardization RFC); +see the [Telemetry Migration Guide](./telemetry-migration-guide.md) for the +mapping from the legacy `toolhive_mcp_*` names these replace. -#### `toolhive_mcp_requests` (Counter) +#### `stacklok.toolhive.proxy.active_connections` (UpDownCounter) -Total number of MCP requests processed. +Number of currently active MCP connections. Prometheus exposes this as +`stacklok_toolhive_proxy_active_connections`. | Attribute | Type | Description | |-----------|------|-------------| -| `method` | string | HTTP method (`POST`, `GET`) | -| `status_code` | string | HTTP status code (`200`, `500`) | -| `status` | string | `"success"` or `"error"` (error if status >= 400) | -| `mcp_method` | string | MCP method name (`tools/call`, `resources/read`, etc.) | -| `mcp_resource_id` | string | Tool name, resource URI, or prompt name | -| `server` | string | MCP server name | -| `transport` | string | Backend transport type (`stdio`, `sse`, `streamable-http`) | - -> **Note**: SSE connection establishment events also increment this counter -> with `mcp_method="sse_connection"` and do not include `mcp_resource_id`. - -#### `toolhive_mcp_request_duration` (Histogram, seconds) - -Duration of MCP requests. Uses default histogram bucket boundaries. - -**Attributes**: Same as `toolhive_mcp_requests`. +| `mcp_server` | string | MCP server name | +| `transport` | string | Backend transport type | +| `connection_type` | string | `"sse"` (only present for SSE connections) | #### `mcp.server.operation.duration` (Histogram, seconds) Duration of MCP server operations per the [OTEL MCP semantic conventions](https://github.com/open-telemetry/semantic-conventions/blob/main/docs/gen-ai/mcp.md). +Recorded only for requests with a resolvable MCP method (`tools/call`, +`resources/read`, etc.) — GET (SSE stream open) and DELETE (session +termination) requests carry no MCP method and are not recorded here. -**Bucket boundaries**: `[0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300]` +**Bucket boundaries** (`coremetrics.BucketsMCPSemconv()`): `[0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300]` | Attribute | Type | Condition | Description | |-----------|------|-----------|-------------| | `mcp.method.name` | string | Always | MCP method (`tools/call`, `resources/read`, etc.) | | `jsonrpc.protocol.version` | string | Always | Always `"2.0"` | | `network.transport` | string | Always | `"tcp"` or `"pipe"` | +| `mcp_server` | string | Always | MCP server name | | `network.protocol.name` | string | If applicable | `"http"` for SSE/streamable-http | | `network.protocol.version` | string | If available | HTTP protocol version (`1.1`, `2`) | | `error.type` | string | On HTTP 5xx | HTTP status code as string | @@ -232,25 +227,104 @@ Duration of MCP server operations per the | `gen_ai.tool.name` | string | For `tools/call` | Tool name | | `gen_ai.prompt.name` | string | For `prompts/get` | Prompt name | -#### `toolhive_mcp_tool_calls` (Counter) +> **Note**: `mcp_resource_id` is not recorded under that key. For +> `resources/read` the resource URI is dropped from this metric entirely, but for +> `tools/call` and `prompts/get` the same value is recorded as +> `gen_ai.tool.name`/`gen_ai.prompt.name` — so it moved keys rather than going +> away. +> +> **Cardinality warning**: `gen_ai.tool.name` and `gen_ai.prompt.name` come from +> `params.name` in the client's JSON-RPC request body and are **not** validated +> against the server's resolved tool or prompt set. A client calling arbitrary +> names therefore grows this metric's series count without bound, and since the +> deleted `toolhive_mcp_*` twins made this the sole per-method metric, there is +> no unaffected alternative. Bounding these attributes is tracked separately; in +> the meantime, drop them with a Prometheus `metric_relabel_config` if untrusted +> clients can reach the proxy. +> +> `mcp.method.name` and `http.request.method` are bounded: values outside the +> known set are recorded as the semconv `_OTHER` sentinel. + +#### `http.server.request.duration` (Histogram, seconds) + +Duration of every HTTP request/response-cycle request the middleware +handles, per the +[OTEL HTTP semantic conventions](https://opentelemetry.io/docs/specs/semconv/http/). +Recorded for session-delete DELETEs and other requests carrying no MCP +method — as well as MCP-method-bearing ones — so transport-level coverage +doesn't depend on a resolvable MCP method the way +`mcp.server.operation.duration` does. + +SSE-open GETs are excluded: they block for the connection's full lifetime +(minutes to hours), which would land every observation in this histogram's +10-second top bucket and flatten any quantile query. Those go to +`stacklok.toolhive.proxy.sse_connection.duration` instead, below. + +**Bucket boundaries** (`coremetrics.BucketsFastHTTP()`): `[0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]` -Total number of MCP tool invocations (only recorded for `tools/call` requests). +| Attribute | Type | Condition | Description | +|-----------|------|-----------|-------------| +| `http.request.method` | string | Always | HTTP method (`GET`, `POST`, `DELETE`) | +| `http.response.status_code` | int | Always | HTTP status code | +| `mcp_server` | string | Always | MCP server name | +| `error.type` | string | On HTTP 5xx | HTTP status code as string | -| Attribute | Type | Description | -|-----------|------|-------------| -| `server` | string | MCP server name | -| `tool` | string | Tool name | -| `status` | string | `"success"` or `"error"` | +#### `stacklok.toolhive.proxy.sse_connection.duration` (Histogram, seconds) + +Duration of SSE connections, recorded once the connection closes (not +per-chunk). Kept separate from `http.server.request.duration` because SSE +connections are long-lived — see that metric's description above. + +**Bucket boundaries** (`coremetrics.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 300]` -#### `toolhive_mcp_active_connections` (UpDownCounter) +| Attribute | Type | Condition | Description | +|-----------|------|-----------|-------------| +| `mcp_server` | string | Always | MCP server name | -Number of currently active MCP connections. +#### `stacklok.build_info` (Gauge) + +Registered once per meter provider via the shared `coremetrics.RegisterBuildInfo` +helper (`pkg/telemetry/middleware.go`), so every `/metrics` endpoint a process +exposes carries it. Always reports `1`, carrying version metadata as attributes. + +> **Exported name**: `RegisterBuildInfo` sets the OTel unit to `1`, and the +> Prometheus translator appends a unit suffix to a dimensionless gauge, so this +> scrapes as **`stacklok_build_info_ratio`** — not `stacklok_build_info`. Query +> the `_ratio` name. The `_ratio` suffix is wrong for an identity gauge and the +> durable fix is upstream in `toolhive-core`; until then a dashboard joining on +> `stacklok_build_info` returns empty. | Attribute | Type | Description | |-----------|------|-------------| -| `server` | string | MCP server name | -| `transport` | string | Backend transport type | -| `connection_type` | string | `"sse"` (only present for SSE connections) | +| `component` | string | Always `"toolhive"`. A bare `component` label distinct from the promoted `stacklok_component` below — it exists so this metric's identity doesn't collide with the D8 constant label. | +| `version` | string | ToolHive version | +| `commit` | string | Build commit SHA | + +Like every other metric ToolHive emits, `stacklok.build_info` also carries +`stacklok_component`/`stacklok_product` as constant labels — see +[D8 Ownership Labels](#d8-ownership-labels). Those two are universal, not +specific to this metric. + +### D8 Ownership Labels + +Every metric emitted by ToolHive carries `stacklok_component="toolhive"` and +`stacklok_product="stacklok-platform"`. These are set as OTel resource +attributes, applied as the last OTel resource detector so they cannot be +overridden by `--otel-custom-attributes` or `OTEL_RESOURCE_ATTRIBUTES` (OTel +resource merge is last-detector-wins). See `pkg/telemetry/providers/providers.go`. + +The Prometheus exporter is configured with `WithResourceAsConstantLabels` to +promote exactly these two resource attributes onto every exported series as +constant labels (`pkg/telemetry/providers/prometheus/prometheus.go`) — so in +scraped Prometheus output they appear as per-series labels on every metric, +not only on a separate `target_info`/`stacklok_build_info` line. + +The Go/process runtime metrics (`go_*`, `process_*`) are native Prometheus +collectors registered directly on the raw registry rather than through the +OTel SDK, so `WithResourceAsConstantLabels` does not reach them. They carry +the same two labels via a separate `prometheus.WrapRegistererWith` applied +only to the runtime-metrics registerer, so the D8 labels are consistently +present on every series, including runtime/process metrics. ### Rate Limit Metrics @@ -259,7 +333,7 @@ and VirtualMCPServer. Prometheus appends `_total` to counter names. The latency histogram is exported with the `_seconds` unit suffix and the standard `_bucket`, `_sum`, and `_count` series suffixes. -#### `toolhive_rate_limit_decisions` (Counter) +#### `stacklok.toolhive.ratelimit.decisions` (Counter) Total number of rate limit bucket decisions. An allowed request increments once for every applicable bucket. A rejected request increments only for the first @@ -269,22 +343,22 @@ do not increment this counter. | Attribute | Type | Description | |-----------|------|-------------| | `namespace` | string | Kubernetes namespace associated with the server | -| `server` | string | MCPServer or VirtualMCPServer name | +| `mcp_server` | string | MCPServer or VirtualMCPServer name | | `decision` | string | `"allowed"` or `"rejected"` | | `scope` | string | `"shared"` or `"per_user"` | | `operation_type` | string | `"server"` or `"tool"` | -#### `toolhive_rate_limit_redis_errors` (Counter) +#### `stacklok.toolhive.ratelimit.redis_errors` (Counter) Total number of Redis errors encountered while checking rate limits. | Attribute | Type | Description | |-----------|------|-------------| | `namespace` | string | Kubernetes namespace associated with the server | -| `server` | string | MCPServer or VirtualMCPServer name | +| `mcp_server` | string | MCPServer or VirtualMCPServer name | | `error_type` | string | `"timeout"`, `"connection"`, `"auth"`, or `"other"` | -#### `toolhive_rate_limit_check_latency` (Histogram, seconds) +#### `stacklok.toolhive.ratelimit.check_latency` (Histogram, seconds) Duration of each attempted atomic Redis Lua rate limit check, including failed checks. @@ -292,7 +366,7 @@ checks. | Attribute | Type | Description | |-----------|------|-------------| | `namespace` | string | Kubernetes namespace associated with the server | -| `server` | string | MCPServer or VirtualMCPServer name | +| `mcp_server` | string | MCPServer or VirtualMCPServer name | ## Span Attributes @@ -399,7 +473,9 @@ Only variables explicitly listed in the configuration are captured. **Custom resource attributes** (`--otel-custom-attributes` or `OTEL_RESOURCE_ATTRIBUTES`): Key-value pairs added as OTEL resource attributes -to all telemetry signals. +to all telemetry signals. `stacklok.component`/`stacklok.product` are +reserved and cannot be set this way — see +[D8 Ownership Labels](#d8-ownership-labels). ### SSE Connection Attributes diff --git a/docs/operator/virtualmcpserver-observability.md b/docs/operator/virtualmcpserver-observability.md index d322f34c70..f636f42aa1 100644 --- a/docs/operator/virtualmcpserver-observability.md +++ b/docs/operator/virtualmcpserver-observability.md @@ -24,91 +24,139 @@ The vMCP uses a decorator pattern to wrap backend clients and workflow executors with telemetry instrumentation. This approach provides consistent metrics and tracing without modifying the core business logic. -The implementation of both metrics and traces can be found in `pkg/vmcp/server/telemetry.go`. +The implementation of backend metrics and traces can be found in +`pkg/vmcp/internal/backendtelemetry/backendtelemetry.go`; composite tool +(workflow) telemetry is in `pkg/vmcp/core/core_telemetry.go` and +`pkg/vmcp/server/sessionmanager/factory.go`. ## Metrics +Metric and label names follow the shared `stacklok.*`/OTel semantic-convention +vocabulary (Metrics Standardization RFC); see the +[Telemetry Migration Guide](../telemetry-migration-guide.md) for the mapping +from the legacy `toolhive_vmcp_*` names these replace. + ### Backend Metrics -Backend metrics track requests to individual backend MCP servers. +Backend metrics track requests to individual backend MCP servers +(`pkg/vmcp/internal/backendtelemetry/backendtelemetry.go`). + +#### `stacklok.vmcp.mcp_server.health` (Gauge) + +Per-backend health, re-derived from the live backend registry on every +collection so a backend removed at runtime (e.g. via `list_changed`) stops +being reported instead of leaving a stale series behind. Emits one point per +`(mcp_server, state)` pair — the observed state reports `1`, the other `0`. + +| Attribute | Type | Description | +|-----------|------|-------------| +| `mcp_server` | string | Backend workload name | +| `state` | string | One of `"healthy"`, `"degraded"`, `"unhealthy"`, `"unknown"`, `"unauthenticated"` | + +#### `mcp.client.operation.duration` (Histogram, seconds) + +Duration of MCP client operations per the +[OTEL MCP semantic conventions](https://github.com/open-telemetry/semantic-conventions/blob/main/docs/gen-ai/mcp.md). + +**Bucket boundaries** (`coremetrics.BucketsMCPSemconv()`): `[0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300]` + +| Attribute | Type | Condition | Description | +|-----------|------|-----------|-------------| +| `mcp.method.name` | string | Always | MCP method name | +| `mcp_server` | string | Always | Backend workload name | +| `network.transport` | string | Always | `"tcp"` or `"pipe"` | +| `error.type` | string | On error | Go error type (e.g., `*url.Error`) | + +Backend operation spans carry additional ToolHive-specific and OTEL MCP +semconv attributes (`target.workload_id`, `target.workload_name`, +`target.base_url`, `target.transport_type`, `action`, `gen_ai.tool.name`, +`mcp.resource.uri`, `gen_ai.prompt.name`) — see +[Backend Operation Spans](#backend-operation-spans) below. -#### `toolhive_vmcp_backends_discovered` (Gauge) +### Composite Tool (Workflow) Metrics -Number of backends discovered. Recorded once at startup. +Composite tool metrics track workflow executions +(`pkg/vmcp/core/core_telemetry.go`, `pkg/vmcp/server/sessionmanager/factory.go`). -#### `toolhive_vmcp_backend_requests` (Counter) +#### `stacklok.vmcp.composite_tool.executions` (Counter) -Total number of requests sent to backend MCP servers. +Total number of composite tool workflow executions, split by outcome. | Attribute | Type | Description | |-----------|------|-------------| -| `target.workload_id` | string | Backend workload ID | -| `target.workload_name` | string | Backend workload name | -| `target.base_url` | string | Backend base URL | -| `target.transport_type` | string | Backend transport type (`stdio`, `sse`, `streamable-http`) | -| `action` | string | Internal action name (`call_tool`, `read_resource`, `get_prompt`, `list_capabilities`) | -| `mcp.method.name` | string | MCP method name (`tools/call`, `resources/read`, `prompts/get`, `list_capabilities`) | +| `composite_tool` | string | Composite tool (workflow) name | +| `outcome` | string | `"success"` or `"error"` | -Method-specific attributes (added in addition to the above): +#### `stacklok.vmcp.composite_tool.duration` (Histogram, seconds) -| Attribute | Method | Description | -|-----------|--------|-------------| -| `tool_name` | `call_tool` | Tool name (ToolHive-specific) | -| `gen_ai.tool.name` | `call_tool` | Tool name (OTEL MCP semconv) | -| `resource_uri` | `read_resource` | Resource URI (ToolHive-specific) | -| `mcp.resource.uri` | `read_resource` | Resource URI (OTEL MCP semconv) | -| `prompt_name` | `get_prompt` | Prompt name (ToolHive-specific) | -| `gen_ai.prompt.name` | `get_prompt` | Prompt name (OTEL MCP semconv) | +Duration of composite tool workflow executions, recorded regardless of outcome. -#### `toolhive_vmcp_backend_errors` (Counter) +**Bucket boundaries** (`coremetrics.BucketsLongRunning()`): `[0.1, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 180, 300]` -Total number of errors from backend MCP servers. +| Attribute | Type | Description | +|-----------|------|-------------| +| `composite_tool` | string | Composite tool (workflow) name | -**Attributes**: Same as `toolhive_vmcp_backend_requests`. +### Tool Optimizer Metrics -#### `toolhive_vmcp_backend_requests_duration` (Histogram, seconds) +Emitted only when the tool optimizer is enabled +(`pkg/vmcp/server/sessionmanager/factory.go`). The optimizer exposes two +meta-tools, `find_tool` and `call_tool`, in place of the full aggregated tool +list; these metrics describe their use. -Duration of requests to backend MCP servers. Uses default histogram bucket -boundaries. +#### `stacklok.vmcp.optimizer.find_tool.requests` (Counter) -**Attributes**: Same as `toolhive_vmcp_backend_requests`. +Total number of `find_tool` calls, split by outcome. -#### `mcp.client.operation.duration` (Histogram, seconds) +| Attribute | Type | Description | +|-----------|------|-------------| +| `outcome` | string | `"success"` or `"error"` | -Duration of MCP client operations per the -[OTEL MCP semantic conventions](https://github.com/open-telemetry/semantic-conventions/blob/main/docs/gen-ai/mcp.md). +#### `stacklok.vmcp.optimizer.find_tool.duration` (Histogram, seconds) -**Bucket boundaries**: `[0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300]` +Duration of `find_tool` calls. -| Attribute | Type | Condition | Description | -|-----------|------|-----------|-------------| -| `mcp.method.name` | string | Always | MCP method name | -| `network.transport` | string | Always | `"tcp"` or `"pipe"` | -| `error.type` | string | On error | Go error type (e.g., `*url.Error`) | +**Bucket boundaries** (`coremetrics.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 300]` + +#### `stacklok.vmcp.optimizer.find_tool.results` (Histogram, `{tools}`) + +Number of tools returned per `find_tool` call. The unit is a count, not +seconds, so the Prometheus name carries no `_seconds` infix. + +**Bucket boundaries**: `[0, 1, 2, 3, 5, 10, 20, 50]` -### Workflow Metrics +#### `stacklok.vmcp.optimizer.token_savings` (Histogram, percent) -Workflow metrics track composite tool workflow executions. +Token savings percentage per `find_tool` call, versus advertising the full +tool list. Exported as `stacklok_vmcp_optimizer_token_savings_percent`. -#### `toolhive_vmcp_workflow_executions` (Counter) +**Bucket boundaries**: `[0, 10, 20, 30, 40, 50, 60, 70, 80, 90, 95, 99, 100]` -Total number of workflow executions. +#### `stacklok.vmcp.optimizer.call_tool.requests` (Counter) + +Total number of `call_tool` calls, split by outcome. | Attribute | Type | Description | |-----------|------|-------------| -| `workflow.name` | string | Workflow name | +| `tool_name` | string | Resolved target tool name | +| `outcome` | string | `"success"`, `"error"`, or `"not_found"` | + +#### `stacklok.vmcp.optimizer.call_tool.duration` (Histogram, seconds) -#### `toolhive_vmcp_workflow_errors` (Counter) +Duration of `call_tool` calls. -Total number of workflow execution errors. +**Bucket boundaries** (`coremetrics.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 300]` -**Attributes**: Same as `toolhive_vmcp_workflow_executions`. +| Attribute | Type | Description | +|-----------|------|-------------| +| `tool_name` | string | Resolved target tool name | -#### `toolhive_vmcp_workflow_duration` (Histogram, seconds) +### Backend Revision Metrics -Duration of workflow executions. +#### `stacklok.vmcp.backend.revision_reclassifications` (Counter) -**Attributes**: Same as `toolhive_vmcp_workflow_executions`. +Number of times a backend's MCP revision was reclassified after a call revealed +the cached revision was wrong. Carries no attributes. ## Distributed Tracing diff --git a/docs/telemetry-migration-guide.md b/docs/telemetry-migration-guide.md index 2cc22b795d..18a351e711 100644 --- a/docs/telemetry-migration-guide.md +++ b/docs/telemetry-migration-guide.md @@ -14,17 +14,37 @@ documentation. ## What Changed -ToolHive's telemetry has been updated across two areas: +ToolHive's telemetry has been updated across four areas: 1. **Span attribute names** — Renamed to follow OTEL semantic conventions (HTTP, RPC, MCP/gen_ai namespaces). -2. **New metrics** — Two new histogram metrics following the OTEL MCP spec: - `mcp.server.operation.duration` and `mcp.client.operation.duration`. - -Existing metrics (`toolhive_mcp_requests`, `toolhive_mcp_request_duration`, -`toolhive_mcp_tool_calls`, `toolhive_mcp_active_connections`, and all -`toolhive_vmcp_*` metrics) are **unchanged** — their names and label names -remain the same. +2. **New metrics** — Three new histogram metrics following OTEL semantic + conventions: `mcp.server.operation.duration` and `mcp.client.operation.duration` + (OTEL MCP spec), and `http.server.request.duration` (OTEL HTTP spec, covering + transport-level requests that don't carry an MCP method — SSE connection opens, + session-terminate DELETEs, etc.). +3. **Metric name and label standardization** — The legacy `toolhive_mcp_*` and + `toolhive_vmcp_*` metric names and their label vocabulary (`server`, + `mcp_method`, `tool`, `workflow.name`, …) have been replaced by the shared + `stacklok.*`/OTel-semconv vocabulary (`mcp_server`, `mcp_method_name`, + `gen_ai_tool_name`, `composite_tool`, …), and six legacy metric twins that + duplicated an OTel-semconv equivalent have been deleted outright (see + [Deleted Legacy Metrics](#deleted-legacy-metrics) below). This is a breaking + change for any dashboard or alert querying the old metric/label names. + + One narrowing to be aware of: the deleted `toolhive_mcp_requests`/ + `toolhive_mcp_request_duration` twins classified any HTTP status ≥400 as an + error. The new `http.server.request.duration` metric's `error.type` attribute + follows OTEL HTTP semconv and is only set for status ≥500 (see + [Known Limitations](#known-limitations)). Any dashboard or alert computing + "error rate" from `error.type` presence will stop counting 4xx client errors + (e.g. auth denials) after upgrade. Query `http_response_status_code=~"[45].."` + directly instead if 4xx should still count toward error rate. +4. **D8 ownership labels hardened** — `stacklok_component`/`stacklok_product` + are now reserved and cannot be overridden via `--otel-custom-attributes` or + `OTEL_RESOURCE_ATTRIBUTES` (see [D8 Ownership Labels](./observability.md#d8-ownership-labels)). + Any deployment previously setting a custom value for either key will see + that value silently replaced by the frozen ToolHive default. ### What Is New @@ -32,6 +52,11 @@ remain the same. |----------|-------------| | `mcp.server.operation.duration` metric | OTEL MCP spec histogram for server-side operation latency | | `mcp.client.operation.duration` metric | OTEL MCP spec histogram for vMCP-to-backend latency | +| `http.server.request.duration` metric | OTEL HTTP semconv histogram recorded for every request/response-cycle request, including those carrying no MCP method (session-terminate `DELETE`s). Total RPS is derivable from its `_count` series | +| `stacklok.toolhive.proxy.sse_connection.duration` metric | Duration of SSE connections, recorded once the connection closes. Separate from `http.server.request.duration` because SSE connections live for minutes to hours and would pin every observation to that histogram's 10s top bucket | +| `stacklok.build_info` metric | Build identity gauge: always observes 1, carrying `component`, `version`, and `commit` labels. Exported as `stacklok_build_info_ratio` (the `WithUnit("1")` → `_ratio` translation rule) | +| `stacklok.vmcp.mcp_server.health` metric | Live per-backend health gauge, emitting one point per `(mcp_server, state)` pair across all five health states. Semantically new — not a rename of the fire-once `toolhive_vmcp_backends_discovered` | +| `outcome` label vocabulary | `success`/`error`/`not_found` now splits counters that were previously separate metrics (workflow executions, optimizer `find_tool`/`call_tool`) | | MCP `_meta` trace context propagation | Extract/inject `traceparent`/`tracestate` from MCP `params._meta` | | MCP request parsing middleware | Dedicated middleware extracts method, resource ID, arguments, and `_meta` | | `--otel-custom-attributes` flag | Add custom resource attributes to all telemetry signals | @@ -43,10 +68,24 @@ remain the same. ## Backward Compatibility -### The `useLegacyAttributes` Flag +Span attributes and metrics follow different backward-compatibility policies — +the migration is not dual-emitted uniformly across both signal types: + +| Signal | Policy | +|--------|--------| +| Span (trace) attributes | Dual-emitted behind `useLegacyAttributes`, see below | +| Metric names and labels | Hard cutover, no legacy fallback — see [Metric Name and Label Mapping](#metric-name-and-label-mapping) | -To avoid breaking existing dashboards and alerts, ToolHive uses a **dual -emission** strategy: +Span attributes get a compatibility window because they are additive +key-value pairs on a span already being emitted — carrying both names costs +a few extra bytes per span, and trace tooling often has saved queries +hard-coded to the old attribute keys. Metrics don't get one: maintaining a +full parallel metric family (separate series, separate cardinality, separate +storage) is not free, and the RFC accepted the one-time break as cheaper +than the ongoing cost of running two metric vocabularies side by side (see +[Deleted Legacy Metrics](#deleted-legacy-metrics)). + +### The `useLegacyAttributes` Flag | Setting | Behavior | |---------|----------| @@ -178,15 +217,17 @@ When upgrading to this release, dual emission is enabled by default. Both old and new attribute names appear on spans. Your existing dashboards and alerts continue to work without changes. -### Step 2: Adopt New Metrics (Optional) +### Step 2: Update Dashboards and Alerts for Renamed/Deleted Metrics -Consider adopting the new spec-compliant metrics alongside your existing ones: +Update any PromQL, alert rule, or dashboard panel that references a legacy +metric or label name (see [Metric Name and Label Mapping](#metric-name-and-label-mapping) +and [Deleted Legacy Metrics](#deleted-legacy-metrics) below): ```promql -# Existing metric (unchanged) +# Before (deleted) rate(toolhive_mcp_requests_total{mcp_method="tools/call"}[5m]) -# New spec-compliant metric for operation duration +# After: OTEL MCP spec-compliant metric for operation duration histogram_quantile(0.95, rate(mcp_server_operation_duration_seconds_bucket{ mcp_method_name="tools/call" @@ -233,21 +274,82 @@ attributes. --- -## Metric Label Changes - -**Important**: The metric *label names* on existing `toolhive_mcp_*` and -`toolhive_vmcp_*` metrics have **not** changed. The `useLegacyAttributes` flag -only affects **span attributes** (trace data), not metric labels. +## Metric Name and Label Mapping + +**Important**: Unlike span attributes, metric name and label changes are +**not** gated by `useLegacyAttributes` — the rename is unconditional. A +dashboard or alert querying an old metric or label name must be updated +regardless of that flag's setting. + +The "New Metric/Label" column below gives the OTel instrument/attribute name +(dotted form, matching what appears in code and in OTLP export). **Query +against the "Prometheus Name" column instead** — that's what actually reaches +PromQL: dots become underscores, and Prometheus appends `_total` to counters +and `_seconds_bucket`/`_seconds_sum`/`_seconds_count` (or the instrument's +declared unit, e.g. `_percent`) to histograms. A value pasted from the "New +Metric/Label" column directly into PromQL returns zero results. + +| Legacy Metric/Label | New Metric/Label | Prometheus Name | Notes | +|----------------------|-------------------|------------------|-------| +| `server` (label, proxy + rate limit metrics) | `mcp_server` | `mcp_server` | | +| `mcp_method` (label, deleted `toolhive_mcp_*` metrics) | `mcp.method.name` | `mcp_method_name` | New attribute on `mcp.server.operation.duration`, not a same-metric label rename | +| `tool` (label, deleted `toolhive_mcp_tool_calls`) | `gen_ai.tool.name` | `gen_ai_tool_name` | New attribute on `mcp.server.operation.duration`; **not** `tool_name` — that label is used only by the unrelated vMCP optimizer `call_tool` metrics (see [vMCP Backend Client Attributes](#vmcp-backend-client-attributes)) | +| `workflow.name` (label, vMCP workflow metrics) | `composite_tool` | `composite_tool` | | +| `toolhive_mcp_active_connections` | `stacklok.toolhive.proxy.active_connections` | `stacklok_toolhive_proxy_active_connections` | Renamed, not deleted. No `_total` suffix — it's an UpDownCounter, which Prometheus exposes as a gauge | +| `toolhive_rate_limit_decisions` | `stacklok.toolhive.ratelimit.decisions` | `stacklok_toolhive_ratelimit_decisions_total` | Renamed, not deleted | +| `toolhive_rate_limit_redis_errors` | `stacklok.toolhive.ratelimit.redis_errors` | `stacklok_toolhive_ratelimit_redis_errors_total` | Renamed, not deleted | +| `toolhive_rate_limit_check_latency` | `stacklok.toolhive.ratelimit.check_latency` | `stacklok_toolhive_ratelimit_check_latency_seconds_bucket` / `_sum` / `_count` | Renamed, not deleted | +| `toolhive_vmcp_workflow_executions` | `stacklok.vmcp.composite_tool.executions` | `stacklok_vmcp_composite_tool_executions_total` | Now split by `outcome` label instead of a separate errors counter | +| `toolhive_vmcp_workflow_errors` | `stacklok.vmcp.composite_tool.executions` (filtered to `outcome="error"`) | `stacklok_vmcp_composite_tool_executions_total{outcome="error"}` | Merged into the executions counter above, not a standalone metric | +| `toolhive_vmcp_workflow_duration` | `stacklok.vmcp.composite_tool.duration` | `stacklok_vmcp_composite_tool_duration_seconds_bucket` / `_sum` / `_count` | | +| `toolhive_vmcp_backends_discovered` | `stacklok.vmcp.mcp_server.health` | `stacklok_vmcp_mcp_server_health` | Semantic change, not a plain rename: a live per-`(mcp_server, state)` health gauge, not a fire-once discovery count. No suffix — it's an ObservableGauge | +| `toolhive_vmcp_optimizer_find_tool_requests` / `_find_tool_errors` | `stacklok.vmcp.optimizer.find_tool.requests` | `stacklok_vmcp_optimizer_find_tool_requests_total` | Merged into one counter split by `outcome` label | +| `toolhive_vmcp_optimizer_find_tool_duration` | `stacklok.vmcp.optimizer.find_tool.duration` | `stacklok_vmcp_optimizer_find_tool_duration_seconds_bucket` / `_sum` / `_count` | | +| `toolhive_vmcp_optimizer_find_tool_results` | `stacklok.vmcp.optimizer.find_tool.results` | `stacklok_vmcp_optimizer_find_tool_results_bucket` / `_sum` / `_count` | Unit is `{tools}` (a count), not seconds — no `_seconds` infix | +| `toolhive_vmcp_optimizer_token_savings_percent` | `stacklok.vmcp.optimizer.token_savings` | `stacklok_vmcp_optimizer_token_savings_percent_bucket` / `_sum` / `_count` | Unit `%` becomes the `_percent` infix, which happens to match the old Prometheus name exactly | +| `toolhive_vmcp_optimizer_call_tool_requests` / `_call_tool_errors` / `_call_tool_not_found` | `stacklok.vmcp.optimizer.call_tool.requests` | `stacklok_vmcp_optimizer_call_tool_requests_total` | Merged into one counter split by `outcome` label (`success`, `error`, or `not_found`) | +| `toolhive_vmcp_optimizer_call_tool_duration` | `stacklok.vmcp.optimizer.call_tool.duration` | `stacklok_vmcp_optimizer_call_tool_duration_seconds_bucket` / `_sum` / `_count` | | +| `toolhive_vmcp_backend_revision_reclassifications` | `stacklok.vmcp.backend.revision_reclassifications` | `stacklok_vmcp_backend_revision_reclassifications_total` | Renamed, not deleted | The new `mcp.server.operation.duration` and `mcp.client.operation.duration` metrics use OTEL MCP semantic convention attribute names exclusively (e.g., -`mcp.method.name` instead of `mcp_method`). +`mcp.method.name` instead of `mcp_method`), and expose in PromQL as +`mcp_server_operation_duration_seconds_{bucket,sum,count}` and +`mcp_client_operation_duration_seconds_{bucket,sum,count}` respectively — +see the [Deleted Legacy Metrics](#deleted-legacy-metrics) table below for +their old→new mapping. + +### Deleted Legacy Metrics + +The following metrics duplicated an OTel-semconv equivalent and have been +deleted outright — there is no renamed successor to redirect a query to, +only the semconv metric that already covered the same signal: + +| Deleted Metric | Semconv Replacement | +|-----------------|----------------------| +| `toolhive_mcp_requests` | `http.server.request.duration` (total request count is derivable via `_count`; see note below) | +| `toolhive_mcp_request_duration` | `mcp.server.operation.duration` | +| `toolhive_mcp_tool_calls` | `mcp.server.operation.duration` filtered to `mcp.method.name="tools/call"` | +| `toolhive_vmcp_backend_requests` | `mcp.client.operation.duration` | +| `toolhive_vmcp_backend_errors` | `mcp.client.operation.duration` filtered to `error.type != ""` | +| `toolhive_vmcp_backend_requests_duration` | `mcp.client.operation.duration` | + +A dashboard or alert built on any of these six metrics has no direct +successor query — it must be rebuilt against the semconv histogram. + +For total HTTP request volume, use `http_server_request_duration_seconds_count` +alone — it is recorded for every request the middleware handles, including +GET (SSE-open) and DELETE (session-terminate) requests that carry no MCP +method. Do not also sum `mcp_server_operation_duration_seconds_count`: every +MCP-method-bearing request increments both metrics, so summing them +double-counts those requests. Use `mcp_server_operation_duration_seconds_count` +only for a per-`mcp_method_name` breakdown of the MCP-bearing subset. --- ## vMCP Backend Client Attributes -The vMCP backend client (`pkg/vmcp/server/telemetry.go`) emits both +The vMCP backend client (`pkg/vmcp/internal/backendtelemetry/backendtelemetry.go`) emits both ToolHive-specific and OTEL spec attributes on spans. These are always emitted regardless of `useLegacyAttributes` since they serve different purposes: @@ -262,9 +364,11 @@ regardless of `useLegacyAttributes` since they serve different purposes: | `resource_uri` | `mcp.resource.uri` | Resource URI (for `read_resource`) | | `prompt_name` | `gen_ai.prompt.name` | Prompt name (for `get_prompt`) | -The `mcp.client.operation.duration` metric uses only `mcp.method.name` and -`network.transport` as labels (plus `error.type` on error), following the OTEL -MCP semantic conventions. +The `mcp.client.operation.duration` metric uses `mcp.method.name`, +`network.transport`, and `mcp_server` (the backend workload name) as labels +(plus `error.type` on error), following the OTEL MCP semantic conventions. +`mcp_server` preserves the per-backend breakdown the deleted +`toolhive_vmcp_backend_requests_duration` twin had. --- diff --git a/examples/otel/README.md b/examples/otel/README.md index 4bcbda48a5..5c20916226 100644 --- a/examples/otel/README.md +++ b/examples/otel/README.md @@ -105,4 +105,20 @@ In the [grafana-dashboards](./grafana-dashboards/) folder are pre-built dashboar You can import these dashboards through: 1. Grafana UI: Configuration → Data Sources → Import 2. Automatic sidecar discovery (if enabled) -3. Grafana provisioning configuration \ No newline at end of file +3. Grafana provisioning configuration + +For option 2, `prometheus-stack-values.yaml` enables the Grafana sidecar to +auto-provision any ConfigMap labeled `grafana_dashboard=1` in the `monitoring` +namespace. Create one per dashboard file: + +```bash +for f in grafana-dashboards/*.json; do + name="dashboard-$(basename "$f" .json)" + kubectl create configmap "$name" --from-file="$f" -n monitoring + kubectl label configmap "$name" grafana_dashboard=1 -n monitoring +done +``` + +The sidecar watches only the `monitoring` namespace (`searchNamespace: +monitoring`) — widening this to `ALL` would require granting the sidecar's +ServiceAccount cluster-wide ConfigMap list/watch RBAC. \ No newline at end of file diff --git a/examples/otel/grafana-dashboards/toolhive-cli-mcp-grafana-dashboard-otel-scrape.json b/examples/otel/grafana-dashboards/toolhive-cli-mcp-grafana-dashboard-otel-scrape.json index 270cea3e8c..05d48bb05f 100644 --- a/examples/otel/grafana-dashboards/toolhive-cli-mcp-grafana-dashboard-otel-scrape.json +++ b/examples/otel/grafana-dashboards/toolhive-cli-mcp-grafana-dashboard-otel-scrape.json @@ -112,13 +112,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "rate(toolhive_mcp_request_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m])", - "legendFormat": "{{mcp_method}} - {{status}} ({{status_code}})", + "expr": "sum by (mcp_method_name) (rate(mcp_server_operation_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m]))", + "legendFormat": "{{mcp_method_name}}", "range": true, "refId": "A" } ], - "title": "HTTP Request Rate", + "title": "MCP Request Rate", "type": "timeseries" }, { @@ -212,8 +212,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.95, rate(toolhive_mcp_request_duration_seconds_bucket{exported_job=\"mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "95th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.95, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{exported_job=\"mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "95th percentile - {{mcp_method_name}}", "range": true, "refId": "A" }, @@ -223,8 +223,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.50, rate(toolhive_mcp_request_duration_seconds_bucket{exported_job=\"mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "50th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.50, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{exported_job=\"mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "50th percentile - {{mcp_method_name}}", "range": true, "refId": "B" } @@ -293,12 +293,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m]))", "legendFormat": "Total RPS", "range": true, "refId": "A" } ], + "description": "Counts every HTTP request the middleware handles (including SSE-open GETs and session-terminate DELETEs), not only MCP-method-bearing requests. This baseline shifted with the metrics-standardization migration; see the telemetry migration guide.", "title": "Total Request Rate", "type": "stat" }, @@ -367,7 +368,7 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{exported_job=\"mcp-fetch-server\",status!=\"success\"}[5m])) / sum(rate(toolhive_mcp_request_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{exported_job=\"mcp-fetch-server\",http_response_status_code=~\"[45]..\"}[5m])) / sum(rate(http_server_request_duration_seconds_count{exported_job=\"mcp-fetch-server\"}[5m]))", "legendFormat": "Error Rate", "range": true, "refId": "A" @@ -467,8 +468,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "toolhive_mcp_active_connections{exported_job=\"mcp-fetch-server\"}", - "legendFormat": "{{server}} ({{transport}})", + "expr": "stacklok_toolhive_proxy_active_connections{exported_job=\"mcp-fetch-server\"}", + "legendFormat": "{{mcp_server}} ({{transport}})", "range": true, "refId": "A" } @@ -497,4 +498,4 @@ "title": "ToolHive CLI MCP Server Dashboard - Scrape from Prometheus", "uid": "toolhive-cli-mcp-otel-scrape", "version": 1 -} \ No newline at end of file +} diff --git a/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-remotewrite.json b/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-remotewrite.json index 22434e835e..24ee8a713a 100644 --- a/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-remotewrite.json +++ b/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-remotewrite.json @@ -111,13 +111,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m])", - "legendFormat": "{{mcp_method}} - {{status}} ({{status_code}})", + "expr": "sum by (mcp_method_name) (rate(mcp_server_operation_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "legendFormat": "{{mcp_method_name}}", "range": true, "refId": "A" } ], - "title": "HTTP Request Rate", + "title": "MCP Request Rate", "type": "timeseries" }, { @@ -181,12 +181,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", "legendFormat": "Total RPS", "range": true, "refId": "A" } ], + "description": "Counts every HTTP request the middleware handles (including SSE-open GETs and session-terminate DELETEs), not only MCP-method-bearing requests. This baseline shifted with the metrics-standardization migration; see the telemetry migration guide.", "title": "Total Request Rate", "type": "stat" }, @@ -255,7 +256,7 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\",status!=\"success\"}[5m])) / sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\",http_response_status_code=~\"[45]..\"}[5m])) / sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", "legendFormat": "Error Rate", "range": true, "refId": "A" @@ -554,8 +555,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "toolhive_mcp_active_connections{job=\"toolhive-system/mcp-fetch-server\"}", - "legendFormat": "{{server}} ({{transport}})", + "expr": "stacklok_toolhive_proxy_active_connections{job=\"toolhive-system/mcp-fetch-server\"}", + "legendFormat": "{{mcp_server}} ({{transport}})", "range": true, "refId": "A" } @@ -653,8 +654,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.95, rate(toolhive_mcp_request_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "95th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.95, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "95th percentile - {{mcp_method_name}}", "range": true, "refId": "A" }, @@ -664,8 +665,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.50, rate(toolhive_mcp_request_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "50th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.50, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "50th percentile - {{mcp_method_name}}", "range": true, "refId": "B" } @@ -793,4 +794,4 @@ "title": "ToolHive MCP Server & Proxy Runner Dashboard - OTEL RemoteWrite to Prometheus (with kubestats)", "uid": "toolhive-mcp-otel-remotewrite", "version": 3 -} \ No newline at end of file +} diff --git a/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-scrape.json b/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-scrape.json index dbe5aa4e57..10e5fb916b 100644 --- a/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-scrape.json +++ b/examples/otel/grafana-dashboards/toolhive-mcp-grafana-dashboard-otel-scrape.json @@ -111,13 +111,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m])", - "legendFormat": "{{mcp_method}} - {{status}} ({{status_code}})", + "expr": "sum by (mcp_method_name) (rate(mcp_server_operation_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "legendFormat": "{{mcp_method_name}}", "range": true, "refId": "A" } ], - "title": "HTTP Request Rate", + "title": "MCP Request Rate", "type": "timeseries" }, { @@ -410,8 +410,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.95, rate(toolhive_mcp_request_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "95th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.95, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "95th percentile - {{mcp_method_name}}", "range": true, "refId": "A" }, @@ -421,8 +421,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "histogram_quantile(0.50, rate(toolhive_mcp_request_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m])) * 1000", - "legendFormat": "50th percentile - {{mcp_method}} - {{status}}", + "expr": "histogram_quantile(0.50, sum by (le, mcp_method_name) (rate(mcp_server_operation_duration_seconds_bucket{job=\"toolhive-system/mcp-fetch-server\"}[5m]))) * 1000", + "legendFormat": "50th percentile - {{mcp_method_name}}", "range": true, "refId": "B" } @@ -491,12 +491,13 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", "legendFormat": "Total RPS", "range": true, "refId": "A" } ], + "description": "Counts every HTTP request the middleware handles (including SSE-open GETs and session-terminate DELETEs), not only MCP-method-bearing requests. This baseline shifted with the metrics-standardization migration; see the telemetry migration guide.", "title": "Total Request Rate", "type": "stat" }, @@ -565,7 +566,7 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\",status!=\"success\"}[5m])) / sum(rate(toolhive_mcp_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\",http_response_status_code=~\"[45]..\"}[5m])) / sum(rate(http_server_request_duration_seconds_count{job=\"toolhive-system/mcp-fetch-server\"}[5m]))", "legendFormat": "Error Rate", "range": true, "refId": "A" @@ -664,8 +665,8 @@ "uid": "prometheus" }, "editorMode": "code", - "expr": "toolhive_mcp_active_connections{job=\"toolhive-system/mcp-fetch-server\"}", - "legendFormat": "{{server}} ({{transport}})", + "expr": "stacklok_toolhive_proxy_active_connections{job=\"toolhive-system/mcp-fetch-server\"}", + "legendFormat": "{{mcp_server}} ({{transport}})", "range": true, "refId": "A" } @@ -793,4 +794,4 @@ "title": "ToolHive MCP Server & Proxy Runner Dashboard - Scrape from OTEL (with kubestats)", "uid": "toolhive-mcp-otel-scrape", "version": 9 -} \ No newline at end of file +} diff --git a/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json b/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json index 95729d917c..9a88197f61 100644 --- a/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json +++ b/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json @@ -243,7 +243,7 @@ "uid": "${datasource}" }, "editorMode": "code", - "expr": "sum(rate(mcp_server_operation_duration_seconds_count{job=~\"$job\", error_type!=\"\"}[5m])) / sum(rate(mcp_server_operation_duration_seconds_count{job=~\"$job\"}[5m]))", + "expr": "sum(rate(http_server_request_duration_seconds_count{job=~\"$job\", http_response_status_code=~\"[45]..\"}[5m])) / sum(rate(http_server_request_duration_seconds_count{job=~\"$job\"}[5m]))", "legendFormat": "Error Rate", "range": true, "refId": "A" @@ -313,8 +313,8 @@ "uid": "${datasource}" }, "editorMode": "code", - "expr": "toolhive_mcp_active_connections{job=~\"$job\"}", - "legendFormat": "{{server}} ({{transport}})", + "expr": "stacklok_toolhive_proxy_active_connections{job=~\"$job\"}", + "legendFormat": "{{mcp_server}} ({{transport}})", "range": true, "refId": "A" } @@ -971,8 +971,8 @@ "uid": "${datasource}" }, "editorMode": "code", - "expr": "sum by (error_type) (rate(mcp_server_operation_duration_seconds_count{job=~\"$job\", error_type!=\"\"}[5m]))", - "legendFormat": "{{error_type}}", + "expr": "sum by (http_response_status_code) (rate(http_server_request_duration_seconds_count{job=~\"$job\", http_response_status_code=~\"[45]..\"}[5m]))", + "legendFormat": "{{http_response_status_code}}", "range": true, "refId": "A" } diff --git a/examples/otel/prometheus-stack-values.yaml b/examples/otel/prometheus-stack-values.yaml index 11e25405cc..949327da18 100644 --- a/examples/otel/prometheus-stack-values.yaml +++ b/examples/otel/prometheus-stack-values.yaml @@ -38,6 +38,18 @@ grafana: datasources: enabled: true defaultDatasourceEnabled: true + dashboards: + enabled: true + label: grafana_dashboard + labelValue: "1" + # folder is the in-pod path the sidecar writes discovered dashboards to + # before Grafana's provisioner picks them up — not a host path. + folder: /tmp/dashboards + # Scoped to this release's namespace (matches the `-n monitoring` install + # below) rather than "ALL", which would require the sidecar's + # ServiceAccount to have cluster-wide ConfigMap list/watch RBAC. See + # "Importing Dashboards" in README.md for the ConfigMap this depends on. + searchNamespace: monitoring # Additional data sources configuration additionalDataSources: diff --git a/pkg/mcp/parser.go b/pkg/mcp/parser.go index 1dabb9a732..e8b2eb987c 100644 --- a/pkg/mcp/parser.go +++ b/pkg/mcp/parser.go @@ -335,6 +335,21 @@ var staticResourceIDs = map[string]string{ "server/discover": "discover", } +// IsKnownMethod reports whether method is a recognized MCP method. It is the +// union of the methods the parser has handlers for and those with static +// resource IDs, so it covers parameterless methods like "ping" too. +// +// Telemetry uses this to bound label cardinality: the JSON-RPC method arrives +// verbatim from the request body, so recording it unvalidated lets a client +// mint one time series per distinct string. +func IsKnownMethod(method string) bool { + if _, exists := methodHandlers[method]; exists { + return true + } + _, exists := staticResourceIDs[method] + return exists +} + func extractResourceAndArguments(method string, params json.RawMessage) (string, map[string]interface{}, map[string]interface{}) { if params == nil { return getStaticResourceID(method), nil, nil diff --git a/pkg/mcp/parser_test.go b/pkg/mcp/parser_test.go index e6c157e303..18fa89f28f 100644 --- a/pkg/mcp/parser_test.go +++ b/pkg/mcp/parser_test.go @@ -2010,3 +2010,28 @@ func TestRepublishParsedMCPRequestHolder(t *testing.T) { require.NotNil(t, republished) }) } + +func TestIsKnownMethod(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + method string + want bool + }{ + {"handler-backed method", "tools/call", true}, + {"list method", "tools/list", true}, + {"static-resource method with no params", "ping", true}, + {"static notification", "notifications/tools/list_changed", true}, + {"unrecognized method", "evil/made-up-method", false}, + {"empty method", "", false}, + {"case mismatch is not a match", "Tools/Call", false}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + assert.Equal(t, tt.want, IsKnownMethod(tt.method)) + }) + } +} diff --git a/pkg/ratelimit/observability.go b/pkg/ratelimit/observability.go index 447ed64215..f70f1c067b 100644 --- a/pkg/ratelimit/observability.go +++ b/pkg/ratelimit/observability.go @@ -16,7 +16,7 @@ import ( "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/metric" - "github.com/stacklok/toolhive/pkg/telemetry" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" ) const ( @@ -58,7 +58,7 @@ func newRateLimitTelemetry( meter := meterProvider.Meter(rateLimitInstrumentationName) decisions, err := meter.Int64Counter( - "toolhive_rate_limit_decisions", + "stacklok.toolhive.ratelimit.decisions", metric.WithDescription("Total number of rate limit bucket decisions"), ) if err != nil { @@ -66,7 +66,7 @@ func newRateLimitTelemetry( } redisErrors, err := meter.Int64Counter( - "toolhive_rate_limit_redis_errors", + "stacklok.toolhive.ratelimit.redis_errors", metric.WithDescription("Total number of Redis errors during rate limit checks"), ) if err != nil { @@ -74,10 +74,10 @@ func newRateLimitTelemetry( } checkLatency, err := meter.Float64Histogram( - "toolhive_rate_limit_check_latency", + "stacklok.toolhive.ratelimit.check_latency", metric.WithDescription("Duration of Redis Lua rate limit checks in seconds"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) if err != nil { return nil, fmt.Errorf("create check latency histogram: %w", err) @@ -111,7 +111,7 @@ func (t *rateLimitTelemetry) recordRejected(ctx context.Context, check limitChec func (t *rateLimitTelemetry) recordDecision(ctx context.Context, decision string, check limitCheck) { t.decisions.Add(ctx, 1, metric.WithAttributes( attribute.String("namespace", t.namespace), - attribute.String("server", t.serverName), + attribute.String(coremetrics.LabelMCPServer, t.serverName), attribute.String("decision", decision), attribute.String("scope", check.scope), attribute.String("operation_type", check.operationType), @@ -124,8 +124,8 @@ func (t *rateLimitTelemetry) recordRedisError(ctx context.Context, err error) { } t.redisErrors.Add(ctx, 1, metric.WithAttributes( attribute.String("namespace", t.namespace), - attribute.String("server", t.serverName), - attribute.String("error_type", classifyRedisError(err)), + attribute.String(coremetrics.LabelMCPServer, t.serverName), + attribute.String(coremetrics.LabelErrorType, classifyRedisError(err)), )) } @@ -135,7 +135,7 @@ func (t *rateLimitTelemetry) recordCheckLatency(ctx context.Context, duration ti } t.checkLatency.Record(ctx, duration.Seconds(), metric.WithAttributes( attribute.String("namespace", t.namespace), - attribute.String("server", t.serverName), + attribute.String(coremetrics.LabelMCPServer, t.serverName), )) } diff --git a/pkg/ratelimit/observability_test.go b/pkg/ratelimit/observability_test.go index 8eb2ba58c8..e4e89f1fae 100644 --- a/pkg/ratelimit/observability_test.go +++ b/pkg/ratelimit/observability_test.go @@ -51,33 +51,33 @@ func TestRateLimitMetrics_SharedDecisionsAndLatency(t *testing.T) { require.False(t, second.Allowed) metrics := collectRateLimitMetrics(t, reader) - decisions := requireRateLimitMetric(t, metrics, "toolhive_rate_limit_decisions") + decisions := requireRateLimitMetric(t, metrics, "stacklok.toolhive.ratelimit.decisions") assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionAllowed, "scope": rateLimitScopeShared, "operation_type": rateLimitOperationServer, })) assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionAllowed, "scope": rateLimitScopeShared, "operation_type": rateLimitOperationTool, })) assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionRejected, "scope": rateLimitScopeShared, "operation_type": rateLimitOperationTool, })) - latency := requireRateLimitMetric(t, metrics, "toolhive_rate_limit_check_latency") + latency := requireRateLimitMetric(t, metrics, "stacklok.toolhive.ratelimit.check_latency") assert.Equal(t, uint64(2), histogramCountWithAttributes(t, latency, map[string]string{ - "namespace": "test-ns", - "server": "test-server", + "namespace": "test-ns", + "mcp_server": "test-server", })) } @@ -112,24 +112,24 @@ func TestRateLimitMetrics_PerUserDecisions(t *testing.T) { require.False(t, second.Allowed) metrics := collectRateLimitMetrics(t, reader) - decisions := requireRateLimitMetric(t, metrics, "toolhive_rate_limit_decisions") + decisions := requireRateLimitMetric(t, metrics, "stacklok.toolhive.ratelimit.decisions") assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionAllowed, "scope": rateLimitScopePerUser, "operation_type": rateLimitOperationServer, })) assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionAllowed, "scope": rateLimitScopePerUser, "operation_type": rateLimitOperationTool, })) assert.Equal(t, int64(1), counterValueWithAttributes(t, decisions, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "decision": rateLimitDecisionRejected, "scope": rateLimitScopePerUser, "operation_type": rateLimitOperationTool, @@ -154,19 +154,19 @@ func TestRateLimitMetrics_RedisErrorAndFailedLatency(t *testing.T) { require.Error(t, err) metrics := collectRateLimitMetrics(t, reader) - redisErrors := requireRateLimitMetric(t, metrics, "toolhive_rate_limit_redis_errors") + redisErrors := requireRateLimitMetric(t, metrics, "stacklok.toolhive.ratelimit.redis_errors") assert.Equal(t, int64(1), counterValueWithAttributes(t, redisErrors, map[string]string{ "namespace": "test-ns", - "server": "test-server", + "mcp_server": "test-server", "error_type": redisErrorTypeConnection, })) - latency := requireRateLimitMetric(t, metrics, "toolhive_rate_limit_check_latency") + latency := requireRateLimitMetric(t, metrics, "stacklok.toolhive.ratelimit.check_latency") assert.Equal(t, uint64(1), histogramCountWithAttributes(t, latency, map[string]string{ - "namespace": "test-ns", - "server": "test-server", + "namespace": "test-ns", + "mcp_server": "test-server", })) - assert.Nil(t, findRateLimitMetric(metrics, "toolhive_rate_limit_decisions")) + assert.Nil(t, findRateLimitMetric(metrics, "stacklok.toolhive.ratelimit.decisions")) } func TestRateLimitMetrics_NoApplicableBucketRecordsNothing(t *testing.T) { @@ -250,7 +250,7 @@ func TestClassifyRedisError(t *testing.T) { } } -func TestRateLimitMetricNamesUseToolHivePrefix(t *testing.T) { +func TestRateLimitMetricNamesUseStacklokPrefix(t *testing.T) { t.Parallel() reader, meterProvider := newRateLimitMeterProvider() @@ -267,7 +267,7 @@ func TestRateLimitMetricNamesUseToolHivePrefix(t *testing.T) { require.NotEmpty(t, metrics.ScopeMetrics) for _, scopeMetrics := range metrics.ScopeMetrics { for _, measured := range scopeMetrics.Metrics { - assert.True(t, strings.HasPrefix(measured.Name, "toolhive_"), measured.Name) + assert.True(t, strings.HasPrefix(measured.Name, "stacklok.toolhive.ratelimit."), measured.Name) } } } diff --git a/pkg/telemetry/buildinfo_test.go b/pkg/telemetry/buildinfo_test.go new file mode 100644 index 0000000000..be70a75fb5 --- /dev/null +++ b/pkg/telemetry/buildinfo_test.go @@ -0,0 +1,120 @@ +// SPDX-FileCopyrightText: Copyright 2025 Stacklok, Inc. +// SPDX-License-Identifier: Apache-2.0 + +package telemetry + +import ( + "context" + "net/http" + "net/http/httptest" + "regexp" + "testing" + + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/attribute" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/resource" + tracenoop "go.opentelemetry.io/otel/trace/noop" + + "github.com/stacklok/toolhive/pkg/telemetry/providers/prometheus" +) + +func TestBuildInfoAndConstLabelsAppear(t *testing.T) { + t.Parallel() + reader, handler, err := prometheus.NewReader(prometheus.Config{EnableMetricsPath: true}) + require.NoError(t, err) + + res, err := resource.New(context.Background(), resource.WithAttributes( + attribute.String("stacklok.component", "toolhive"), + attribute.String("stacklok.product", "stacklok-platform"), + )) + require.NoError(t, err) + + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader), sdkmetric.WithResource(res)) + + // Registered directly rather than through NewHTTPMiddleware: build_info is + // guarded by a process-wide sync.Once, so if any earlier test in this package + // constructed a middleware first, the guard is already spent and this + // provider would never see the gauge. + registerBuildInfoNow(mp.Meter(instrumentationName)) + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rw := httptest.NewRecorder() + handler.ServeHTTP(rw, req) + body := rw.Body.String() + + // Anchored at line start so the EXPORTED name is pinned, not merely present as + // a substring: RegisterBuildInfo sets WithUnit("1"), and the Prometheus + // translator appends _ratio to any gauge with unit "1", so a bare + // Contains("stacklok_build_info") is satisfied by stacklok_build_info_ratio and + // cannot detect the discrepancy. + require.Regexp(t, `(?m)^stacklok_build_info(_ratio)?\{`, body, + "build_info metric should be exported") + + // build_info always observes 1, so its labels are the entire point of the + // metric — a series with no version/commit carries no information. + require.Regexp(t, `(?m)^stacklok_build_info(_ratio)?\{[^}]*component="toolhive"`, body, + "build_info must identify the component") + require.Regexp(t, `(?m)^stacklok_build_info(_ratio)?\{[^}]*version="[^"]+"`, body, + "build_info must carry a non-empty version") + require.Regexp(t, `(?m)^stacklok_build_info(_ratio)?\{[^}]*commit="[^"]+"`, body, + "build_info must carry a non-empty commit") + + require.Contains(t, body, `stacklok_component="toolhive"`, "component const label should be promoted") + require.Contains(t, body, `stacklok_product="stacklok-platform"`, "product const label should be promoted") +} + +// TestRegisterBuildInfoIsOncePerProcess pins the guard that makes +// docs/observability.md's "registered once per process" claim true. build_info is +// process identity, and RegisterBuildInfo returns no handle to release its +// observable callback, so a second registration would permanently attach a +// duplicate callback observing the same attribute set. +func TestRegisterBuildInfoIsOncePerProcess(t *testing.T) { + t.Parallel() + + reader, handler, err := prometheus.NewReader(prometheus.Config{EnableMetricsPath: true}) + require.NoError(t, err) + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + // Two middlewares over the same provider: the second must not add a callback. + _ = NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), mp, "github", "stdio") + _ = NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), mp, "fetch", "stdio") + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rw := httptest.NewRecorder() + handler.ServeHTTP(rw, req) + + // Exactly one, not "at most one": LessOrEqual(…, 1) is satisfied by zero, so it + // passes both when the gauge is correctly deduped and when it is missing + // entirely — which is what a process-wide guard would do to this provider. + series := regexp.MustCompile(`(?m)^stacklok_build_info(_ratio)?\{`). + FindAllString(rw.Body.String(), -1) + require.Len(t, series, 1, + "build_info must be registered exactly once per MeterProvider, got %d series", len(series)) +} + +// TestRegisterBuildInfoIsPerProviderNotPerProcess pins the dedup key. A +// process-wide guard leaves the second provider's /metrics endpoint with no +// build_info at all, so any dashboard joining on it returns empty for that scrape +// target — an absence that produces no error and no series. +func TestRegisterBuildInfoIsPerProviderNotPerProcess(t *testing.T) { + t.Parallel() + + for _, name := range []string{"first", "second"} { + reader, handler, err := prometheus.NewReader(prometheus.Config{EnableMetricsPath: true}) + require.NoError(t, err) + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + _ = NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), mp, "github", "stdio") + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rw := httptest.NewRecorder() + handler.ServeHTTP(rw, req) + + series := regexp.MustCompile(`(?m)^stacklok_build_info(_ratio)?\{`). + FindAllString(rw.Body.String(), -1) + require.Len(t, series, 1, + "%s provider must export build_info exactly once; each provider owns its own "+ + "reader and /metrics endpoint, so registration cannot be process-wide", name) + } +} diff --git a/pkg/telemetry/integration_test.go b/pkg/telemetry/integration_test.go index 269ed2417d..96b2c422c2 100644 --- a/pkg/telemetry/integration_test.go +++ b/pkg/telemetry/integration_test.go @@ -27,8 +27,18 @@ import ( ) const ( - testToolName = "github_search" - metricRequestCounter = "toolhive_mcp_requests" + testToolName = "github_search" + + // metricHTTPServerDuration is the semconv HTTP server request-duration metric + // as rendered by the Prometheus exporter (dots to underscores, _seconds unit). + // It is recorded for every request the middleware handles regardless of MCP + // method and, with mcp.server.operation.duration, replaces the deleted + // toolhive_mcp_* request twins. + metricHTTPServerDuration = "http_server_request_duration_seconds" + + // metricActiveConnections is the renamed Stacklok-authored active-connections + // gauge as rendered by the Prometheus exporter. + metricActiveConnections = "stacklok_toolhive_proxy_active_connections" ) func TestTelemetryIntegration_EndToEnd(t *testing.T) { @@ -126,23 +136,22 @@ func TestTelemetryIntegration_EndToEnd(t *testing.T) { }, } + // Served inline rather than as parallel subtests: the scrape below asserts on + // the metrics these requests produce, and parallel subtests would not run + // until after this function returns, leaving nothing to find. for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - t.Parallel() - - var req *http.Request - if tc.body != "" { - req = httptest.NewRequest(tc.method, tc.path, strings.NewReader(tc.body)) - req.Header.Set("Content-Type", "application/json") - } else { - req = httptest.NewRequest(tc.method, tc.path, nil) - } + var req *http.Request + if tc.body != "" { + req = httptest.NewRequest(tc.method, tc.path, strings.NewReader(tc.body)) + req.Header.Set("Content-Type", "application/json") + } else { + req = httptest.NewRequest(tc.method, tc.path, nil) + } - rec := httptest.NewRecorder() - wrappedHandler.ServeHTTP(rec, req) + rec := httptest.NewRecorder() + wrappedHandler.ServeHTTP(rec, req) - assert.Equal(t, tc.expectedStatus, rec.Code) - }) + assert.Equal(t, tc.expectedStatus, rec.Code, "case %q", tc.name) } // Verify Prometheus handler is available @@ -160,12 +169,18 @@ func TestTelemetryIntegration_EndToEnd(t *testing.T) { // At minimum, we should have some metrics assert.True(t, len(metricsBody) > 0, "Metrics should not be empty") - // If we have custom metrics, verify them - if strings.Contains(metricsBody, "toolhive_mcp") { - assert.Contains(t, metricsBody, "toolhive_mcp_requests") - assert.Contains(t, metricsBody, "toolhive_mcp_request_duration") - assert.Contains(t, metricsBody, "toolhive_mcp_active_connections") - } + // The deleted legacy twins must never reappear. + assert.NotContains(t, metricsBody, "toolhive_mcp_requests") + assert.NotContains(t, metricsBody, "toolhive_mcp_request_duration") + assert.NotContains(t, metricsBody, "toolhive_mcp_tool_calls") + + // The renamed active-connections gauge and the semconv HTTP duration must + // be present (both are recorded for every handled request). Asserted + // unconditionally: the test already drove a real request through the + // middleware, so both series must exist. Guarding on a prefix of + // metricActiveConnections would make these assertions unable to fail. + assert.Contains(t, metricsBody, metricActiveConnections) + assert.Contains(t, metricsBody, metricHTTPServerDuration) } else { // If metrics endpoint fails, just log it but don't fail the test t.Logf("Metrics endpoint returned status %d, body: %s", metricsRec.Code, metricsRec.Body.String()) @@ -275,48 +290,53 @@ func TestTelemetryIntegration_WithRealProviders(t *testing.T) { // Check that metrics were recorded assert.NotEmpty(t, rm.ScopeMetrics) - var foundRequestCounter, foundDurationHistogram, foundActiveConnections bool + var foundOperationDuration, foundHTTPDuration, foundActiveConnections bool for _, sm := range rm.ScopeMetrics { for _, metric := range sm.Metrics { + // The deleted legacy twins must never be recorded. + assert.NotEqual(t, "toolhive_mcp_requests", metric.Name) + assert.NotEqual(t, "toolhive_mcp_request_duration", metric.Name) + assert.NotEqual(t, "toolhive_mcp_tool_calls", metric.Name) + switch metric.Name { - case metricRequestCounter: - foundRequestCounter = true - // Verify metric has expected attributes - if sum, ok := metric.Data.(metricdata.Sum[int64]); ok { - assert.NotEmpty(t, sum.DataPoints) - for _, dp := range sum.DataPoints { - // Check for expected attributes - attrSet := dp.Attributes - hasServer := false + case "mcp.server.operation.duration": + foundOperationDuration = true + // The semconv operation-duration metric carries the spec method + // and gen_ai tool-name keys for a tools/call, and never the + // unbounded mcp_resource_id. + if hist, ok := metric.Data.(metricdata.Histogram[float64]); ok { + assert.NotEmpty(t, hist.DataPoints) + for _, dp := range hist.DataPoints { hasMethod := false + hasToolName := false hasResourceID := false - for _, attr := range attrSet.ToSlice() { - if attr.Key == "server" && attr.Value.AsString() == "github" { - hasServer = true - } - if attr.Key == "mcp_method" && attr.Value.AsString() == "tools/call" { + for _, attr := range dp.Attributes.ToSlice() { + if attr.Key == "mcp.method.name" && attr.Value.AsString() == "tools/call" { hasMethod = true } - if attr.Key == "mcp_resource_id" && attr.Value.AsString() == testToolName { + if attr.Key == "gen_ai.tool.name" && attr.Value.AsString() == testToolName { + hasToolName = true + } + if attr.Key == "mcp_resource_id" { hasResourceID = true } } - assert.True(t, hasServer, "Request counter should have server attribute") - assert.True(t, hasMethod, "Request counter should have mcp_method attribute") - assert.True(t, hasResourceID, "Request counter should have mcp_resource_id attribute with tool name") + assert.True(t, hasMethod, "operation duration should carry mcp.method.name") + assert.True(t, hasToolName, "operation duration should carry gen_ai.tool.name for tools/call") + assert.False(t, hasResourceID, "operation duration must not carry mcp_resource_id (cardinality)") } } - case "toolhive_mcp_request_duration": - foundDurationHistogram = true - case "toolhive_mcp_active_connections": + case "http.server.request.duration": + foundHTTPDuration = true + case "stacklok.toolhive.proxy.active_connections": foundActiveConnections = true } } } - assert.True(t, foundRequestCounter, "Request counter metric should be present") - assert.True(t, foundDurationHistogram, "Duration histogram metric should be present") - assert.True(t, foundActiveConnections, "Active connections metric should be present") + assert.True(t, foundOperationDuration, "semconv operation-duration metric should be present") + assert.True(t, foundHTTPDuration, "semconv http server request-duration metric should be present") + assert.True(t, foundActiveConnections, "renamed active connections metric should be present") // Clean up err = tracerProvider.Shutdown(ctx) @@ -365,16 +385,12 @@ func TestTelemetryIntegration_ErrorHandling(t *testing.T) { prometheusHandler.ServeHTTP(metricsRec, metricsReq) metricsBody := metricsRec.Body.String() - // Check if metrics contain error indicators - the exact format may vary - hasErrorMetrics := strings.Contains(metricsBody, `status="error"`) || - strings.Contains(metricsBody, `status_code="500"`) || - strings.Contains(metricsBody, "500") || - strings.Contains(metricsBody, "error") - - // If we have custom metrics, they should include error status - if strings.Contains(metricsBody, "toolhive_mcp") { - assert.True(t, hasErrorMetrics, "Expected error metrics to be present") - } + + // The 500 is captured on the semconv HTTP duration metric via the + // http_response_status_code and error_type labels (error.type set on 5xx). + assert.Contains(t, metricsBody, metricHTTPServerDuration) + assert.Contains(t, metricsBody, `http_response_status_code="500"`) + assert.Contains(t, metricsBody, `error_type="500"`) } func TestTelemetryIntegration_ToolSpecificMetrics(t *testing.T) { @@ -425,53 +441,41 @@ func TestTelemetryIntegration_ToolSpecificMetrics(t *testing.T) { err := metricsReader.Collect(context.Background(), &rm) require.NoError(t, err) - // Look for tool-specific counter and general request counter - var foundToolCounter, foundRequestCounter bool + // The deleted toolhive_mcp_tool_calls twin is replaced by the semconv + // operation-duration metric scoped to mcp.method.name="tools/call", which + // carries the tool identity as gen_ai.tool.name. + var foundOperationDuration bool for _, sm := range rm.ScopeMetrics { for _, metric := range sm.Metrics { - switch metric.Name { - case "toolhive_mcp_tool_calls": - foundToolCounter = true - if sum, ok := metric.Data.(metricdata.Sum[int64]); ok { - assert.NotEmpty(t, sum.DataPoints) - for _, dp := range sum.DataPoints { - // Verify tool-specific attributes - attrSet := dp.Attributes - hasServer := false - hasTool := false - for _, attr := range attrSet.ToSlice() { - if attr.Key == "server" && attr.Value.AsString() == "github" { - hasServer = true - } - if attr.Key == "tool" && attr.Value.AsString() == testToolName { - hasTool = true - } + assert.NotEqual(t, "toolhive_mcp_tool_calls", metric.Name, + "the deleted tool-calls twin must not be recorded") + assert.NotEqual(t, "toolhive_mcp_requests", metric.Name) + + if metric.Name != "mcp.server.operation.duration" { + continue + } + foundOperationDuration = true + if hist, ok := metric.Data.(metricdata.Histogram[float64]); ok { + assert.NotEmpty(t, hist.DataPoints) + for _, dp := range hist.DataPoints { + hasMethod := false + hasToolName := false + for _, attr := range dp.Attributes.ToSlice() { + if attr.Key == "mcp.method.name" && attr.Value.AsString() == "tools/call" { + hasMethod = true } - assert.True(t, hasServer, "Tool counter should have server attribute") - assert.True(t, hasTool, "Tool counter should have tool attribute") - } - } - case metricRequestCounter: - foundRequestCounter = true - if sum, ok := metric.Data.(metricdata.Sum[int64]); ok { - assert.NotEmpty(t, sum.DataPoints) - for _, dp := range sum.DataPoints { - attrSet := dp.Attributes - hasResourceID := false - for _, attr := range attrSet.ToSlice() { - if attr.Key == "mcp_resource_id" && attr.Value.AsString() == testToolName { - hasResourceID = true - } + if attr.Key == "gen_ai.tool.name" && attr.Value.AsString() == testToolName { + hasToolName = true } - assert.True(t, hasResourceID, "Request counter should have mcp_resource_id attribute with tool name") } + assert.True(t, hasMethod, "operation duration should carry mcp.method.name=tools/call") + assert.True(t, hasToolName, "operation duration should carry gen_ai.tool.name") } } } } - assert.True(t, foundToolCounter, "Tool-specific counter should be recorded for tools/call") - assert.True(t, foundRequestCounter, "General request counter should be recorded") + assert.True(t, foundOperationDuration, "operation-duration metric should be recorded for tools/call") // Clean up err = meterProvider.Shutdown(ctx) @@ -520,10 +524,13 @@ func TestTelemetryIntegration_MultipleRequests(t *testing.T) { metricsBody := metricsRec.Body.String() - // The exact count format depends on Prometheus exposition format - // We just verify the metrics are present and contain our server name - assert.Contains(t, metricsBody, "toolhive_mcp_requests") - assert.Contains(t, metricsBody, `server="multi-test"`) + // These POSTs carry no parsed MCP request, so no mcp.server.operation.duration + // is recorded; the transport-level http.server.request.duration is, and the + // renamed active-connections gauge carries the server identity. + assert.NotContains(t, metricsBody, "toolhive_mcp_requests") + assert.Contains(t, metricsBody, metricHTTPServerDuration) + assert.Contains(t, metricsBody, metricActiveConnections) + assert.Contains(t, metricsBody, `mcp_server="multi-test"`) } func TestTelemetryIntegration_MetaTraceContextExtraction(t *testing.T) { //nolint:paralleltest // Mutates global OTEL propagator diff --git a/pkg/telemetry/middleware.go b/pkg/telemetry/middleware.go index e155212556..f1ca600d31 100644 --- a/pkg/telemetry/middleware.go +++ b/pkg/telemetry/middleware.go @@ -13,19 +13,23 @@ import ( "os" "strconv" "strings" + "sync" "time" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/metric" + "go.opentelemetry.io/otel/metric/noop" "go.opentelemetry.io/otel/propagation" "go.opentelemetry.io/otel/trace" "github.com/stacklok/toolhive-core/mcpcompat/mcp" - "github.com/stacklok/toolhive-core/telemetry/metrics" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" mcpparser "github.com/stacklok/toolhive/pkg/mcp" + "github.com/stacklok/toolhive/pkg/telemetry/providers" "github.com/stacklok/toolhive/pkg/transport/types" + "github.com/stacklok/toolhive/pkg/versions" ) const ( @@ -33,17 +37,16 @@ const ( instrumentationName = "github.com/stacklok/toolhive/pkg/telemetry" // methodPromptsGet is the MCP method name for prompts/get methodPromptsGet = "prompts/get" + // attrValueOther is the OTEL semconv sentinel for a value outside the + // known set. Used to bound the cardinality of metric attributes whose + // raw value comes from the client. + attrValueOther = "_OTHER" // networkTransportTCP is the OTEL value for TCP transport networkTransportTCP = "tcp" // networkProtocolHTTP is the OTEL value for HTTP protocol networkProtocolHTTP = "http" ) -// MCPHistogramBuckets are the bucket boundaries defined by the MCP OTEL semantic conventions -// for MCP server histograms (e.g. mcp.server.operation.duration). -// See https://github.com/open-telemetry/semantic-conventions/blob/main/docs/gen-ai/mcp.md -var MCPHistogramBuckets = metrics.BucketsMCPSemconv() - // HTTPMiddleware provides OpenTelemetry instrumentation for HTTP requests. type HTTPMiddleware struct { config Config @@ -55,11 +58,10 @@ type HTTPMiddleware struct { transport string // Metrics - requestCounter metric.Int64Counter - requestDuration metric.Float64Histogram - operationDuration metric.Float64Histogram - activeConnections metric.Int64UpDownCounter - toolCallCounter metric.Int64Counter + operationDuration metric.Float64Histogram + httpServerReqDuration metric.Float64Histogram + sseConnectionDuration metric.Float64Histogram + activeConnections metric.Int64UpDownCounter } // NewHTTPMiddleware creates a new HTTP middleware for OpenTelemetry instrumentation. @@ -73,69 +75,125 @@ func NewHTTPMiddleware( ) types.MiddlewareFunction { meter := meterProvider.Meter(instrumentationName) - // Initialize metrics - requestCounter, err := meter.Int64Counter( - "toolhive_mcp_requests", // The exporter adds the _total suffix automatically - metric.WithDescription("Total number of MCP requests"), - ) - if err != nil { - slog.Debug("failed to create request counter metric", "error", err) - } - - requestDuration, err := meter.Float64Histogram( - "toolhive_mcp_request_duration", // The exporter adds the _seconds suffix automatically - metric.WithDescription("Duration of MCP requests in seconds"), - metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(MCPHistogramBuckets...), - ) - if err != nil { - slog.Debug("failed to create request duration metric", "error", err) - } - activeConnections, err := meter.Int64UpDownCounter( - "toolhive_mcp_active_connections", + "stacklok.toolhive.proxy.active_connections", metric.WithDescription("Number of active MCP connections"), ) if err != nil { slog.Debug("failed to create active connections metric", "error", err) + activeConnections = noop.Int64UpDownCounter{} } + // Semconv-named metric, so it carries the semconv bucket set exactly rather + // than the coarser Stacklok proxy preset. operationDuration, err := meter.Float64Histogram( "mcp.server.operation.duration", metric.WithDescription("Duration of MCP server operations"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPSemconv()...), ) if err != nil { slog.Debug("failed to create operation duration metric", "error", err) + operationDuration = noop.Float64Histogram{} + } + + // OTEL HTTP semantic-convention metric. Name kept verbatim (no stacklok_ + // prefix) so OTel-aware tooling recognizes it. Recorded for every + // request/response-cycle request the middleware handles, including + // session-delete DELETEs that carry no MCP method — restoring + // transport-level coverage that the MCP-scoped operation-duration metric + // misses. SSE-open GETs are excluded: they block for the connection's + // full lifetime (minutes to hours), which would pin every observation to + // this histogram's 10s top bucket. Those go to sseConnectionDuration + // instead, below. + httpServerReqDuration, err := meter.Float64Histogram( + "http.server.request.duration", + metric.WithDescription("Duration of HTTP server requests"), + metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsFastHTTP()...), + ) + if err != nil { + slog.Debug("failed to create http server request duration metric", "error", err) + httpServerReqDuration = noop.Float64Histogram{} } - toolCallCounter, err := meter.Int64Counter( - "toolhive_mcp_tool_calls", - metric.WithDescription("Total number of MCP tool calls"), + // SSE connections live for minutes to hours, not milliseconds, so they get + // their own histogram on BucketsMCPProxy() (tops out at 300s) instead of + // sharing http.server.request.duration's 10s-capped buckets. + sseConnectionDuration, err := meter.Float64Histogram( + "stacklok.toolhive.proxy.sse_connection.duration", + metric.WithDescription("Duration of SSE connections, recorded once the connection closes"), + metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) if err != nil { - slog.Debug("failed to create tool call counter metric", "error", err) + slog.Debug("failed to create sse connection duration metric", "error", err) + sseConnectionDuration = noop.Float64Histogram{} } + registerBuildInfo(meterProvider, meter) + middleware := &HTTPMiddleware{ - config: config, - tracerProvider: tracerProvider, - tracer: tracerProvider.Tracer(instrumentationName), - meterProvider: meterProvider, - meter: meter, - serverName: serverName, - transport: transport, - requestCounter: requestCounter, - requestDuration: requestDuration, - operationDuration: operationDuration, - activeConnections: activeConnections, - toolCallCounter: toolCallCounter, + config: config, + tracerProvider: tracerProvider, + tracer: tracerProvider.Tracer(instrumentationName), + meterProvider: meterProvider, + meter: meter, + serverName: serverName, + transport: transport, + operationDuration: operationDuration, + httpServerReqDuration: httpServerReqDuration, + sseConnectionDuration: sseConnectionDuration, + activeConnections: activeConnections, } return middleware.Handler } +// buildInfoProviders tracks the MeterProviders build_info has been registered on. +// +// The dedup key is the provider, not the process. RegisterBuildInfo attaches an +// observable callback while returning no handle to release it, so registering +// twice on one provider permanently duplicates a callback observing the same +// attribute set. But each provider owns its own reader and /metrics endpoint, so a +// process-wide guard would leave every provider after the first exporting no +// build_info at all — and absence is the harder failure to notice, since a fleet +// dashboard joining on build_info just returns empty for that scrape target. +// NewHTTPMiddleware is reachable from the public Provider.Middleware() and from +// CreateMiddleware, which builds a fresh provider per call, so both cases are real. +// +// The durable fix is to register during provider assembly in +// pkg/telemetry/providers, where ComponentName and the resource already live; +// this keeps the guard correct until then. +var buildInfoProviders = struct { + mu sync.Mutex + seen map[metric.MeterProvider]struct{} +}{seen: make(map[metric.MeterProvider]struct{})} + +// registerBuildInfo registers the stacklok.build_info gauge via the shared +// toolhive-core helper, stamping this component's identity (toolhive) plus the +// build version/commit. Registers at most once per MeterProvider. +func registerBuildInfo(meterProvider metric.MeterProvider, meter metric.Meter) { + buildInfoProviders.mu.Lock() + defer buildInfoProviders.mu.Unlock() + if _, done := buildInfoProviders.seen[meterProvider]; done { + return + } + buildInfoProviders.seen[meterProvider] = struct{}{} + registerBuildInfoNow(meter) +} + +// registerBuildInfoNow performs the registration unconditionally, bypassing the +// per-provider guard. Exists so a test asserting on build_info can register +// against its own meter provider regardless of what earlier tests in the same +// process already registered. +func registerBuildInfoNow(meter metric.Meter) { + info := versions.GetVersionInfo() + if err := coremetrics.RegisterBuildInfo(meter, providers.ComponentName, info.Version, info.Commit); err != nil { + slog.Debug("failed to register build info", "error", err) + } +} + // Handler implements the middleware function that wraps HTTP handlers. // This middleware should be placed after the MCP parsing middleware in the chain // to leverage the parsed MCP data. @@ -152,15 +210,25 @@ func (m *HTTPMiddleware) Handler(next http.Handler) http.Handler { // Track active SSE connections with defer to ensure decrement on close sseAttrs := metric.WithAttributes( - attribute.String("server", m.serverName), - attribute.String("transport", m.transport), + attribute.String(coremetrics.LabelMCPServer, m.serverName), + attribute.String(coremetrics.LabelTransport, m.transport), attribute.String("connection_type", "sse"), ) m.activeConnections.Add(ctx, 1, sseAttrs) defer m.activeConnections.Add(ctx, -1, sseAttrs) - // Pass through to SSE handler - blocks for the lifetime of the SSE connection - next.ServeHTTP(w, r) + // Pass through to SSE handler - blocks for the lifetime of the SSE + // connection. Record its duration on close, into sseConnectionDuration + // rather than http.server.request.duration — see the comment on that + // histogram's construction above for why the two are kept separate. + sseStart := time.Now() + rw := &responseWriter{ResponseWriter: w, statusCode: http.StatusOK} + defer func() { + m.sseConnectionDuration.Record(ctx, time.Since(sseStart).Seconds(), metric.WithAttributes( + attribute.String(coremetrics.LabelMCPServer, m.serverName), + )) + }() + next.ServeHTTP(rw, r) return } @@ -179,12 +247,12 @@ func (m *HTTPMiddleware) Handler(next http.Handler) http.Handler { // Increment active connections m.activeConnections.Add(ctx, 1, metric.WithAttributes( - attribute.String("server", m.serverName), - attribute.String("transport", m.transport), + attribute.String(coremetrics.LabelMCPServer, m.serverName), + attribute.String(coremetrics.LabelTransport, m.transport), )) defer m.activeConnections.Add(ctx, -1, metric.WithAttributes( - attribute.String("server", m.serverName), - attribute.String("transport", m.transport), + attribute.String(coremetrics.LabelMCPServer, m.serverName), + attribute.String(coremetrics.LabelTransport, m.transport), )) // Create span name based on MCP method if available, otherwise use HTTP method + path @@ -675,36 +743,22 @@ func (m *HTTPMiddleware) recordMetrics(ctx context.Context, r *http.Request, rw mcpMethod = "unknown" } - // Determine status (success/error) - status := "success" - if rw.statusCode >= 400 { - status = "error" - } - // Get the resource ID from the parsed MCP request if available. // For tools/call this is the tool name, for resources/read the URI, - // and for prompts/get the prompt name. + // and for prompts/get the prompt name. It feeds gen_ai.tool.name on the + // semconv operation-duration metric; it is deliberately kept off the + // custom request metrics to bound cardinality. mcpResourceID := "" if parsedMCP := mcpparser.GetParsedMCPRequest(ctx); parsedMCP != nil { mcpResourceID = parsedMCP.ResourceID } - // Common attributes for all metrics - attrs := metric.WithAttributes( - attribute.String("method", r.Method), - attribute.String("status_code", strconv.Itoa(rw.statusCode)), - attribute.String("status", status), - attribute.String("mcp_method", mcpMethod), - attribute.String("mcp_resource_id", mcpResourceID), - attribute.String("server", m.serverName), - attribute.String("transport", m.transport), - ) - - // Record request count - m.requestCounter.Add(ctx, 1, attrs) - - // Record request duration - m.requestDuration.Record(ctx, duration.Seconds(), attrs) + // Record OTEL HTTP semconv duration for every request/response-cycle + // request, regardless of MCP method. This is the transport-level + // counterpart that stays valid for DELETE (session terminate) requests + // carrying no MCP method. SSE-open GETs never reach recordMetrics — they + // return early in Handler and record into sseConnectionDuration instead. + m.recordHTTPServerDuration(ctx, r, rw.statusCode, duration) // Record OTEL MCP spec mcp.server.operation.duration for actual MCP requests. // Only POST requests carry a JSON-RPC body; GET (SSE stream open) and DELETE @@ -718,18 +772,68 @@ func (m *HTTPMiddleware) recordMetrics(ctx context.Context, r *http.Request, rw slog.Warn("mcp method could not be determined, middleware may be misconfigured", "http_method", r.Method, "path", r.URL.Path) } +} - // For tools/call, record tool-specific metrics - if mcpMethod == string(mcp.MethodToolsCall) { - if parsedMCP := mcpparser.GetParsedMCPRequest(ctx); parsedMCP != nil && parsedMCP.ResourceID != "" { - toolAttrs := metric.WithAttributes( - attribute.String("server", m.serverName), - attribute.String("tool", parsedMCP.ResourceID), - attribute.String("status", status), - ) - m.toolCallCounter.Add(ctx, 1, toolAttrs) - } +// recordHTTPServerDuration records the http.server.request.duration OTEL HTTP +// semantic-convention metric. It carries the semconv attribute keys +// (http.request.method, url.scheme, http.response.status_code, error.type set +// only on failure) plus mcp_server, so a single Prometheus instance scraping +// several proxies can still split this metric per backend without a join — the +// deleted toolhive_mcp_requests/_request_duration twins this metric replaces +// both carried an equivalent server label. +func (m *HTTPMiddleware) recordHTTPServerDuration( + ctx context.Context, r *http.Request, statusCode int, duration time.Duration, +) { + specAttrs := []attribute.KeyValue{ + attribute.String("http.request.method", normalizeHTTPMethod(r.Method)), + attribute.String("url.scheme", requestScheme(r)), + attribute.Int("http.response.status_code", statusCode), + attribute.String(coremetrics.LabelMCPServer, m.serverName), + } + if pv := httpProtocolVersion(r); pv != "" { + specAttrs = append(specAttrs, attribute.String("network.protocol.version", pv)) } + if statusCode >= 500 { + specAttrs = append(specAttrs, attribute.String("error.type", strconv.Itoa(statusCode))) + } + m.httpServerReqDuration.Record(ctx, duration.Seconds(), metric.WithAttributes(specAttrs...)) +} + +// knownHTTPMethods is the set semconv treats as recording-safe for +// http.request.method. Anything else must be recorded as attrValueOther. +var knownHTTPMethods = map[string]struct{}{ + http.MethodGet: {}, http.MethodHead: {}, http.MethodPost: {}, + http.MethodPut: {}, http.MethodPatch: {}, http.MethodDelete: {}, + http.MethodConnect: {}, http.MethodOptions: {}, http.MethodTrace: {}, +} + +// normalizeHTTPMethod bounds http.request.method's cardinality. Go's net/http +// accepts any RFC 7230 token as a method, so an unauthenticated caller can +// otherwise mint a permanently-retained series per distinct method string. +// Semconv mandates recording unrecognized methods as _OTHER. +// +// The raw value is not lost: the span keeps it under http.request.method (spans +// are not a cardinality surface). Semconv would have the span carry it as +// http.request.method_original alongside an _OTHER http.request.method; that +// rename is deferred with the rest of the span-attribute work (RFC D9). +func normalizeHTTPMethod(method string) string { + if _, ok := knownHTTPMethods[method]; ok { + return method + } + return attrValueOther +} + +// requestScheme reports the URL scheme for url.scheme, which semconv marks +// Required on http.server.request.duration. Server-side request URLs are +// typically scheme-less, so fall back to the TLS state. +func requestScheme(r *http.Request) string { + if r.URL != nil && r.URL.Scheme != "" { + return r.URL.Scheme + } + if r.TLS != nil { + return "https" + } + return "http" } // recordOperationDuration records the mcp.server.operation.duration metric @@ -739,10 +843,17 @@ func (m *HTTPMiddleware) recordOperationDuration( ) { networkTransport, protocolName, _ := mapTransport(m.transport) + // mcp.method.name arrives verbatim from the JSON-RPC body, so it is bounded + // against the parser's own method set; the raw value stays on the span. + if !mcpparser.IsKnownMethod(mcpMethod) { + mcpMethod = attrValueOther + } + specAttrs := []attribute.KeyValue{ attribute.String("mcp.method.name", mcpMethod), attribute.String("jsonrpc.protocol.version", "2.0"), attribute.String("network.transport", networkTransport), + attribute.String(coremetrics.LabelMCPServer, m.serverName), } if protocolName != "" { specAttrs = append(specAttrs, attribute.String("network.protocol.name", protocolName)) @@ -760,7 +871,12 @@ func (m *HTTPMiddleware) recordOperationDuration( specAttrs = append(specAttrs, attribute.String("error.type", strconv.Itoa(statusCode))) } - // Method-specific attributes + // Method-specific attributes. + // + // NOTE: gen_ai.tool.name and gen_ai.prompt.name derive from params.name in + // the client's JSON-RPC body and are NOT bounded against a resolved + // capability set, so their cardinality is client-controlled. Bounding them + // is tracked separately; the proxy has no tool list in scope here. switch mcpMethod { case string(mcp.MethodToolsCall): specAttrs = append(specAttrs, attribute.String("gen_ai.operation.name", "execute_tool")) @@ -810,19 +926,6 @@ func (m *HTTPMiddleware) recordSSEConnection(ctx context.Context, r *http.Reques // End the span immediately since this is just the connection establishment span.SetStatus(codes.Ok, "SSE connection established") span.End() - - // Record SSE connection metrics - attrs := metric.WithAttributes( - attribute.String("method", r.Method), - attribute.String("status_code", "200"), // SSE connections start with 200 - attribute.String("status", "success"), - attribute.String("mcp_method", "sse_connection"), - attribute.String("server", m.serverName), - attribute.String("transport", m.transport), - ) - - // Record the connection establishment - m.requestCounter.Add(ctx, 1, attrs) } // Factory middleware type constant diff --git a/pkg/telemetry/middleware_sse_test.go b/pkg/telemetry/middleware_sse_test.go index 3cae3a804f..a6860de52b 100644 --- a/pkg/telemetry/middleware_sse_test.go +++ b/pkg/telemetry/middleware_sse_test.go @@ -120,13 +120,8 @@ func TestHTTPMiddleware_RecordSSEConnection(t *testing.T) { // We need to create the middleware manually to access the method meter := meterProvider.Meter(instrumentationName) - requestCounter, _ := meter.Int64Counter( - "toolhive_mcp_requests", - metric.WithDescription("Total number of MCP requests"), - ) - activeConnections, _ := meter.Int64UpDownCounter( - "toolhive_mcp_active_connections", + "stacklok.toolhive.proxy.active_connections", metric.WithDescription("Number of active MCP connections"), ) @@ -138,7 +133,6 @@ func TestHTTPMiddleware_RecordSSEConnection(t *testing.T) { meter: meter, serverName: "test-server", transport: "sse", - requestCounter: requestCounter, activeConnections: activeConnections, } diff --git a/pkg/telemetry/middleware_test.go b/pkg/telemetry/middleware_test.go index a582e5802c..d22659103d 100644 --- a/pkg/telemetry/middleware_test.go +++ b/pkg/telemetry/middleware_test.go @@ -26,6 +26,7 @@ import ( tracenoop "go.opentelemetry.io/otel/trace/noop" "go.uber.org/mock/gomock" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" mcpparser "github.com/stacklok/toolhive/pkg/mcp" "github.com/stacklok/toolhive/pkg/transport/types" "github.com/stacklok/toolhive/pkg/transport/types/mocks" @@ -781,23 +782,25 @@ func TestHTTPMiddleware_WithRealMetrics(t *testing.T) { // Verify metrics were recorded assert.NotEmpty(t, rm.ScopeMetrics) - // Find our metrics - var foundCounter, foundHistogram, foundGauge bool + // This POST carries no parsed MCP method, so mcp.server.operation.duration is + // not recorded; the transport-level http.server.request.duration is, alongside + // the renamed active-connections gauge. The deleted twins must be absent. + var foundHTTPDuration, foundGauge bool for _, sm := range rm.ScopeMetrics { for _, metric := range sm.Metrics { + assert.NotEqual(t, "toolhive_mcp_requests", metric.Name) + assert.NotEqual(t, "toolhive_mcp_request_duration", metric.Name) + assert.NotEqual(t, "toolhive_mcp_tool_calls", metric.Name) switch metric.Name { - case metricRequestCounter: - foundCounter = true - case "toolhive_mcp_request_duration": - foundHistogram = true - case "toolhive_mcp_active_connections": + case "http.server.request.duration": + foundHTTPDuration = true + case "stacklok.toolhive.proxy.active_connections": foundGauge = true } } } - assert.True(t, foundCounter, "Request counter metric should be recorded") - assert.True(t, foundHistogram, "Request duration histogram should be recorded") + assert.True(t, foundHTTPDuration, "http server request duration should be recorded") assert.True(t, foundGauge, "Active connections gauge should be recorded") } @@ -2425,16 +2428,12 @@ func TestRecordSSEConnection_DualEmission(t *testing.T) { t.Parallel() mt := &mockTracer{} - meterProvider := noop.NewMeterProvider() - meter := meterProvider.Meter(instrumentationName) - requestCounter, _ := meter.Int64Counter("toolhive_mcp_requests") middleware := &HTTPMiddleware{ - config: Config{UseLegacyAttributes: tt.useLegacy}, - tracer: mt, - serverName: "github", - transport: tt.transport, - requestCounter: requestCounter, + config: Config{UseLegacyAttributes: tt.useLegacy}, + tracer: mt, + serverName: "github", + transport: tt.transport, } req := httptest.NewRequest("GET", "/sse", nil) @@ -2461,3 +2460,288 @@ func TestRecordSSEConnection_DualEmission(t *testing.T) { }) } } + +// findHTTPServerDuration returns the http.server.request.duration histogram from +// collected metrics, or nil if absent. +func findHTTPServerDuration(rm metricdata.ResourceMetrics) *metricdata.Histogram[float64] { + return findHistogramByName(rm, "http.server.request.duration") +} + +func findSSEConnectionDuration(rm metricdata.ResourceMetrics) *metricdata.Histogram[float64] { + return findHistogramByName(rm, "stacklok.toolhive.proxy.sse_connection.duration") +} + +func findHistogramByName(rm metricdata.ResourceMetrics, name string) *metricdata.Histogram[float64] { + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == name { + if h, ok := m.Data.(metricdata.Histogram[float64]); ok { + return &h + } + } + } + } + return nil +} + +// TestHTTPMiddleware_OperationDurationSemconvBuckets pins mcp.server.operation.duration +// to the semconv bucket preset. A semconv-named metric must carry the semconv +// boundary set: switching it to a coarser preset silently changes the layout, so +// any histogram_quantile() spanning the change mixes two incompatible bucket sets +// and returns wrong values with no error. +func TestHTTPMiddleware_OperationDurationSemconvBuckets(t *testing.T) { + t.Parallel() + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + middleware := NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), meterProvider, "github", "streamable-http") + + handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + + req := httptest.NewRequest(http.MethodPost, "/mcp", nil) + req = req.WithContext(context.WithValue(req.Context(), mcpparser.MCPRequestContextKey, + &mcpparser.ParsedMCPRequest{Method: "tools/list"})) + handler.ServeHTTP(httptest.NewRecorder(), req) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + hist := findHistogramByName(rm, metricOperationDuration) + require.NotNil(t, hist, "mcp.server.operation.duration must be emitted") + require.Len(t, hist.DataPoints, 1) + + assert.Equal(t, coremetrics.BucketsMCPSemconv(), hist.DataPoints[0].Bounds, + "semconv-named metric must carry the semconv bucket preset, not the coarser proxy preset") +} + +// TestHTTPMiddleware_OperationDurationUnknownMethodOther pins the cardinality +// bound on mcp.method.name. The JSON-RPC method arrives verbatim from the request +// body, so an unrecognized one must collapse to _OTHER rather than minting a new +// time series per distinct string. +func TestHTTPMiddleware_OperationDurationUnknownMethodOther(t *testing.T) { + t.Parallel() + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + middleware := NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), meterProvider, "github", "streamable-http") + + handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + + req := httptest.NewRequest(http.MethodPost, "/mcp", nil) + req = req.WithContext(context.WithValue(req.Context(), mcpparser.MCPRequestContextKey, + &mcpparser.ParsedMCPRequest{Method: "evil/made-up-method"})) + handler.ServeHTTP(httptest.NewRecorder(), req) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + hist := findHistogramByName(rm, metricOperationDuration) + require.NotNil(t, hist, "mcp.server.operation.duration must be emitted") + require.Len(t, hist.DataPoints, 1) + + mv, ok := hist.DataPoints[0].Attributes.Value(attribute.Key("mcp.method.name")) + require.True(t, ok, "mcp.method.name must be present") + assert.Equal(t, attrValueOther, mv.AsString(), + "an unrecognized JSON-RPC method must collapse to the _OTHER sentinel") +} + +func TestHTTPMiddleware_HTTPServerRequestDuration(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + method string + path string + parsedMCP *mcpparser.ParsedMCPRequest // nil => no MCP method (SSE-open GET / non-MCP) + handlerStatus int + wantMethod string + wantStatusCode int64 + wantErrorType string // "" => error.type must be absent + }{ + { + // RFC §7 AT: a GET SSE-open request carrying no MCP method still + // produces an http.server.request.duration observation. + name: "GET SSE-open with no MCP method", + method: http.MethodGet, + path: "/mcp", + parsedMCP: nil, + handlerStatus: http.StatusOK, + wantMethod: http.MethodGet, + wantStatusCode: 200, + wantErrorType: "", + }, + { + name: "normal POST with MCP method", + method: http.MethodPost, + path: "/mcp", + parsedMCP: &mcpparser.ParsedMCPRequest{Method: "tools/list"}, + handlerStatus: http.StatusOK, + wantMethod: http.MethodPost, + wantStatusCode: 200, + wantErrorType: "", + }, + { + name: "DELETE session terminate with no MCP method", + method: http.MethodDelete, + path: "/mcp", + parsedMCP: nil, + handlerStatus: http.StatusOK, + wantMethod: http.MethodDelete, + wantStatusCode: 200, + wantErrorType: "", + }, + { + name: "5xx sets error.type to status code", + method: http.MethodPost, + path: "/mcp", + parsedMCP: &mcpparser.ParsedMCPRequest{Method: "tools/call"}, + handlerStatus: http.StatusBadGateway, + wantMethod: http.MethodPost, + wantStatusCode: 502, + wantErrorType: "502", + }, + { + // The documented narrowing: error.type is set only for status >= 500, + // so a 4xx must leave it absent. Guards against a regression back to + // statusCode >= 400, which would silently start counting auth denials + // as errors again. + name: "4xx leaves error.type absent", + method: http.MethodPost, + path: "/mcp", + parsedMCP: &mcpparser.ParsedMCPRequest{Method: "tools/call"}, + handlerStatus: http.StatusForbidden, + wantMethod: http.MethodPost, + wantStatusCode: 403, + wantErrorType: "", + }, + { + // Go's net/http accepts any RFC 7230 token as a method, so an + // unrecognized one must collapse to the semconv _OTHER sentinel + // rather than minting a new series per distinct string. + name: "unknown method collapses to _OTHER", + method: "ZZZZ1", + path: "/mcp", + parsedMCP: nil, + handlerStatus: http.StatusOK, + wantMethod: attrValueOther, + wantStatusCode: 200, + wantErrorType: "", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + middleware := NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), meterProvider, "github", "streamable-http") + + handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(tt.handlerStatus) + })) + + req := httptest.NewRequest(tt.method, tt.path, nil) + if tt.parsedMCP != nil { + req = req.WithContext(context.WithValue(req.Context(), mcpparser.MCPRequestContextKey, tt.parsedMCP)) + } + handler.ServeHTTP(httptest.NewRecorder(), req) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + hist := findHTTPServerDuration(rm) + require.NotNil(t, hist, "http.server.request.duration must be emitted") + require.Len(t, hist.DataPoints, 1) + dp := hist.DataPoints[0] + + // Buckets: fast-HTTP preset. + assert.Equal(t, coremetrics.BucketsFastHTTP(), dp.Bounds, + "must use the fast-HTTP bucket preset") + + // Data points are keyed by attribute set, so a double-record would + // still yield one data point — with Count == 2. Pin the count so + // double-counting transport-level request volume is detectable. + assert.Equal(t, uint64(1), dp.Count, "request must be recorded exactly once") + + // semconv attributes only. + mv, ok := dp.Attributes.Value(attribute.Key("http.request.method")) + require.True(t, ok, "http.request.method must be present") + assert.Equal(t, tt.wantMethod, mv.AsString()) + + // url.scheme is Required on http.server.request.duration. + schemeV, ok := dp.Attributes.Value(attribute.Key("url.scheme")) + require.True(t, ok, "url.scheme must be present") + assert.Equal(t, "http", schemeV.AsString()) + + sv, ok := dp.Attributes.Value(attribute.Key("http.response.status_code")) + require.True(t, ok, "http.response.status_code must be present") + assert.Equal(t, tt.wantStatusCode, sv.AsInt64()) + + serverV, ok := dp.Attributes.Value(attribute.Key(coremetrics.LabelMCPServer)) + require.True(t, ok, "mcp_server must be present") + assert.Equal(t, "github", serverV.AsString()) + + ev, hasErr := dp.Attributes.Value(attribute.Key("error.type")) + if tt.wantErrorType == "" { + assert.False(t, hasErr, "error.type must be absent on non-5xx") + } else { + require.True(t, hasErr, "error.type must be present on 5xx") + assert.Equal(t, tt.wantErrorType, ev.AsString()) + } + + // The semconv metric must not carry the Stacklok mcp_method label. + _, hasMCPMethod := dp.Attributes.Value(attribute.Key(coremetrics.LabelMCPMethod)) + assert.False(t, hasMCPMethod, "semconv metric must not carry the mcp_method label") + }) + } +} + +// TestHTTPMiddleware_SSEConnectionDuration_SSEBranch exercises the SSE branch +// of Handler specifically (path suffix "/sse"), which records +// stacklok.toolhive.proxy.sse_connection.duration in its own deferred call on +// connection close rather than through recordMetrics. It must NOT emit +// http.server.request.duration: SSE connections are long-lived (minutes to +// hours), and that histogram's 10-second top bucket would flatten every +// quantile query if SSE observations landed there — see the constructor +// comment on sseConnectionDuration in middleware.go. +func TestHTTPMiddleware_SSEConnectionDuration_SSEBranch(t *testing.T) { + t.Parallel() + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + middleware := NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), meterProvider, "github", "sse") + + handler := middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("data: test event\n\n")) + })) + + req := httptest.NewRequest(http.MethodGet, "/sse", nil) + handler.ServeHTTP(httptest.NewRecorder(), req) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + require.Nil(t, findHTTPServerDuration(rm), + "http.server.request.duration must not be emitted for the SSE branch") + + hist := findSSEConnectionDuration(rm) + require.NotNil(t, hist, "stacklok.toolhive.proxy.sse_connection.duration must be emitted for the SSE branch") + require.Len(t, hist.DataPoints, 1) + dp := hist.DataPoints[0] + + assert.Equal(t, uint64(1), dp.Count, "SSE connection must be recorded exactly once") + + assert.Equal(t, coremetrics.BucketsMCPProxy(), dp.Bounds, + "sse_connection.duration must use the MCP-proxy bucket preset (tops out at 300s), not the 10s-capped fast-HTTP preset") + + serverV, ok := dp.Attributes.Value(attribute.Key(coremetrics.LabelMCPServer)) + require.True(t, ok, "mcp_server must be present") + assert.Equal(t, "github", serverV.AsString()) +} diff --git a/pkg/telemetry/providers/prometheus/prometheus.go b/pkg/telemetry/providers/prometheus/prometheus.go index 753e6214e8..991aac6416 100644 --- a/pkg/telemetry/providers/prometheus/prometheus.go +++ b/pkg/telemetry/providers/prometheus/prometheus.go @@ -11,8 +11,11 @@ import ( promclient "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/collectors" "github.com/prometheus/client_golang/prometheus/promhttp" + "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/prometheus" sdkmetric "go.opentelemetry.io/otel/sdk/metric" + + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" ) // Config holds Prometheus-specific configuration @@ -21,6 +24,11 @@ type Config struct { EnableMetricsPath bool // IncludeRuntimeMetrics adds Go runtime metrics to the registry IncludeRuntimeMetrics bool + // OwnershipLabels are the D8 stacklok.component/stacklok.product values. They are applied + // as Prometheus constant labels directly to the runtime-metrics registerer, since the Go/ + // process collectors are registered on the raw registry and never pass through the OTel + // exporter's WithResourceAsConstantLabels promotion below. + OwnershipLabels map[string]string } // NewReader creates a Prometheus metric reader and HTTP handler for use in a unified meter provider @@ -32,14 +40,25 @@ func NewReader(config Config) (sdkmetric.Reader, http.Handler, error) { // Create a dedicated registry registry := promclient.NewRegistry() - // Add runtime metrics if requested + // Add runtime metrics if requested. These are native prometheus.Collector + // implementations registered directly on the registry, so they never pass + // through the OTel exporter below — wrap the registerer with the same D8 + // ownership labels so go_*/process_* series carry them too. if config.IncludeRuntimeMetrics { - registry.MustRegister(collectors.NewGoCollector()) - registry.MustRegister(collectors.NewProcessCollector(collectors.ProcessCollectorOpts{})) + runtimeRegisterer := promclient.WrapRegistererWith(config.OwnershipLabels, registry) + runtimeRegisterer.MustRegister(collectors.NewGoCollector()) + runtimeRegisterer.MustRegister(collectors.NewProcessCollector(collectors.ProcessCollectorOpts{})) } - // Create the Prometheus exporter (which is also a Reader) - exporter, err := prometheus.New(prometheus.WithRegisterer(registry)) + // Create the Prometheus exporter (which is also a Reader). Promote the + // stacklok.component/stacklok.product resource attributes to per-series + // constant labels so dashboards can filter on them (D8). + exporter, err := prometheus.New( + prometheus.WithRegisterer(registry), + prometheus.WithResourceAsConstantLabels(attribute.NewAllowKeysFilter( + coremetrics.AttrStacklokComponent, coremetrics.AttrStacklokProduct, + )), + ) if err != nil { return nil, nil, fmt.Errorf("failed to create prometheus exporter: %w", err) } diff --git a/pkg/telemetry/providers/prometheus/prometheus_test.go b/pkg/telemetry/providers/prometheus/prometheus_test.go index e154f01f67..ad14f6fe33 100644 --- a/pkg/telemetry/providers/prometheus/prometheus_test.go +++ b/pkg/telemetry/providers/prometheus/prometheus_test.go @@ -7,6 +7,7 @@ import ( "context" "net/http" "net/http/httptest" + "strings" "testing" "github.com/stretchr/testify/assert" @@ -32,6 +33,10 @@ func TestNewReader(t *testing.T) { config: Config{ EnableMetricsPath: true, IncludeRuntimeMetrics: true, + OwnershipLabels: map[string]string{ + "stacklok_component": "toolhive", + "stacklok_product": "stacklok-platform", + }, }, wantErr: false, checkHandler: true, @@ -87,8 +92,19 @@ func TestNewReader(t *testing.T) { // Check for runtime metrics if expected if tt.checkRuntimeMetrics { - assert.Contains(t, rec.Body.String(), "go_") - assert.Contains(t, rec.Body.String(), "process_") + body := rec.Body.String() + assert.Contains(t, body, "go_") + assert.Contains(t, body, "process_") + + // D8 ownership labels must be promoted onto runtime/process series too, + // since they're registered on the raw registry and never pass through + // the OTel exporter's WithResourceAsConstantLabels. + for line := range strings.SplitSeq(body, "\n") { + if strings.HasPrefix(line, "go_goroutines") || strings.HasPrefix(line, "process_cpu_seconds_total") { + assert.Contains(t, line, `stacklok_component="toolhive"`) + assert.Contains(t, line, `stacklok_product="stacklok-platform"`) + } + } } } } diff --git a/pkg/telemetry/providers/providers.go b/pkg/telemetry/providers/providers.go index 924d68289f..d0e260c557 100644 --- a/pkg/telemetry/providers/providers.go +++ b/pkg/telemetry/providers/providers.go @@ -19,8 +19,15 @@ import ( semconv "go.opentelemetry.io/otel/semconv/v1.21.0" "go.opentelemetry.io/otel/trace" tracenoop "go.opentelemetry.io/otel/trace/noop" + + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" ) +// ComponentName is toolhive's stacklok.component value (D8). toolhive-core +// defines the AttrStacklokComponent key but leaves the value to each component. +// Exported so pkg/telemetry's build-info registration uses the same value. +const ComponentName = "toolhive" + // Config holds the telemetry configuration for all providers. // It contains service information, OTLP settings, and Prometheus configuration. type Config struct { @@ -177,8 +184,7 @@ func NewCompositeProvider( } } - // Create resource for all providers - // Start with base attributes + // Create resource for all providers. baseAttrs := []attribute.KeyValue{ semconv.ServiceName(config.ServiceName), semconv.ServiceVersion(config.ServiceVersion), @@ -196,11 +202,23 @@ func NewCompositeProvider( } } + // stacklok.component/stacklok.product identify the emitter across the platform + // (D8); the product value is frozen as "stacklok-platform". These are applied + // as the last detector so they win over any collision from CustomAttributes or + // OTEL_RESOURCE_ATTRIBUTES — the ownership labels must not be user-overridable. + ownershipAttrs := []attribute.KeyValue{ + attribute.String(coremetrics.AttrStacklokComponent, ComponentName), + attribute.String(coremetrics.AttrStacklokProduct, coremetrics.ProductStacklokPlatform), + } + + warnIfOwnershipAttrsOverridden(ctx, baseAttrs) + // Create resource with base attributes and support for OTEL_RESOURCE_ATTRIBUTES env var res, err := resource.New(ctx, resource.WithAttributes(baseAttrs...), - resource.WithFromEnv(), // This reads OTEL_RESOURCE_ATTRIBUTES automatically - resource.WithHost(), // Add host information + resource.WithFromEnv(), // This reads OTEL_RESOURCE_ATTRIBUTES automatically + resource.WithHost(), // Add host information + resource.WithAttributes(ownershipAttrs...), // Reserved D8 labels; last so they cannot be overridden ) if err != nil { return nil, fmt.Errorf("failed to create resource with service name '%s' and version '%s': %w", @@ -220,6 +238,39 @@ func NewCompositeProvider( return buildProviders(ctx, config, selector, res) } +// warnIfOwnershipAttrsOverridden logs a warning for each reserved D8 key +// (stacklok.component, stacklok.product) that a user attempted to set via +// CustomAttributes or OTEL_RESOURCE_ATTRIBUTES. Both sources are silently +// discarded in favor of the frozen ToolHive-owned value (see ownershipAttrs +// in NewCompositeProvider) — this only makes that discard observable so an +// operator debugging a missing custom value isn't left with no signal. +func warnIfOwnershipAttrsOverridden(ctx context.Context, baseAttrs []attribute.KeyValue) { + reserved := map[attribute.Key]struct{}{ + attribute.Key(coremetrics.AttrStacklokComponent): {}, + attribute.Key(coremetrics.AttrStacklokProduct): {}, + } + + for _, attr := range baseAttrs { + if _, ok := reserved[attr.Key]; ok { + slog.Warn("ignoring user-supplied custom attribute: reserved by ToolHive and cannot be overridden", + "key", string(attr.Key)) + } + } + + // OTEL_RESOURCE_ATTRIBUTES isn't part of baseAttrs (WithFromEnv reads it + // directly inside resource.New), so probe it independently. + envRes, err := resource.New(ctx, resource.WithFromEnv()) + if err != nil { + return + } + for _, attr := range envRes.Attributes() { + if _, ok := reserved[attr.Key]; ok { + slog.Warn("ignoring OTEL_RESOURCE_ATTRIBUTES entry: reserved by ToolHive and cannot be overridden", + "key", string(attr.Key)) + } + } +} + func createNoOpProvider() *CompositeProvider { return &CompositeProvider{ tracerProvider: tracenoop.NewTracerProvider(), diff --git a/pkg/telemetry/providers/providers_strategy.go b/pkg/telemetry/providers/providers_strategy.go index bb30746425..66d22bf0c9 100644 --- a/pkg/telemetry/providers/providers_strategy.go +++ b/pkg/telemetry/providers/providers_strategy.go @@ -16,6 +16,7 @@ import ( "go.opentelemetry.io/otel/trace" tracenoop "go.opentelemetry.io/otel/trace/noop" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/telemetry/providers/otlp" "github.com/stacklok/toolhive/pkg/telemetry/providers/prometheus" ) @@ -146,6 +147,19 @@ func (s *UnifiedMeterStrategy) CreateMeterProvider( promConfig := prometheus.Config{ EnableMetricsPath: true, IncludeRuntimeMetrics: true, + // Prometheus label names, not OTel attribute keys — coremetrics.AttrStacklokComponent/ + // AttrStacklokProduct ("stacklok.component"/"stacklok.product") are dotted OTel resource- + // attribute names and must not be used here. This map goes straight into + // promclient.WrapRegistererWith, and Prometheus's own name-escaping scheme is + // content-negotiated per scrape: a client negotiating escaping=allow-utf-8 (Prometheus + // 3.x) gets a dotted key back verbatim, while every OTel-native series on this same + // provider is unconditionally converted to underscore form by the OTel exporter's own + // attribute-to-label conversion — splitting one ownership label into two incompatible + // families depending on how a given scraper negotiates. + OwnershipLabels: map[string]string{ + "stacklok_component": ComponentName, + "stacklok_product": coremetrics.ProductStacklokPlatform, + }, } reader, handler, err := prometheus.NewReader(promConfig) if err != nil { diff --git a/pkg/telemetry/providers/providers_strategy_test.go b/pkg/telemetry/providers/providers_strategy_test.go index 2b2d63562a..81d8c6c433 100644 --- a/pkg/telemetry/providers/providers_strategy_test.go +++ b/pkg/telemetry/providers/providers_strategy_test.go @@ -6,6 +6,8 @@ package providers import ( "context" "fmt" + "net/http" + "net/http/httptest" "strings" "testing" @@ -459,6 +461,71 @@ func TestUnifiedMeterStrategy_Configurations(t *testing.T) { } } +// TestUnifiedMeterStrategy_PrometheusOwnershipLabels verifies that the D8 ownership +// labels (stacklok_component/stacklok_product) reach runtime/process series through +// UnifiedMeterStrategy's own OwnershipLabels map construction, not just through +// prometheus.NewReader called directly with hardcoded labels (see prometheus_test.go). +// A key/value swap or wrong-form key (e.g. an OTel dotted attribute key instead of a +// Prometheus label name) in that construction would otherwise go undetected. +// +// Escaping is checked under two negotiated formats, not just the default: Prometheus's +// name-escaping scheme is content-negotiated per scrape, and a dotted OTel attribute key +// used as a Prometheus label name would pass under the default (UnderscoreEscaping) +// negotiation while still exposing verbatim under escaping=allow-utf-8 (Prometheus 3.x) — +// splitting one ownership label into two incompatible families depending on scraper. Only +// testing the default negotiation would have let that regression through undetected. +func TestUnifiedMeterStrategy_PrometheusOwnershipLabels(t *testing.T) { + t.Parallel() + + ctx := context.Background() + res := createTestResource(t) + + strategy := &UnifiedMeterStrategy{EnablePrometheus: true} + result, err := strategy.CreateMeterProvider(ctx, Config{}, res) + require.NoError(t, err) + require.NotNil(t, result.PrometheusHandler) + + tests := []struct { + name string + accept string + }{ + {name: "default negotiation", accept: ""}, + { + name: "escaping=allow-utf-8 negotiation", + accept: "text/plain;version=0.0.4;escaping=allow-utf-8,*/*;q=0.1", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + if tt.accept != "" { + req.Header.Set("Accept", tt.accept) + } + rec := httptest.NewRecorder() + result.PrometheusHandler.ServeHTTP(rec, req) + require.Equal(t, http.StatusOK, rec.Code) + + body := rec.Body.String() + require.Contains(t, body, "go_goroutines") + + foundRuntimeSeries := false + for line := range strings.SplitSeq(body, "\n") { + if strings.HasPrefix(line, "go_goroutines") || strings.HasPrefix(line, "process_cpu_seconds_total") { + foundRuntimeSeries = true + assert.Contains(t, line, `stacklok_component="toolhive"`) + assert.Contains(t, line, `stacklok_product="stacklok-platform"`) + assert.NotContains(t, line, `"stacklok.component"`, + "ownership label must never expose in dotted OTel-attribute form") + } + } + assert.True(t, foundRuntimeSeries, "expected to find go_/process_ runtime series in scrape output") + }) + } +} + // TestUnifiedMeterStrategyConfiguration tests the unified meter strategy configuration func TestUnifiedMeterStrategyConfiguration(t *testing.T) { t.Parallel() diff --git a/pkg/telemetry/providers/providers_test.go b/pkg/telemetry/providers/providers_test.go index bec1c562fa..477d0124d4 100644 --- a/pkg/telemetry/providers/providers_test.go +++ b/pkg/telemetry/providers/providers_test.go @@ -4,8 +4,12 @@ package providers import ( + "bytes" "context" "errors" + "log/slog" + "net/http" + "net/http/httptest" "testing" "time" @@ -186,6 +190,103 @@ func TestAssembler_Assemble_WithEverything(t *testing.T) { assert.NotEmpty(t, provider.shutdownFuncs) // Should have multiple shutdown functions } +// TestReservedOwnershipAttributesNotOverridable verifies the D8 ownership labels +// (stacklok.component / stacklok.product) cannot be overridden by user-supplied +// CustomAttributes or the OTEL_RESOURCE_ATTRIBUTES env var. The Prometheus +// exporter renders resource attributes onto the target_info gauge, so scraping +// it reveals the final resource state. +func TestReservedOwnershipAttributesNotOverridable(t *testing.T) { + // Not parallel: mutates the OTEL_RESOURCE_ATTRIBUTES process env var. + t.Setenv("OTEL_RESOURCE_ATTRIBUTES", "stacklok.product=evil-product,deployment=prod") + + ctx := context.Background() + provider, err := NewCompositeProvider(ctx, + WithServiceName("test-service"), + WithServiceVersion("1.0.0"), + WithMetricsEnabled(false), + WithTracingEnabled(false), + WithEnablePrometheusMetricsPath(true), + // A CLI custom attribute attempting to override the reserved component key. + WithCustomAttributes(map[string]string{ + "stacklok.component": "evil-component", + "deployment": "prod", + }), + ) + require.NoError(t, err) + require.NotNil(t, provider.PrometheusHandler()) + + // Emit a metric so the exporter renders target_info with the resource attrs. + meter := provider.MeterProvider().Meter("test") + counter, err := meter.Int64Counter("test.counter") + require.NoError(t, err) + counter.Add(ctx, 1) + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rw := httptest.NewRecorder() + provider.PrometheusHandler().ServeHTTP(rw, req) + body := rw.Body.String() + + // The frozen ownership labels must survive both override attempts. + assert.Contains(t, body, `stacklok_component="toolhive"`, + "reserved component label must not be overridable by CustomAttributes") + assert.Contains(t, body, `stacklok_product="stacklok-platform"`, + "reserved product label must not be overridable by OTEL_RESOURCE_ATTRIBUTES") + assert.NotContains(t, body, "evil-component", + "user-supplied component override must be discarded") + assert.NotContains(t, body, "evil-product", + "env-supplied product override must be discarded") + // Non-reserved custom/env attributes are still applied. + assert.Contains(t, body, `deployment="prod"`, + "non-reserved custom attributes should still pass through") +} + +// captureSlogWarn redirects slog's default logger to a bytes.Buffer for the +// duration of f, then restores the original default. Returns the captured +// output. This helper exists because slog.SetDefault is a process-global +// side effect — tests that use it must NOT run in parallel. +func captureSlogWarn(t *testing.T, f func()) string { + t.Helper() + + var buf bytes.Buffer + handler := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelWarn}) + orig := slog.Default() + slog.SetDefault(slog.New(handler)) + t.Cleanup(func() { slog.SetDefault(orig) }) + + f() + + return buf.String() +} + +// TestReservedOwnershipAttributeOverrideIsLogged verifies that an attempted +// override of a reserved D8 key — via CustomAttributes or +// OTEL_RESOURCE_ATTRIBUTES — produces a WARN log naming the rejected key, so +// an operator debugging a missing custom value has a signal to find. +// +//nolint:paralleltest,tparallel // Subtest uses slog.SetDefault, which is process-global +func TestReservedOwnershipAttributeOverrideIsLogged(t *testing.T) { + t.Setenv("OTEL_RESOURCE_ATTRIBUTES", "stacklok.product=evil-product") + + ctx := context.Background() + output := captureSlogWarn(t, func() { + _, err := NewCompositeProvider(ctx, + WithServiceName("test-service"), + WithServiceVersion("1.0.0"), + WithMetricsEnabled(false), + WithTracingEnabled(false), + WithCustomAttributes(map[string]string{ + "stacklok.component": "evil-component", + }), + ) + require.NoError(t, err) + }) + + assert.Contains(t, output, "stacklok.component", + "WARN log must name the rejected CustomAttributes key") + assert.Contains(t, output, "stacklok.product", + "WARN log must name the rejected OTEL_RESOURCE_ATTRIBUTES key") +} + func TestCompositeProvider_Accessors(t *testing.T) { t.Parallel() diff --git a/pkg/vmcp/core/core_telemetry.go b/pkg/vmcp/core/core_telemetry.go index 40f565f4e9..e1e00b6517 100644 --- a/pkg/vmcp/core/core_telemetry.go +++ b/pkg/vmcp/core/core_telemetry.go @@ -13,6 +13,7 @@ import ( "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/telemetry" "github.com/stacklok/toolhive/pkg/vmcp/composer" ) @@ -28,7 +29,6 @@ const instrumentationName = "github.com/stacklok/toolhive/pkg/vmcp" type workflowInstruments struct { tracer trace.Tracer executionsTotal metric.Int64Counter - errorsTotal metric.Int64Counter executionDuration metric.Float64Histogram } @@ -45,26 +45,18 @@ func newWorkflowInstruments(provider *telemetry.Provider) (*workflowInstruments, meter := provider.MeterProvider().Meter(instrumentationName) executions, err := meter.Int64Counter( - "toolhive_vmcp_workflow_executions", - metric.WithDescription("Total number of workflow executions"), + "stacklok.vmcp.composite_tool.executions", + metric.WithDescription("Total number of workflow executions, split by outcome"), ) if err != nil { return nil, fmt.Errorf("failed to create workflow executions counter: %w", err) } - errors, err := meter.Int64Counter( - "toolhive_vmcp_workflow_errors", - metric.WithDescription("Total number of workflow execution errors"), - ) - if err != nil { - return nil, fmt.Errorf("failed to create workflow errors counter: %w", err) - } - duration, err := meter.Float64Histogram( - "toolhive_vmcp_workflow_duration", + "stacklok.vmcp.composite_tool.duration", metric.WithDescription("Duration of workflow executions in seconds"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsLongRunning()...), ) if err != nil { return nil, fmt.Errorf("failed to create workflow duration histogram: %w", err) @@ -73,7 +65,6 @@ func newWorkflowInstruments(provider *telemetry.Provider) (*workflowInstruments, return &workflowInstruments{ tracer: provider.TracerProvider().Tracer(instrumentationName), executionsTotal: executions, - errorsTotal: errors, executionDuration: duration, }, nil } @@ -88,32 +79,34 @@ type telemetryComposer struct { var _ composer.Composer = (*telemetryComposer)(nil) -// ExecuteWorkflow records execution count, duration, and errors before delegating -// to the wrapped composer. Uses def.Name as the workflow_name metric attribute to -// match the label emitted by the session-factory path in sessionmanager. +// ExecuteWorkflow records execution count (split by outcome) and duration around +// the wrapped composer call. Uses def.Name as the composite_tool metric attribute +// to match the label emitted by the session-factory path in sessionmanager. func (c *telemetryComposer) ExecuteWorkflow( ctx context.Context, def *composer.WorkflowDefinition, params map[string]any, ) (*composer.WorkflowResult, error) { - commonAttrs := []attribute.KeyValue{attribute.String("workflow.name", def.Name)} - ctx, span := c.instruments.tracer.Start(ctx, "core.ExecuteWorkflow", - trace.WithAttributes(commonAttrs...), + trace.WithAttributes(attribute.String("workflow.name", def.Name)), ) defer span.End() - metricAttrs := metric.WithAttributes(commonAttrs...) + durationAttrs := metric.WithAttributes(attribute.String(coremetrics.LabelCompositeTool, def.Name)) start := time.Now() - c.instruments.executionsTotal.Add(ctx, 1, metricAttrs) result, err := c.base.ExecuteWorkflow(ctx, def, params) - c.instruments.executionDuration.Record(ctx, time.Since(start).Seconds(), metricAttrs) + c.instruments.executionDuration.Record(ctx, time.Since(start).Seconds(), durationAttrs) + outcome := coremetrics.OutcomeSuccess if err != nil { - c.instruments.errorsTotal.Add(ctx, 1, metricAttrs) + outcome = coremetrics.OutcomeError span.RecordError(err) span.SetStatus(codes.Error, err.Error()) } + c.instruments.executionsTotal.Add(ctx, 1, metric.WithAttributes( + attribute.String(coremetrics.LabelCompositeTool, def.Name), + attribute.String(coremetrics.LabelOutcome, outcome), + )) return result, err } diff --git a/pkg/vmcp/core/core_telemetry_test.go b/pkg/vmcp/core/core_telemetry_test.go index 1899d38062..9026386cde 100644 --- a/pkg/vmcp/core/core_telemetry_test.go +++ b/pkg/vmcp/core/core_telemetry_test.go @@ -15,6 +15,7 @@ import ( tracesdk "go.opentelemetry.io/otel/sdk/trace" tracenoop "go.opentelemetry.io/otel/trace/noop" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/vmcp/composer" ) @@ -32,17 +33,14 @@ func newTestInstruments(t *testing.T) (*workflowInstruments, *sdkmetric.ManualRe tp := tracesdk.NewTracerProvider() meter := mp.Meter(instrumentationName) - executions, err := meter.Int64Counter("toolhive_vmcp_workflow_executions") + executions, err := meter.Int64Counter("stacklok.vmcp.composite_tool.executions") require.NoError(t, err) - errs, err := meter.Int64Counter("toolhive_vmcp_workflow_errors") - require.NoError(t, err) - duration, err := meter.Float64Histogram("toolhive_vmcp_workflow_duration") + duration, err := meter.Float64Histogram("stacklok.vmcp.composite_tool.duration") require.NoError(t, err) return &workflowInstruments{ tracer: tp.Tracer(instrumentationName), executionsTotal: executions, - errorsTotal: errs, executionDuration: duration, }, reader } @@ -67,7 +65,10 @@ func findMetricByName(rm metricdata.ResourceMetrics, name string) *metricdata.Me return nil } -func int64CounterValue(m *metricdata.Metrics) int64 { +// counterValueForOutcome sums the data points of an int64 counter whose +// coremetrics.LabelOutcome attribute equals want. Returns 0 if no matching +// point exists. +func counterValueForOutcome(m *metricdata.Metrics, want string) int64 { if m == nil { return 0 } @@ -77,7 +78,9 @@ func int64CounterValue(m *metricdata.Metrics) int64 { } var total int64 for _, dp := range s.DataPoints { - total += dp.Value + if v, present := dp.Attributes.Value(coremetrics.LabelOutcome); present && v.AsString() == want { + total += dp.Value + } } return total } @@ -98,8 +101,8 @@ func float64HistogramCount(m *metricdata.Metrics) uint64 { } // TestTelemetryComposer_Success verifies that on a successful ExecuteWorkflow call: -// - the executions counter increments by 1 -// - the error counter stays at 0 +// - the merged executions counter increments by 1 with outcome="success" +// - the same counter records nothing under outcome="error" // - the duration histogram records 1 observation // - the result from the inner composer is returned unchanged func TestTelemetryComposer_Success(t *testing.T) { @@ -118,17 +121,20 @@ func TestTelemetryComposer_Success(t *testing.T) { assert.Equal(t, want, got) rm := collectMetrics(t, reader) - assert.Equal(t, int64(1), int64CounterValue(findMetricByName(rm, "toolhive_vmcp_workflow_executions")), - "executions counter must increment on success") - assert.Equal(t, int64(0), int64CounterValue(findMetricByName(rm, "toolhive_vmcp_workflow_errors")), - "errors counter must remain zero on success") - assert.Equal(t, uint64(1), float64HistogramCount(findMetricByName(rm, "toolhive_vmcp_workflow_duration")), + execs := findMetricByName(rm, "stacklok.vmcp.composite_tool.executions") + assert.Equal(t, int64(1), counterValueForOutcome(execs, "success"), + `executions counter must increment with outcome="success"`) + assert.Equal(t, int64(0), counterValueForOutcome(execs, "error"), + `executions counter must record nothing under outcome="error" on success`) + assert.Nil(t, findMetricByName(rm, "stacklok.vmcp.composite_tool.errors"), + "the split _errors counter must no longer exist") + assert.Equal(t, uint64(1), float64HistogramCount(findMetricByName(rm, "stacklok.vmcp.composite_tool.duration")), "duration histogram must record exactly one observation") } // TestTelemetryComposer_Error verifies that on a failed ExecuteWorkflow call: -// - the executions counter still increments by 1 -// - the error counter also increments by 1 +// - the merged executions counter increments by 1 with outcome="error" +// - the same counter records nothing under outcome="success" // - the duration histogram records 1 observation // - the error from the inner composer is propagated func TestTelemetryComposer_Error(t *testing.T) { @@ -146,11 +152,14 @@ func TestTelemetryComposer_Error(t *testing.T) { require.ErrorIs(t, err, boom) rm := collectMetrics(t, reader) - assert.Equal(t, int64(1), int64CounterValue(findMetricByName(rm, "toolhive_vmcp_workflow_executions")), - "executions counter must increment even on failure") - assert.Equal(t, int64(1), int64CounterValue(findMetricByName(rm, "toolhive_vmcp_workflow_errors")), - "errors counter must increment on failure") - assert.Equal(t, uint64(1), float64HistogramCount(findMetricByName(rm, "toolhive_vmcp_workflow_duration")), + execs := findMetricByName(rm, "stacklok.vmcp.composite_tool.executions") + assert.Equal(t, int64(1), counterValueForOutcome(execs, "error"), + `executions counter must increment with outcome="error" on failure`) + assert.Equal(t, int64(0), counterValueForOutcome(execs, "success"), + `executions counter must record nothing under outcome="success" on failure`) + assert.Nil(t, findMetricByName(rm, "stacklok.vmcp.composite_tool.errors"), + "the split _errors counter must no longer exist") + assert.Equal(t, uint64(1), float64HistogramCount(findMetricByName(rm, "stacklok.vmcp.composite_tool.duration")), "duration histogram must record one observation even on failure") } diff --git a/pkg/vmcp/core/core_vmcp.go b/pkg/vmcp/core/core_vmcp.go index 98c5523fca..2324200cc2 100644 --- a/pkg/vmcp/core/core_vmcp.go +++ b/pkg/vmcp/core/core_vmcp.go @@ -80,11 +80,33 @@ type coreVMCP struct { // Close is not a silent capability assertion. Guarded by closeOnce. stopStore func() + // unregisterBackendHealth releases the backend-health gauge callback + // registered by backendtelemetry.MonitorBackends. A no-op when telemetry is + // disabled. Guarded by closeOnce. + unregisterBackendHealth func() error + closeOnce sync.Once } var _ VMCP = (*coreVMCP)(nil) +// unregisterHealthLogged calls unregister and logs (rather than swallows) a +// failure. Used from New's deferred cleanup — so a gauge callback registered +// against the shared meter provider doesn't stay attached for a coreVMCP that +// was never returned to the caller, and so never has Close called on it — and +// from Close's normal shutdown path. +// A nil unregister is a no-op: coreVMCP is also built by struct literal in-package +// (tests), where the field is left nil, so the zero value must be safe to close — +// matching the nil check on healthMonitor. +func unregisterHealthLogged(unregister func() error) { + if unregister == nil { + return + } + if err := unregister(); err != nil { + slog.Warn("failed to unregister backend health gauge callback", "error", err) + } +} + // New constructs the core [VMCP] by relocating the domain wiring that lives in // server.New today (server.go:330-405): telemetry backend-client decoration, the // optional workflow auditor, the in-memory state store and workflow engine, the @@ -109,20 +131,52 @@ func New(cfg *Config) (VMCP, error) { backendClient := cfg.BackendClient + // unregisterBackendHealth releases the health-gauge callback registered by + // MonitorBackends; a no-op unless telemetry is enabled below. Captured before + // any later error path so Close always has a valid (possibly no-op) func to call. + unregisterBackendHealth := func() error { return nil } + + // stopStore stops the state store's cleanup goroutine; reassigned once the + // store exists. Declared here so the deferred cleanup below can discharge it. + stopStore := func() {} + + // New acquires two resources that must be released if construction later + // fails: the health-gauge callback (registered against a shared meter + // provider) and the state store's cleanup goroutine. Discharging them from a + // single deferred cleanup keyed on success makes every error path below — + // present and future — correct by construction, rather than requiring each + // new `return nil, err` to remember both. + constructed := false + defer func() { + if !constructed { + unregisterHealthLogged(unregisterBackendHealth) + stopStore() + } + }() + + // healthProviderSetter lets the health monitor built below (buildHealthMonitor) + // attach itself to the already-registered gauge callback, so the gauge agrees + // with the same live health.StatusProvider filterHealthyBackends consults — + // nil until then, in which case the gauge falls back to registry/record() + // state exactly as it did before health monitoring was wired in. + var healthProviderSetter *backendtelemetry.HealthProviderSetter + // Telemetry backend-client decoration must happen BEFORE building the workflow // engine so that workflow backend calls are instrumented (server.go:350-367). if cfg.TelemetryProvider != nil { - decorated, err := backendtelemetry.MonitorBackends( + decorated, setter, unregister, err := backendtelemetry.MonitorBackends( context.Background(), cfg.TelemetryProvider.MeterProvider(), cfg.TelemetryProvider.TracerProvider(), - cfg.BackendRegistry.List(context.Background()), + cfg.BackendRegistry, backendClient, ) if err != nil { return nil, fmt.Errorf("failed to monitor backends: %w", err) } backendClient = decorated + healthProviderSetter = setter + unregisterBackendHealth = unregister } // Workflow auditor (server.go:370-381). @@ -152,7 +206,6 @@ func New(cfg *Config) (VMCP, error) { // goroutine. Capture its Stop here so Close releases it; warn loudly (rather // than a silent no-op, per go-style) if a future store swap drops the // capability, so a leaked goroutine is diagnosable instead of invisible. - stopStore := func() {} if s, ok := stateStore.(interface{ Stop() }); ok { stopStore = s.Stop } else { @@ -167,7 +220,6 @@ func New(cfg *Config) (VMCP, error) { // Prometheus counters and histograms. instruments, err := newWorkflowInstruments(cfg.TelemetryProvider) if err != nil { - stopStore() return nil, fmt.Errorf("failed to create workflow telemetry instruments: %w", err) } @@ -194,7 +246,6 @@ func New(cfg *Config) (VMCP, error) { ) workflowDefs, err := validateWorkflowDefs(validationEngine, cfg.WorkflowDefs) if err != nil { - stopStore() return nil, fmt.Errorf("workflow validation failed: %w", err) } @@ -202,23 +253,34 @@ func New(cfg *Config) (VMCP, error) { // lifecycle). The core filters capabilities with it and stops it in Close. It is started // with context.Background() and torn down via Close — like the state store — since New has // no request-scoped context. The monitor uses the undecorated backend client so health - // checks do not emit backend-call telemetry. Built last so few error paths must stop it. + // checks do not emit backend-call telemetry. healthMonitor, healthProvider, err := buildHealthMonitor(cfg) if err != nil { - stopStore() return nil, err } + // Attach the live health provider to the already-registered backend-health + // gauge so it agrees with the same StatusProvider filterHealthyBackends + // consults, rather than only the registry snapshot/request-outcome fallback. + // A nil healthProvider (monitoring disabled or failed to start) is a valid, + // explicit no-op — the gauge keeps using its pre-existing fallback. + if healthProviderSetter != nil { + healthProviderSetter.Set(healthProvider) + } + + constructed = true + return &coreVMCP{ - aggregator: cfg.Aggregator, - backendRegistry: cfg.BackendRegistry, - backendClient: backendClient, - health: healthProvider, - healthMonitor: healthMonitor, - admission: admission, - workflowDefs: workflowDefs, - composerFactory: composerFactory, - stopStore: stopStore, + aggregator: cfg.Aggregator, + backendRegistry: cfg.BackendRegistry, + backendClient: backendClient, + health: healthProvider, + healthMonitor: healthMonitor, + admission: admission, + workflowDefs: workflowDefs, + composerFactory: composerFactory, + stopStore: stopStore, + unregisterBackendHealth: unregisterBackendHealth, }, nil } @@ -537,17 +599,25 @@ func (c *coreVMCP) InvalidateCapabilityCache() { invalidator.InvalidateAll() } -// Close stops the workflow state store's cleanup goroutine. It is idempotent: -// the underlying Stop closes a channel that cannot be closed twice, so the work -// is guarded by sync.Once and subsequent calls return nil. +// Close releases everything New acquired: it stops the workflow state store's +// cleanup goroutine, stops the backend health monitor (if one was started), +// and unregisters the backend-health gauge callback (if telemetry was +// enabled). It is idempotent: the underlying Stop closes a channel that +// cannot be closed twice, so the work is guarded by sync.Once and subsequent +// calls return nil. func (c *coreVMCP) Close() error { c.closeOnce.Do(func() { - c.stopStore() + // Nil-checked for the same reason as unregisterBackendHealth below: an + // in-package struct literal leaves it unset. + if c.stopStore != nil { + c.stopStore() + } if c.healthMonitor != nil { if err := c.healthMonitor.Stop(); err != nil { slog.Warn("failed to stop health monitor", "error", err) } } + unregisterHealthLogged(c.unregisterBackendHealth) }) return nil } diff --git a/pkg/vmcp/core/core_vmcp_test.go b/pkg/vmcp/core/core_vmcp_test.go index 5506635fba..0595158b20 100644 --- a/pkg/vmcp/core/core_vmcp_test.go +++ b/pkg/vmcp/core/core_vmcp_test.go @@ -8,6 +8,10 @@ import ( "context" "errors" "log/slog" + "net/http" + "net/http/httptest" + "path/filepath" + "regexp" "testing" "time" @@ -15,7 +19,9 @@ import ( "github.com/stretchr/testify/require" "go.uber.org/mock/gomock" + "github.com/stacklok/toolhive/pkg/audit" "github.com/stacklok/toolhive/pkg/auth" + "github.com/stacklok/toolhive/pkg/telemetry" "github.com/stacklok/toolhive/pkg/vmcp" "github.com/stacklok/toolhive/pkg/vmcp/aggregator" aggmocks "github.com/stacklok/toolhive/pkg/vmcp/aggregator/mocks" @@ -157,6 +163,143 @@ func TestNew_ValidatesWorkflows(t *testing.T) { } } +// TestNew_UnregistersBackendHealthCallbackOnLaterConstructionFailure guards +// against a regression where a construction failure occurring AFTER +// MonitorBackends registers the backend-health gauge callback left that +// callback attached to the shared meter provider forever, since the coreVMCP +// it was built for is never returned to a caller and so never has Close +// called on it. Table-driven over every error branch in New that runs after +// MonitorBackends succeeds and is exercisable through this constructor's +// public inputs (invalid AuditConfig, workflow-auditor construction failure, +// workflow validation failure, health-monitor build failure) — each scrapes +// the same meter provider's Prometheus handler after the failed New call and +// asserts the gauge produced no series, proving the callback was +// unregistered, not merely that New returned an error. +// +// newWorkflowInstruments' error path (core_vmcp.go, invoked between the audit +// and validation branches above) is not included: the OTel SDK does not +// return an error for a same-name instrument-kind conflict, so there is no +// input that reaches it through the public API. +func TestNew_UnregistersBackendHealthCallbackOnLaterConstructionFailure(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + mutate func(*Config, *coreMocks) + }{ + { + name: "invalid audit configuration", + mutate: func(c *Config, _ *coreMocks) { c.AuditConfig = &audit.Config{MaxDataSize: -1} }, + }, + { + name: "workflow auditor construction fails", + mutate: func(c *Config, _ *coreMocks) { + c.AuditConfig = &audit.Config{LogFile: filepath.Join(t.TempDir(), "no-such-dir", "audit.log")} + }, + }, + { + name: "workflow validation fails", + mutate: func(c *Config, _ *coreMocks) { + c.WorkflowDefs = map[string]*composer.WorkflowDefinition{ + "wf": { + Name: "wf", + Steps: []composer.WorkflowStep{ + {ID: "s1", Type: composer.StepTypeTool, Tool: "be1.tool", DependsOn: []string{"s2"}}, + {ID: "s2", Type: composer.StepTypeTool, Tool: "be1.tool", DependsOn: []string{"s1"}}, + }, + }, + } + }, + }, + { + name: "health monitor build fails", + mutate: func(c *Config, m *coreMocks) { + // Must return a NON-EMPTY list: the gauge callback emits one point + // per (mcp_server, state) pair from registry.List, so an empty list + // yields zero series whether or not the callback was unregistered, + // making the assertion below unable to fail. + m.reg.EXPECT().List(gomock.Any()). + Return([]vmcp.Backend{{ID: testBackendID, Name: testBackendID}}).AnyTimes() + c.HealthMonitorConfig = &health.MonitorConfig{CheckInterval: 0, UnhealthyThreshold: 1} + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + ctx := context.Background() + provider, err := telemetry.NewProvider(ctx, telemetry.Config{ + ServiceName: "core-new-test-" + t.Name(), + ServiceVersion: "0.0.0", + EnablePrometheusMetricsPath: true, + }) + require.NoError(t, err) + t.Cleanup(func() { _ = provider.Shutdown(ctx) }) + + cfg, m := baseConfig(t) + cfg.TelemetryProvider = provider + tt.mutate(cfg, m) + + c, err := New(cfg) + require.Error(t, err, "construction must fail after the health callback is registered") + assert.Nil(t, c) + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rec := httptest.NewRecorder() + provider.PrometheusHandler().ServeHTTP(rec, req) + + assert.NotContains(t, rec.Body.String(), "stacklok_vmcp_mcp_server_health", + "health gauge callback must be unregistered when New fails after MonitorBackends succeeds") + }) + } +} + +// TestNew_BackendHealthGaugeEmitsThenStopsOnClose is the positive control for +// TestNew_UnregistersBackendHealthCallbackOnLaterConstructionFailure: it proves the +// gauge actually appears in a scrape after a successful New, so that test's +// NotContains assertions are capable of failing. It also covers the Close() path, +// which every other test leaves as a no-op by building without a TelemetryProvider. +func TestNew_BackendHealthGaugeEmitsThenStopsOnClose(t *testing.T) { + t.Parallel() + + ctx := context.Background() + provider, err := telemetry.NewProvider(ctx, telemetry.Config{ + ServiceName: "core-health-gauge-positive", + ServiceVersion: "0.0.0", + EnablePrometheusMetricsPath: true, + }) + require.NoError(t, err) + t.Cleanup(func() { _ = provider.Shutdown(ctx) }) + + cfg, m := baseConfig(t) + cfg.TelemetryProvider = provider + m.reg.EXPECT().List(gomock.Any()). + Return([]vmcp.Backend{{ID: testBackendID, Name: testBackendID}}).AnyTimes() + + c, err := New(cfg) + require.NoError(t, err) + + scrape := func() string { + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rec := httptest.NewRecorder() + provider.PrometheusHandler().ServeHTTP(rec, req) + return rec.Body.String() + } + + assert.Contains(t, scrape(), "stacklok_vmcp_mcp_server_health", + "gauge must be emitted while the core is live") + + require.NoError(t, c.Close()) + + assert.NotContains(t, scrape(), "stacklok_vmcp_mcp_server_health", + "gauge callback must be unregistered by Close") + + // The SDK's Unregister is safe twice; prove a telemetry-enabled core survives it. + require.NoError(t, c.Close()) +} + func TestNew_ElicitationRequiredWhenWorkflowElicits(t *testing.T) { t.Parallel() @@ -768,6 +911,56 @@ func TestNew_HealthMonitorOwnedByCore(t *testing.T) { assert.NotNil(t, c.BackendHealth()) } +// TestNew_BackendHealthGaugeReflectsLiveMonitorNotRegistrySnapshot guards +// against the backend-health gauge disagreeing with capability filtering: both +// must consult the same live health.Monitor once one is built and started, +// not the registry's static discovery-time HealthStatus. The registry here +// reports the backend with no HealthStatus set (the zero value, "" — treated +// as healthy for capability filtering); the monitor's health checks fail, so +// once it starts, the gauge must flip to unhealthy rather than keep reporting +// the registry's stale/absent status. +func TestNew_BackendHealthGaugeReflectsLiveMonitorNotRegistrySnapshot(t *testing.T) { + t.Parallel() + + ctx := context.Background() + provider, err := telemetry.NewProvider(ctx, telemetry.Config{ + ServiceName: "core-new-health-gauge-test", + ServiceVersion: "0.0.0", + EnablePrometheusMetricsPath: true, + }) + require.NoError(t, err) + t.Cleanup(func() { _ = provider.Shutdown(ctx) }) + + cfg, m := baseConfig(t) + cfg.TelemetryProvider = provider + backends := []vmcp.Backend{{ID: testBackendID, Name: "be1", BaseURL: "http://be1:8080", TransportType: "sse"}} + m.reg.EXPECT().List(gomock.Any()).Return(backends).AnyTimes() + m.client.EXPECT().ListCapabilities(gomock.Any(), gomock.Any()). + Return(nil, errors.New("backend unreachable")).AnyTimes() + cfg.HealthMonitorConfig = &health.MonitorConfig{ + CheckInterval: 20 * time.Millisecond, + UnhealthyThreshold: 1, + Timeout: time.Second, + } + + c, err := New(cfg) + require.NoError(t, err) + t.Cleanup(func() { _ = c.Close() }) + + // The Prometheus exporter interleaves scope/resource labels alphabetically + // between mcp_server and state, so match on the two labels this test cares + // about plus the trailing value rather than a fully-pinned label set. + unhealthyPoint := regexp.MustCompile( + `stacklok_vmcp_mcp_server_health\{mcp_server="be1",[^}]*state="unhealthy"\} 1`) + require.Eventually(t, func() bool { + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rec := httptest.NewRecorder() + provider.PrometheusHandler().ServeHTTP(rec, req) + return unhealthyPoint.MatchString(rec.Body.String()) + }, 2*time.Second, 10*time.Millisecond, + "the health gauge must reflect the live monitor's unhealthy assessment, not the registry's healthy-by-default snapshot") +} + // TestNew_HealthMonitorDisabledWhenNil verifies a nil HealthMonitorConfig leaves health // monitoring disabled: the core builds no monitor and BackendHealth reports none. func TestNew_HealthMonitorDisabledWhenNil(t *testing.T) { diff --git a/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go b/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go index b804d95c8a..577dd98cc6 100644 --- a/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go +++ b/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go @@ -12,7 +12,9 @@ package backendtelemetry import ( "context" + "errors" "fmt" + "maps" "sync" "time" @@ -22,16 +24,31 @@ import ( "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/auth" mcpparser "github.com/stacklok/toolhive/pkg/mcp" - "github.com/stacklok/toolhive/pkg/telemetry" transporttypes "github.com/stacklok/toolhive/pkg/transport/types" "github.com/stacklok/toolhive/pkg/vmcp" + "github.com/stacklok/toolhive/pkg/vmcp/health" ) -const ( - instrumentationName = "github.com/stacklok/toolhive/pkg/vmcp" -) +const instrumentationName = "github.com/stacklok/toolhive/pkg/vmcp" + +// healthStateLabel is the label key distinguishing the health state a gauge +// point represents. The gauge emits one point per (mcp_server, state) pair, +// covering every possible vmcp.BackendHealthStatus value, for every backend. +const healthStateLabel = "state" + +// healthStates lists every vmcp.BackendHealthStatus value the gauge reports a +// point for, so a dashboard can rely on the series existing (at 0) even for +// states a backend has never been in. +var healthStates = []vmcp.BackendHealthStatus{ + vmcp.BackendHealthy, + vmcp.BackendDegraded, + vmcp.BackendUnhealthy, + vmcp.BackendUnknown, + vmcp.BackendUnauthenticated, +} var ( reclassCounterOnce sync.Once @@ -51,7 +68,7 @@ var ( func RecordRevisionReclassification(ctx context.Context) { reclassCounterOnce.Do(func() { reclassCounter, _ = otel.GetMeterProvider().Meter(instrumentationName).Int64Counter( - "toolhive_vmcp_backend_revision_reclassifications", + "stacklok.vmcp.backend.revision_reclassifications", metric.WithDescription("Number of times a backend's MCP revision was reclassified after a mismatch"), ) }) @@ -61,77 +78,232 @@ func RecordRevisionReclassification(ctx context.Context) { } // MonitorBackends decorates the backend client so it records telemetry on each method call. -// It also emits a gauge for the number of backends discovered once, since the number of backends is static. +// It also registers a live per-backend health gauge (stacklok.vmcp.mcp_server.health) +// whose observable callback reports each backend's current health at every collection. +// +// The gauge callback re-reads registry on every collection rather than tracking backend +// membership in backendHealth itself, so a backend removed from the registry (e.g. via +// list_changed) stops being reported instead of leaving an orphaned series behind. +// +// The returned unregister func releases the gauge callback and must be called when the +// decorated client is no longer in use (e.g. from the owning VMCP's Close), so a future +// rebuild of the backend client does not accumulate callbacks against stale health state. +// +// The returned *HealthProviderSetter lets the caller attach a live health.StatusProvider +// once it becomes available (core.New builds health.Monitor after this call; see +// HealthProviderSetter for why the ordering is a resource-acquisition choice rather +// than a data dependency). Until it's set — or if it's never set because health +// monitoring is disabled — the gauge falls back to registry/record()-derived state +// exactly as before. func MonitorBackends( - ctx context.Context, + _ context.Context, meterProvider metric.MeterProvider, tracerProvider trace.TracerProvider, - backends []vmcp.Backend, + registry vmcp.BackendRegistry, backendClient vmcp.BackendClient, -) (vmcp.BackendClient, error) { +) (vmcp.BackendClient, *HealthProviderSetter, func() error, error) { meter := meterProvider.Meter(instrumentationName) - backendCount, err := meter.Int64Gauge( - "toolhive_vmcp_backends_discovered", - metric.WithDescription("Number of backends discovered"), + // recordedHealth is mutated on request success/failure so the gauge reflects + // live health within one collection interval. It is never seeded here, and is + // pruned to the live backend set by the gauge callback below (membership at + // collection time comes from registry.List either way). + // + // record() classifies each failure through healthStatusForError, so it can set + // BackendHealthy, BackendUnhealthy, or BackendUnauthenticated. The remaining + // states (degraded, unknown) can only come from the registry's own HealthStatus + // (a health monitor's discovery-time assessment), used as a fallback below when + // no live StatusProvider is set or it doesn't track a given backend. + recordedHealth := &backendHealth{states: make(map[string]vmcp.BackendHealthStatus)} + providerSetter := &HealthProviderSetter{} + + // Semconv-named metric, so it carries the semconv bucket set exactly rather + // than the coarser Stacklok proxy preset. + clientOperationDuration, err := meter.Float64Histogram( + "mcp.client.operation.duration", + metric.WithDescription("Duration of MCP client operations"), + metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPSemconv()...), ) if err != nil { - return nil, fmt.Errorf("failed to create backend count gauge: %w", err) + return nil, nil, nil, fmt.Errorf("failed to create client operation duration histogram: %w", err) } - backendCount.Record(ctx, int64(len(backends))) - requestsTotal, err := meter.Int64Counter( - "toolhive_vmcp_backend_requests", - metric.WithDescription("Total number of requests per backend")) - if err != nil { - return nil, fmt.Errorf("failed to create requests total counter: %w", err) - } - errorsTotal, err := meter.Int64Counter( - "toolhive_vmcp_backend_errors", - metric.WithDescription("Total number of errors per backend")) - if err != nil { - return nil, fmt.Errorf("failed to create errors total counter: %w", err) - } - requestsDuration, err := meter.Float64Histogram( - "toolhive_vmcp_backend_requests_duration", - metric.WithDescription("Duration of requests in seconds per backend"), - metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + healthGauge, err := meter.Int64ObservableGauge( + "stacklok.vmcp.mcp_server.health", + metric.WithDescription("Per-backend health: 1 for the observed state, 0 otherwise, per (mcp_server, state)"), ) if err != nil { - return nil, fmt.Errorf("failed to create requests duration histogram: %w", err) + return nil, nil, nil, fmt.Errorf("failed to create backend health gauge: %w", err) } - clientOperationDuration, err := meter.Float64Histogram( - "mcp.client.operation.duration", - metric.WithDescription("Duration of MCP client operations"), - metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + registration, err := meter.RegisterCallback( + func(ctx context.Context, o metric.Observer) error { + states := recordedHealth.snapshot() + provider := providerSetter.get() + backends := registry.List(ctx) + live := make(map[string]struct{}, len(backends)) + for _, backend := range backends { + live[backend.ID] = struct{}{} + current := currentHealthStatus(backend, states, provider) + for _, state := range healthStates { + value := int64(0) + if state == current { + value = 1 + } + o.ObserveInt64(healthGauge, value, metric.WithAttributes( + attribute.String(coremetrics.LabelMCPServer, backend.Name), + attribute.String(healthStateLabel, string(state)), + )) + } + } + // Bound the recorded-health map to the live backend set, so its growth + // matches the gauge's rather than the process lifetime. + recordedHealth.retain(live) + return nil + }, + healthGauge, ) if err != nil { - return nil, fmt.Errorf("failed to create client operation duration histogram: %w", err) + return nil, nil, nil, fmt.Errorf("failed to register backend health callback: %w", err) } - return telemetryBackendClient{ + return &telemetryBackendClient{ backendClient: backendClient, tracer: tracerProvider.Tracer(instrumentationName), - requestsTotal: requestsTotal, - errorsTotal: errorsTotal, - requestsDuration: requestsDuration, + health: recordedHealth, clientOperationDuration: clientOperationDuration, - }, nil + }, providerSetter, registration.Unregister, nil +} + +// currentHealthStatus resolves a backend's health for the gauge callback. When a +// live health.StatusProvider is set, its tracked status wins outright — and if it +// doesn't track this backend, the registry's discovery-time snapshot is used +// directly. This matches filterHealthyBackends's precedence exactly whenever a +// provider is set (tracked or not), so the two agree in that case. +// +// When no provider is set at all (health monitoring disabled, or not yet wired up +// during startup), the gauge instead consults the request-outcome map record() +// maintains, giving it a live-ish signal instead of a snapshot frozen at discovery +// time. filterHealthyBackends has no equivalent fallback and always uses the +// registry snapshot when there's no provider. This is the actual — and only — +// divergence window: whenever provider == nil and record() has observed at least +// one outcome for a backend, the gauge and filterHealthyBackends can disagree +// until a health.StatusProvider is attached and starts tracking that backend. +// +// An empty/zero-value HealthStatus (no source has classified the backend yet) is +// normalized to BackendHealthy, matching filterHealthyBackends's "empty/zero-value: +// assume healthy" convention — otherwise none of healthStates would match and the +// gauge would silently report every state as 0 for that backend instead of a +// definite one. +func currentHealthStatus( + backend vmcp.Backend, recorded map[string]vmcp.BackendHealthStatus, provider health.StatusProvider, +) vmcp.BackendHealthStatus { + status := backend.HealthStatus + if provider != nil { + if s, tracked := provider.QueryBackendStatus(backend.ID); tracked { + status = s + } + } else if s, ok := recorded[backend.ID]; ok { + status = s + } + if status == "" { + return vmcp.BackendHealthy + } + return status +} + +// HealthProviderSetter lets core.New attach a live health.StatusProvider to an +// already-registered health gauge once the health.Monitor is built. +// +// The ordering is not a data dependency: buildHealthMonitor deliberately +// constructs the monitor from the UNDECORATED client so health checks emit no +// backend telemetry, so the monitor could in principle be built first. The +// two-phase init exists to keep the gauge's registration — and therefore its +// unregister func, the resource New must release on failure — acquired at a +// single point early in New, rather than ordering resource acquisition around +// the monitor. Building the monitor first would move more of New's error paths +// above the gauge registration. +// +// Safe for concurrent use: Set is called at most once from New, and get() may run +// concurrently from the gauge's observable callback. +type HealthProviderSetter struct { + mu sync.RWMutex + provider health.StatusProvider +} + +// Set attaches provider so the health gauge callback prefers it over the +// registry/record()-derived fallback. A nil provider (health monitoring +// disabled or failed to start) is a valid, explicit no-op. +func (s *HealthProviderSetter) Set(provider health.StatusProvider) { + s.mu.Lock() + defer s.mu.Unlock() + s.provider = provider +} + +func (s *HealthProviderSetter) get() health.StatusProvider { + s.mu.RLock() + defer s.mu.RUnlock() + return s.provider +} + +// backendHealth tracks the latest observed health of each backend, keyed by +// workload ID (the same identity space as the registry and health.StatusProvider, +// so a backend rename can't cause a stale/duplicate entry). It is read by the +// observable-gauge callback and written on each request's success/failure, so +// the gauge reflects live health. +// +// set() receives BackendHealthy, BackendUnhealthy, or BackendUnauthenticated — +// whatever healthStatusForError classifies a failure as. The remaining states +// (degraded, unknown) can only come from the registry's own HealthStatus, used as +// a fallback for backends the map has no entry for yet (see MonitorBackends). +// +// The map is bounded by retain(), called from the gauge callback with the live +// registry set; without it set() would add an entry per distinct workload ID and +// nothing would ever remove one. +type backendHealth struct { + mu sync.RWMutex + states map[string]vmcp.BackendHealthStatus +} + +func (b *backendHealth) set(name string, status vmcp.BackendHealthStatus) { + b.mu.Lock() + defer b.mu.Unlock() + b.states[name] = status +} + +func (b *backendHealth) snapshot() map[string]vmcp.BackendHealthStatus { + b.mu.RLock() + defer b.mu.RUnlock() + out := make(map[string]vmcp.BackendHealthStatus, len(b.states)) + maps.Copy(out, b.states) + return out +} + +// retain drops every entry whose key is absent from live, bounding the map to the +// backends the registry currently knows about. set() adds an entry per distinct +// WorkloadID and nothing else removes one, so under dynamic discovery +// (list_changed, K8s watcher churn) the map would otherwise grow for the process +// lifetime over an ID space the process does not control — and snapshot() copies +// all of it on every collection. +func (b *backendHealth) retain(live map[string]struct{}) { + b.mu.Lock() + defer b.mu.Unlock() + for id := range b.states { + if _, ok := live[id]; !ok { + delete(b.states, id) + } + } } type telemetryBackendClient struct { backendClient vmcp.BackendClient tracer trace.Tracer + health *backendHealth - requestsTotal metric.Int64Counter - errorsTotal metric.Int64Counter - requestsDuration metric.Float64Histogram clientOperationDuration metric.Float64Histogram } -var _ vmcp.BackendClient = telemetryBackendClient{} +var _ vmcp.BackendClient = (*telemetryBackendClient)(nil) // CachedRevision forwards to the wrapped client's optional vmcp.RevisionReporter so // callers reaching the client THROUGH this decorator (e.g. the health monitor) @@ -153,6 +325,39 @@ func (t telemetryBackendClient) revisionLabel(workloadID string) string { return "" } +// healthStatusForError classifies a failed backend call into the health state the +// gauge should report, or (_, false) when the error says nothing about backend +// liveness and the gauge must be left untouched. +// +// Not every error means the backend is unhealthy. A caller that disconnects +// mid-call yields context.Canceled/DeadlineExceeded, which is caller-side; and an +// auth failure has its own state in the gauge's vocabulary. Treating either as +// BackendUnhealthy pins the gauge — and any alert reading it — until the next +// successful call to that backend. +// +// Caller-side cancellation is matched on vmcp.ErrCancelled/ErrTimeout, not on +// context.Canceled/DeadlineExceeded: client.wrapBackendError formats the origin +// error with %v and wraps only the domain sentinel with %w, so the context +// sentinels are not in the chain by the time an error reaches here. Matching them +// would compile and read correctly while never firing. health.categorizeError +// checks the same domain sentinels for the same reason. +// +// Auth errors map to BackendUnauthenticated to match health.categorizeError's +// vocabulary, though this cannot consult the target's AuthConfig the way +// health.authErrorStatus does, so it does not distinguish an expected auth +// challenge from a misconfiguration. +func healthStatusForError(err error) (vmcp.BackendHealthStatus, bool) { + switch { + case errors.Is(err, vmcp.ErrCancelled), errors.Is(err, vmcp.ErrTimeout), + errors.Is(err, context.Canceled), errors.Is(err, context.DeadlineExceeded): + return "", false + case errors.Is(err, vmcp.ErrAuthenticationFailed), errors.Is(err, vmcp.ErrAuthorizationFailed): + return vmcp.BackendUnauthenticated, true + default: + return vmcp.BackendUnhealthy, true + } +} + // mapActionToMCPMethod maps internal action names to MCP method names per the OTEL MCP spec. func mapActionToMCPMethod(action string) string { switch action { @@ -181,7 +386,7 @@ func mapTransportTypeToNetworkTransport(transportType string) string { // record updates the metrics and creates a span for each method on the BackendClient interface. // It returns a function that should be deferred to record the duration, error, and end the span. -func (t telemetryBackendClient) record( +func (t *telemetryBackendClient) record( ctx context.Context, target *vmcp.BackendTarget, action string, targetName string, err *error, attrs ...attribute.KeyValue, ) (context.Context, func()) { mcpMethod := mapActionToMCPMethod(action) @@ -215,21 +420,19 @@ func (t telemetryBackendClient) record( trace.WithSpanKind(trace.SpanKindClient), ) - // Attributes for legacy metrics - legacyMetricAttrs := metric.WithAttributes(commonAttrs...) - - // Attributes for mcp.client.operation.duration (spec-required) + // Attributes for mcp.client.operation.duration (spec-required + bounded + // backend identity so per-backend latency/error rate stays queryable — + // the deleted toolhive_vmcp_backend_requests_duration twin carried this). specMetricAttrs := metric.WithAttributes( attribute.String("mcp.method.name", mcpMethod), attribute.String("network.transport", networkTransport), + attribute.String(coremetrics.LabelMCPServer, target.WorkloadName), ) start := time.Now() - t.requestsTotal.Add(ctx, 1, legacyMetricAttrs) return ctx, func() { duration := time.Since(start) - t.requestsDuration.Record(ctx, duration.Seconds(), legacyMetricAttrs) // Record mcp.client.operation.duration with spec attributes if err != nil && *err != nil { @@ -237,21 +440,25 @@ func (t telemetryBackendClient) record( specMetricAttrsWithError := metric.WithAttributes( attribute.String("mcp.method.name", mcpMethod), attribute.String("network.transport", networkTransport), + attribute.String(coremetrics.LabelMCPServer, target.WorkloadName), attribute.String("error.type", fmt.Sprintf("%T", *err)), ) t.clientOperationDuration.Record(ctx, duration.Seconds(), specMetricAttrsWithError) - t.errorsTotal.Add(ctx, 1, legacyMetricAttrs) + if status, ok := healthStatusForError(*err); ok { + t.health.set(target.WorkloadID, status) + } span.RecordError(*err) span.SetStatus(codes.Error, (*err).Error()) } else { t.clientOperationDuration.Record(ctx, duration.Seconds(), specMetricAttrs) + t.health.set(target.WorkloadID, vmcp.BackendHealthy) } span.End() } } -func (t telemetryBackendClient) CallTool( +func (t *telemetryBackendClient) CallTool( ctx context.Context, target *vmcp.BackendTarget, toolName string, @@ -272,7 +479,7 @@ func (t telemetryBackendClient) CallTool( return t.backendClient.CallTool(ctx, target, toolName, arguments, meta, paramHeaders) } -func (t telemetryBackendClient) ReadResource( +func (t *telemetryBackendClient) ReadResource( ctx context.Context, target *vmcp.BackendTarget, uri string, ) (_ *vmcp.ResourceReadResult, retErr error) { // Use empty targetName to avoid unbounded URI cardinality in span names. @@ -290,7 +497,7 @@ func (t telemetryBackendClient) ReadResource( return t.backendClient.ReadResource(ctx, target, uri) } -func (t telemetryBackendClient) GetPrompt( +func (t *telemetryBackendClient) GetPrompt( ctx context.Context, target *vmcp.BackendTarget, name string, arguments map[string]any, ) (_ *vmcp.PromptGetResult, retErr error) { attrs := []attribute.KeyValue{ @@ -306,7 +513,7 @@ func (t telemetryBackendClient) GetPrompt( return t.backendClient.GetPrompt(ctx, target, name, arguments) } -func (t telemetryBackendClient) Complete( +func (t *telemetryBackendClient) Complete( ctx context.Context, target *vmcp.BackendTarget, ref vmcp.CompletionRef, @@ -326,7 +533,7 @@ func (t telemetryBackendClient) Complete( return t.backendClient.Complete(ctx, target, ref, argName, argValue, contextArgs) } -func (t telemetryBackendClient) ListCapabilities( +func (t *telemetryBackendClient) ListCapabilities( ctx context.Context, target *vmcp.BackendTarget, ) (_ *vmcp.CapabilityList, retErr error) { ctx, done := t.record(ctx, target, "list_capabilities", "", &retErr) diff --git a/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go b/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go index 5a43f7605e..25aad11e51 100644 --- a/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go +++ b/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go @@ -5,10 +5,24 @@ package backendtelemetry import ( "context" + "errors" + "fmt" + "sync" "testing" + "time" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/attribute" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + tracenoop "go.opentelemetry.io/otel/trace/noop" + "go.uber.org/mock/gomock" + + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" mcpparser "github.com/stacklok/toolhive/pkg/mcp" "github.com/stacklok/toolhive/pkg/vmcp" + vmcpmocks "github.com/stacklok/toolhive/pkg/vmcp/mocks" ) // fakeRevClient embeds vmcp.BackendClient (nil — its methods are never called @@ -109,3 +123,428 @@ func TestMapTransportTypeToNetworkTransport(t *testing.T) { }) } } + +// healthPoints collects stacklok.vmcp.mcp_server.health and returns, per +// backend name, the single vmcp.BackendHealthStatus value currently reporting +// 1. It also asserts every other state in healthStates reports 0 for that +// backend, so a collapse back to a two-value (healthy/unhealthy) gauge would +// fail this helper's invariant even if the "current" value alone looked right. +func healthPoints(t *testing.T, reader sdkmetric.Reader) map[string]string { + t.Helper() + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + current := map[string]string{} + seen := map[string]map[string]int64{} + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name != "stacklok.vmcp.mcp_server.health" { + continue + } + gauge, ok := m.Data.(metricdata.Gauge[int64]) + require.True(t, ok, "gauge must be an int64 Gauge") + for _, dp := range gauge.DataPoints { + name, hasName := dp.Attributes.Value(attribute.Key(coremetrics.LabelMCPServer)) + require.True(t, hasName, "mcp_server label must be present") + state, hasState := dp.Attributes.Value(attribute.Key(healthStateLabel)) + require.True(t, hasState, "state label must be present") + + if seen[name.AsString()] == nil { + seen[name.AsString()] = map[string]int64{} + } + seen[name.AsString()][state.AsString()] = dp.Value + if dp.Value == 1 { + current[name.AsString()] = state.AsString() + } + } + } + } + + for backend, points := range seen { + require.Len(t, points, len(healthStates), + "backend %q must report one point per possible health state", backend) + for _, state := range healthStates { + value, ok := points[string(state)] + require.True(t, ok, "backend %q missing a point for state %q", backend, state) + if string(state) != current[backend] { + assert.Equal(t, int64(0), value, "backend %q state %q must be 0 when not current", backend, state) + } + } + } + + return current +} + +func TestMonitorBackends_HealthGaugeReportsRegistryStatusBeyondHealthyUnhealthy(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + registry.EXPECT().List(gomock.Any()).Return([]vmcp.Backend{ + {ID: "be1", Name: "degraded-backend", HealthStatus: vmcp.BackendDegraded}, + {ID: "be2", Name: "unauthenticated-backend", HealthStatus: vmcp.BackendUnauthenticated}, + }).AnyTimes() + + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + // record() only ever distinguishes success/failure, so before any request + // completes for these backends, the gauge must surface the registry's own + // finer-grained status rather than collapsing it to healthy/unhealthy. + _, _, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, vmcpmocks.NewMockBackendClient(ctrl), + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + assert.Equal(t, map[string]string{ + "degraded-backend": string(vmcp.BackendDegraded), + "unauthenticated-backend": string(vmcp.BackendUnauthenticated), + }, healthPoints(t, reader)) +} + +func TestMonitorBackends_HealthGaugeNormalizesEmptyHealthStatusToHealthy(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + // No HealthStatus set (zero value) and no request has completed yet, so + // nothing classifies this backend — matches filterHealthyBackends's + // "empty/zero-value: assume healthy" convention rather than reporting + // every healthStates point as 0. + registry.EXPECT().List(gomock.Any()).Return([]vmcp.Backend{ + {ID: "be1", Name: "unclassified-backend"}, + }).AnyTimes() + + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + _, _, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, vmcpmocks.NewMockBackendClient(ctrl), + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + assert.Equal(t, map[string]string{"unclassified-backend": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) +} + +// fakeStatusProvider is a minimal health.StatusProvider stub so tests can pin +// a specific per-backend status without constructing a full health.Monitor. +type fakeStatusProvider struct { + statuses map[string]vmcp.BackendHealthStatus +} + +func (f *fakeStatusProvider) QueryBackendStatus(backendID string) (vmcp.BackendHealthStatus, bool) { + status, tracked := f.statuses[backendID] + return status, tracked +} + +func TestMonitorBackends_HealthGaugeMatchesFilterHealthyBackendsPrecedence(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + // Registry snapshot says healthy. The live provider disagrees — it must win, + // exactly as filterHealthyBackends prefers it over the registry snapshot. + registry.EXPECT().List(gomock.Any()).Return([]vmcp.Backend{ + {ID: "be1", Name: "backend-1", HealthStatus: vmcp.BackendHealthy}, + }).AnyTimes() + + baseClient := vmcpmocks.NewMockBackendClient(ctrl) + target := &vmcp.BackendTarget{WorkloadID: "be1", WorkloadName: "backend-1", TransportType: "sse"} + + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + decorated, setter, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, baseClient, + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + // record() sees a failure, so the request-outcome map disagrees with the + // registry: recorded=unhealthy, registry=healthy. This divergence is what + // makes the later "provider set but doesn't track" step unambiguous. + baseClient.EXPECT().CallTool(gomock.Any(), target, "t", gomock.Any(), gomock.Any(), gomock.Any()). + Return(nil, assert.AnError) + _, err = decorated.CallTool(context.Background(), target, "t", nil, nil, nil) + require.Error(t, err) + + // No provider set yet: falls back to the recorded (request-outcome) state, + // per currentHealthStatus's "no provider: use recorded" branch. + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendUnhealthy)}, healthPoints(t, reader)) + + // The health monitor (built after MonitorBackends, per core.New's ordering) + // now reports this backend as healthy — e.g. after a successful health check. + // The gauge must reflect the live provider immediately, not the recorded + // request-outcome state. + setter.Set(&fakeStatusProvider{statuses: map[string]vmcp.BackendHealthStatus{ + "be1": vmcp.BackendHealthy, + }}) + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) + + // A provider is set but doesn't track this backend (tracked=false): falls + // straight to the registry snapshot, exactly as filterHealthyBackends does — + // NOT to the recorded state, which still disagrees (unhealthy) at this point. + // This is the precedence filterHealthyBackends itself uses, so the gauge and + // capability-filtering agree even in this fallback case. + setter.Set(&fakeStatusProvider{statuses: map[string]vmcp.BackendHealthStatus{}}) + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) + + // A nil provider (monitoring disabled) falls back to the recorded state again. + setter.Set(nil) + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendUnhealthy)}, healthPoints(t, reader)) +} + +func TestMonitorBackends_HealthGaugeTransitionsOnRequestOutcome(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + registry.EXPECT().List(gomock.Any()).Return([]vmcp.Backend{ + {ID: "be1", Name: "backend-1", HealthStatus: vmcp.BackendHealthy}, + }).AnyTimes() + + baseClient := vmcpmocks.NewMockBackendClient(ctrl) + target := &vmcp.BackendTarget{WorkloadID: "be1", WorkloadName: "backend-1", TransportType: "sse"} + + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + decorated, _, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, baseClient, + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + // No request yet: falls back to the registry's discovery-time HealthStatus. + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) + + baseClient.EXPECT().CallTool(gomock.Any(), target, "t", gomock.Any(), gomock.Any(), gomock.Any()). + Return(nil, errors.New("backend unreachable")) + _, err = decorated.CallTool(context.Background(), target, "t", nil, nil, nil) + require.Error(t, err) + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendUnhealthy)}, healthPoints(t, reader)) + + baseClient.EXPECT().CallTool(gomock.Any(), target, "t", gomock.Any(), gomock.Any(), gomock.Any()). + Return(&vmcp.ToolCallResult{}, nil) + _, err = decorated.CallTool(context.Background(), target, "t", nil, nil, nil) + require.NoError(t, err) + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) +} + +func TestMonitorBackends_HealthGaugeDropsBackendRemovedFromRegistry(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + backends := []vmcp.Backend{ + {ID: "be1", Name: "backend-1", HealthStatus: vmcp.BackendHealthy}, + {ID: "be2", Name: "backend-2", HealthStatus: vmcp.BackendHealthy}, + } + registry.EXPECT().List(gomock.Any()).DoAndReturn( + func(context.Context) []vmcp.Backend { return backends }, + ).AnyTimes() + + baseClient := vmcpmocks.NewMockBackendClient(ctrl) + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + _, _, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, baseClient, + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + assert.Equal(t, map[string]string{ + "backend-1": string(vmcp.BackendHealthy), + "backend-2": string(vmcp.BackendHealthy), + }, healthPoints(t, reader)) + + // Simulate a list_changed-driven removal: the next List call no longer + // includes backend-2. The gauge must stop reporting it, not keep emitting + // its last-known state indefinitely. + backends = backends[:1] + assert.Equal(t, map[string]string{"backend-1": string(vmcp.BackendHealthy)}, healthPoints(t, reader)) +} + +// clientOperationDurationServers returns the mcp_server label value recorded +// on every mcp.client.operation.duration data point. +func clientOperationDurationServers(t *testing.T, reader sdkmetric.Reader) []string { + t.Helper() + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + var servers []string + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name != "mcp.client.operation.duration" { + continue + } + hist, ok := m.Data.(metricdata.Histogram[float64]) + require.True(t, ok, "mcp.client.operation.duration must be a float64 Histogram") + for _, dp := range hist.DataPoints { + name, ok := dp.Attributes.Value(attribute.Key(coremetrics.LabelMCPServer)) + require.True(t, ok, "mcp_server label must be present on mcp.client.operation.duration") + servers = append(servers, name.AsString()) + } + } + } + return servers +} + +func TestMonitorBackends_ClientOperationDurationCarriesBackendIdentity(t *testing.T) { + t.Parallel() + + ctrl := gomock.NewController(t) + registry := vmcpmocks.NewMockBackendRegistry(ctrl) + registry.EXPECT().List(gomock.Any()).Return([]vmcp.Backend{ + {ID: "be1", Name: "backend-1", HealthStatus: vmcp.BackendHealthy}, + }).AnyTimes() + + baseClient := vmcpmocks.NewMockBackendClient(ctrl) + target := &vmcp.BackendTarget{WorkloadID: "be1", WorkloadName: "backend-1", TransportType: "sse"} + + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + decorated, _, unregister, err := MonitorBackends( + context.Background(), mp, tracenoop.NewTracerProvider(), registry, baseClient, + ) + require.NoError(t, err) + t.Cleanup(func() { assert.NoError(t, unregister()) }) + + baseClient.EXPECT().CallTool(gomock.Any(), target, "t", gomock.Any(), gomock.Any(), gomock.Any()). + Return(&vmcp.ToolCallResult{}, nil) + _, err = decorated.CallTool(context.Background(), target, "t", nil, nil, nil) + require.NoError(t, err) + + baseClient.EXPECT().CallTool(gomock.Any(), target, "t", gomock.Any(), gomock.Any(), gomock.Any()). + Return(nil, errors.New("backend unreachable")) + _, err = decorated.CallTool(context.Background(), target, "t", nil, nil, nil) + require.Error(t, err) + + // Both the success and error data points must carry the backend identity — + // without it, per-backend latency/error-rate breakdown is impossible. + assert.Equal(t, []string{"backend-1", "backend-1"}, clientOperationDurationServers(t, reader)) +} + +func TestBackendHealth_ConcurrentSetAndSnapshot(t *testing.T) { + t.Parallel() + + health := &backendHealth{states: make(map[string]vmcp.BackendHealthStatus)} + + var wg sync.WaitGroup + for i := range 50 { + wg.Go(func() { + status := vmcp.BackendUnhealthy + if i%2 == 0 { + status = vmcp.BackendHealthy + } + health.set("backend-1", status) + }) + } + wg.Go(func() { + for range 50 { + _ = health.snapshot() + } + }) + + done := make(chan struct{}) + go func() { wg.Wait(); close(done) }() + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("timeout waiting for concurrent set/snapshot goroutines") + } + + // Race-detector coverage is the point of this test; the exact final value + // is non-deterministic, so only assert the key is present. + _, recorded := health.snapshot()["backend-1"] + assert.True(t, recorded) +} + +func TestHealthStatusForError(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + err error + wantStatus vmcp.BackendHealthStatus + wantOK bool + }{ + { + // A caller that disconnects mid-call says nothing about the backend. + name: "context canceled leaves the gauge untouched", + err: context.Canceled, + wantOK: false, + }, + { + name: "deadline exceeded leaves the gauge untouched", + err: context.DeadlineExceeded, + wantOK: false, + }, + { + name: "wrapped cancellation is still recognized", + err: fmt.Errorf("call backend: %w", context.Canceled), + wantOK: false, + }, + { + // The shape the real client produces: wrapBackendError wraps only the + // domain sentinel with %w and formats the origin error with %v, so the + // context sentinel is NOT in the chain. Matching context.Canceled alone + // compiles and reads correctly while never firing on a real call. + name: "client-shaped cancellation leaves the gauge untouched", + err: fmt.Errorf("%w: failed to call tool for backend wl-1 (cancelled): %v", vmcp.ErrCancelled, context.Canceled), + wantOK: false, + }, + { + name: "client-shaped timeout leaves the gauge untouched", + err: fmt.Errorf("%w: failed to call tool for backend wl-1 (timeout): %v", vmcp.ErrTimeout, context.DeadlineExceeded), + wantOK: false, + }, + { + name: "authentication failure maps to unauthenticated", + err: vmcp.ErrAuthenticationFailed, + wantStatus: vmcp.BackendUnauthenticated, + wantOK: true, + }, + { + name: "authorization failure maps to unauthenticated", + err: fmt.Errorf("wrapped: %w", vmcp.ErrAuthorizationFailed), + wantStatus: vmcp.BackendUnauthenticated, + wantOK: true, + }, + { + name: "an unrecognized error means unhealthy", + err: errors.New("connection refused"), + wantStatus: vmcp.BackendUnhealthy, + wantOK: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + status, ok := healthStatusForError(tt.err) + assert.Equal(t, tt.wantOK, ok) + if tt.wantOK { + assert.Equal(t, tt.wantStatus, status) + } + }) + } +} + +func TestBackendHealthRetainPrunesAbsentKeys(t *testing.T) { + t.Parallel() + + b := &backendHealth{states: make(map[string]vmcp.BackendHealthStatus)} + b.set("live", vmcp.BackendHealthy) + b.set("removed", vmcp.BackendUnhealthy) + + b.retain(map[string]struct{}{"live": {}}) + + got := b.snapshot() + assert.Equal(t, map[string]vmcp.BackendHealthStatus{"live": vmcp.BackendHealthy}, got, + "entries absent from the live set must be pruned so the map cannot grow unbounded") +} diff --git a/pkg/vmcp/server/sessionmanager/factory.go b/pkg/vmcp/server/sessionmanager/factory.go index 73bbc3e9f5..54d7f1a0db 100644 --- a/pkg/vmcp/server/sessionmanager/factory.go +++ b/pkg/vmcp/server/sessionmanager/factory.go @@ -18,6 +18,7 @@ import ( "github.com/stacklok/toolhive-core/mcpcompat/mcp" mcpserver "github.com/stacklok/toolhive-core/mcpcompat/server" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/auth" "github.com/stacklok/toolhive/pkg/telemetry" "github.com/stacklok/toolhive/pkg/vmcp" @@ -35,6 +36,11 @@ const instrumentationName = "github.com/stacklok/toolhive/pkg/vmcp" // CacheCapacity from a config does not silently enable unbounded growth. const defaultCacheCapacity = 1000 +// outcomeNotFound extends the standard coremetrics.OutcomeSuccess/OutcomeError +// pair with a third CallTool-specific terminal state: the tool ran without +// error but reported IsError, meaning the optimizer couldn't resolve it. +const outcomeNotFound = "not_found" + // FactoryConfig holds the session factory construction parameters that the // session manager needs to build its decorating factory. It is separate from // server.Config to avoid a circular import between the server and sessionmanager @@ -269,33 +275,25 @@ func monitorOptimizer( meter := meterProvider.Meter(instrumentationName) findToolRequests, err := meter.Int64Counter( - "toolhive_vmcp_optimizer_find_tool_requests", - metric.WithDescription("Total number of FindTool calls"), + "stacklok.vmcp.optimizer.find_tool.requests", + metric.WithDescription("Total number of FindTool calls, split by outcome"), ) if err != nil { return nil, fmt.Errorf("failed to create find_tool requests counter: %w", err) } - findToolErrors, err := meter.Int64Counter( - "toolhive_vmcp_optimizer_find_tool_errors", - metric.WithDescription("Total number of FindTool errors"), - ) - if err != nil { - return nil, fmt.Errorf("failed to create find_tool errors counter: %w", err) - } - findToolDuration, err := meter.Float64Histogram( - "toolhive_vmcp_optimizer_find_tool_duration", + "stacklok.vmcp.optimizer.find_tool.duration", metric.WithDescription("Duration of FindTool calls in seconds"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) if err != nil { return nil, fmt.Errorf("failed to create find_tool duration histogram: %w", err) } findToolResults, err := meter.Float64Histogram( - "toolhive_vmcp_optimizer_find_tool_results", + "stacklok.vmcp.optimizer.find_tool.results", metric.WithDescription("Number of tools returned per FindTool call"), metric.WithUnit("{tools}"), metric.WithExplicitBucketBoundaries(0, 1, 2, 3, 5, 10, 20, 50), @@ -305,7 +303,7 @@ func monitorOptimizer( } tokenSavingsPercent, err := meter.Float64Histogram( - "toolhive_vmcp_optimizer_token_savings_percent", + "stacklok.vmcp.optimizer.token_savings", metric.WithDescription("Token savings percentage per FindTool call"), metric.WithUnit("%"), metric.WithExplicitBucketBoundaries(0, 10, 20, 30, 40, 50, 60, 70, 80, 90, 95, 99, 100), @@ -315,34 +313,18 @@ func monitorOptimizer( } callToolRequests, err := meter.Int64Counter( - "toolhive_vmcp_optimizer_call_tool_requests", - metric.WithDescription("Total number of CallTool calls"), + "stacklok.vmcp.optimizer.call_tool.requests", + metric.WithDescription("Total number of CallTool calls, split by outcome (success, error, not_found)"), ) if err != nil { return nil, fmt.Errorf("failed to create call_tool requests counter: %w", err) } - callToolErrors, err := meter.Int64Counter( - "toolhive_vmcp_optimizer_call_tool_errors", - metric.WithDescription("Total number of CallTool Go errors"), - ) - if err != nil { - return nil, fmt.Errorf("failed to create call_tool errors counter: %w", err) - } - - callToolNotFound, err := meter.Int64Counter( - "toolhive_vmcp_optimizer_call_tool_not_found", - metric.WithDescription("Total number of CallTool calls where result.IsError is true"), - ) - if err != nil { - return nil, fmt.Errorf("failed to create call_tool not_found counter: %w", err) - } - callToolDuration, err := meter.Float64Histogram( - "toolhive_vmcp_optimizer_call_tool_duration", + "stacklok.vmcp.optimizer.call_tool.duration", metric.WithDescription("Duration of CallTool calls in seconds"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(telemetry.MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) if err != nil { return nil, fmt.Errorf("failed to create call_tool duration histogram: %w", err) @@ -359,13 +341,10 @@ func monitorOptimizer( optimizer: opt, tracer: tracer, findToolRequests: findToolRequests, - findToolErrors: findToolErrors, findToolDuration: findToolDuration, findToolResults: findToolResults, tokenSavingsPercent: tokenSavingsPercent, callToolRequests: callToolRequests, - callToolErrors: callToolErrors, - callToolNotFound: callToolNotFound, callToolDuration: callToolDuration, }, nil } @@ -378,14 +357,11 @@ type telemetryOptimizer struct { tracer trace.Tracer findToolRequests metric.Int64Counter - findToolErrors metric.Int64Counter findToolDuration metric.Float64Histogram findToolResults metric.Float64Histogram tokenSavingsPercent metric.Float64Histogram callToolRequests metric.Int64Counter - callToolErrors metric.Int64Counter - callToolNotFound metric.Int64Counter callToolDuration metric.Float64Histogram } @@ -398,7 +374,6 @@ func (t *telemetryOptimizer) FindTool(ctx context.Context, input optimizer.FindT defer span.End() start := time.Now() - t.findToolRequests.Add(ctx, 1) result, err := t.optimizer.FindTool(ctx, input) @@ -406,12 +381,13 @@ func (t *telemetryOptimizer) FindTool(ctx context.Context, input optimizer.FindT t.findToolDuration.Record(ctx, duration.Seconds()) if err != nil { - t.findToolErrors.Add(ctx, 1) + t.findToolRequests.Add(ctx, 1, metric.WithAttributes(attribute.String(coremetrics.LabelOutcome, coremetrics.OutcomeError))) span.RecordError(err) span.SetStatus(codes.Error, err.Error()) return nil, err } + t.findToolRequests.Add(ctx, 1, metric.WithAttributes(attribute.String(coremetrics.LabelOutcome, coremetrics.OutcomeSuccess))) t.findToolResults.Record(ctx, float64(len(result.Tools))) t.tokenSavingsPercent.Record(ctx, result.TokenMetrics.SavingsPercent) @@ -419,32 +395,35 @@ func (t *telemetryOptimizer) FindTool(ctx context.Context, input optimizer.FindT } func (t *telemetryOptimizer) CallTool(ctx context.Context, input optimizer.CallToolInput) (*mcp.CallToolResult, error) { - toolAttr := attribute.String("tool_name", input.ToolName) - ctx, span := t.tracer.Start(ctx, "optimizer.CallTool", - trace.WithAttributes(toolAttr), + trace.WithAttributes(attribute.String("tool_name", input.ToolName)), ) defer span.End() - metricAttrs := metric.WithAttributes(toolAttr) + durationAttrs := metric.WithAttributes(attribute.String(coremetrics.LabelToolName, input.ToolName)) start := time.Now() - t.callToolRequests.Add(ctx, 1, metricAttrs) result, err := t.optimizer.CallTool(ctx, input) duration := time.Since(start) - t.callToolDuration.Record(ctx, duration.Seconds(), metricAttrs) + t.callToolDuration.Record(ctx, duration.Seconds(), durationAttrs) + + outcome := coremetrics.OutcomeSuccess + if err != nil { + outcome = coremetrics.OutcomeError + } else if result != nil && result.IsError { + outcome = outcomeNotFound + } + t.callToolRequests.Add(ctx, 1, metric.WithAttributes( + attribute.String(coremetrics.LabelToolName, input.ToolName), + attribute.String(coremetrics.LabelOutcome, outcome), + )) if err != nil { - t.callToolErrors.Add(ctx, 1, metricAttrs) span.RecordError(err) span.SetStatus(codes.Error, err.Error()) return nil, err } - if result != nil && result.IsError { - t.callToolNotFound.Add(ctx, 1, metricAttrs) - } - return result, nil } diff --git a/pkg/vmcp/server/sessionmanager/telemetry_test.go b/pkg/vmcp/server/sessionmanager/telemetry_test.go index 332b62d73c..2073ca113e 100644 --- a/pkg/vmcp/server/sessionmanager/telemetry_test.go +++ b/pkg/vmcp/server/sessionmanager/telemetry_test.go @@ -16,6 +16,7 @@ import ( "github.com/stacklok/toolhive-core/mcpcompat/mcp" mcpserver "github.com/stacklok/toolhive-core/mcpcompat/server" + coremetrics "github.com/stacklok/toolhive-core/telemetry/metrics" "github.com/stacklok/toolhive/pkg/vmcp/optimizer" ) @@ -45,9 +46,10 @@ func findMetric(rm metricdata.ResourceMetrics, name string) *metricdata.Metrics return nil } -// counterValue returns the sum of all data points for an Int64 counter metric. -// Returns 0 if m is nil (metric not reported because it was never incremented). -func counterValue(m *metricdata.Metrics) int64 { +// counterValueForOutcome sums the data points of an int64 counter whose +// coremetrics.LabelOutcome attribute equals want. Returns 0 if m is nil or no +// matching point exists. +func counterValueForOutcome(m *metricdata.Metrics, want string) int64 { if m == nil { return 0 } @@ -57,7 +59,9 @@ func counterValue(m *metricdata.Metrics) int64 { } var total int64 for _, dp := range sum.DataPoints { - total += dp.Value + if v, present := dp.Attributes.Value(coremetrics.LabelOutcome); present && v.AsString() == want { + total += dp.Value + } } return total } @@ -117,21 +121,24 @@ func TestTelemetryOptimizer(t *testing.T) { }, assertFunc: func(t *testing.T, rm metricdata.ResourceMetrics) { t.Helper() - m := findMetric(rm, "toolhive_vmcp_optimizer_find_tool_requests") + m := findMetric(rm, "stacklok.vmcp.optimizer.find_tool.requests") require.NotNil(t, m, "find_tool_requests metric should exist") - assert.Equal(t, int64(1), counterValue(m)) - - assert.Equal(t, int64(0), counterValue(findMetric(rm, "toolhive_vmcp_optimizer_find_tool_errors"))) - - m = findMetric(rm, "toolhive_vmcp_optimizer_find_tool_duration") + assert.Equal(t, int64(1), counterValueForOutcome(m, "success"), + `find_tool_requests must increment with outcome="success"`) + assert.Equal(t, int64(0), counterValueForOutcome(m, "error"), + `find_tool_requests must record nothing under outcome="error" on success`) + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.find_tool.errors"), + "the split find_tool_errors counter must no longer exist") + + m = findMetric(rm, "stacklok.vmcp.optimizer.find_tool.duration") require.NotNil(t, m, "find_tool_duration metric should exist") assert.Equal(t, uint64(1), histogramCount(m)) - m = findMetric(rm, "toolhive_vmcp_optimizer_find_tool_results") + m = findMetric(rm, "stacklok.vmcp.optimizer.find_tool.results") require.NotNil(t, m, "find_tool_results metric should exist") assert.Equal(t, uint64(1), histogramCount(m)) - m = findMetric(rm, "toolhive_vmcp_optimizer_token_savings_percent") + m = findMetric(rm, "stacklok.vmcp.optimizer.token_savings") require.NotNil(t, m, "token_savings_percent metric should exist") assert.Equal(t, uint64(1), histogramCount(m)) }, @@ -154,19 +161,20 @@ func TestTelemetryOptimizer(t *testing.T) { }, assertFunc: func(t *testing.T, rm metricdata.ResourceMetrics) { t.Helper() - m := findMetric(rm, "toolhive_vmcp_optimizer_find_tool_requests") + m := findMetric(rm, "stacklok.vmcp.optimizer.find_tool.requests") require.NotNil(t, m) - assert.Equal(t, int64(1), counterValue(m)) - - m = findMetric(rm, "toolhive_vmcp_optimizer_find_tool_errors") - require.NotNil(t, m) - assert.Equal(t, int64(1), counterValue(m)) - - m = findMetric(rm, "toolhive_vmcp_optimizer_find_tool_duration") + assert.Equal(t, int64(1), counterValueForOutcome(m, "error"), + `find_tool_requests must increment with outcome="error" on failure`) + assert.Equal(t, int64(0), counterValueForOutcome(m, "success"), + `find_tool_requests must record nothing under outcome="success" on failure`) + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.find_tool.errors"), + "the split find_tool_errors counter must no longer exist") + + m = findMetric(rm, "stacklok.vmcp.optimizer.find_tool.duration") require.NotNil(t, m) assert.Equal(t, uint64(1), histogramCount(m)) - assert.Equal(t, uint64(0), histogramCount(findMetric(rm, "toolhive_vmcp_optimizer_find_tool_results"))) + assert.Equal(t, uint64(0), histogramCount(findMetric(rm, "stacklok.vmcp.optimizer.find_tool.results"))) }, }, { @@ -190,14 +198,18 @@ func TestTelemetryOptimizer(t *testing.T) { }, assertFunc: func(t *testing.T, rm metricdata.ResourceMetrics) { t.Helper() - m := findMetric(rm, "toolhive_vmcp_optimizer_call_tool_requests") + m := findMetric(rm, "stacklok.vmcp.optimizer.call_tool.requests") require.NotNil(t, m, "call_tool_requests metric should exist") - assert.Equal(t, int64(1), counterValue(m)) - - assert.Equal(t, int64(0), counterValue(findMetric(rm, "toolhive_vmcp_optimizer_call_tool_errors"))) - assert.Equal(t, int64(0), counterValue(findMetric(rm, "toolhive_vmcp_optimizer_call_tool_not_found"))) - - m = findMetric(rm, "toolhive_vmcp_optimizer_call_tool_duration") + assert.Equal(t, int64(1), counterValueForOutcome(m, "success"), + `call_tool_requests must increment with outcome="success"`) + assert.Equal(t, int64(0), counterValueForOutcome(m, "error")) + assert.Equal(t, int64(0), counterValueForOutcome(m, "not_found")) + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.call_tool.errors"), + "the split call_tool_errors counter must no longer exist") + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.call_tool.not_found"), + "the split call_tool_not_found counter must no longer exist") + + m = findMetric(rm, "stacklok.vmcp.optimizer.call_tool.duration") require.NotNil(t, m) assert.Equal(t, uint64(1), histogramCount(m)) }, @@ -221,17 +233,16 @@ func TestTelemetryOptimizer(t *testing.T) { }, assertFunc: func(t *testing.T, rm metricdata.ResourceMetrics) { t.Helper() - m := findMetric(rm, "toolhive_vmcp_optimizer_call_tool_requests") + m := findMetric(rm, "stacklok.vmcp.optimizer.call_tool.requests") require.NotNil(t, m) - assert.Equal(t, int64(1), counterValue(m)) - - assert.Equal(t, int64(0), counterValue(findMetric(rm, "toolhive_vmcp_optimizer_call_tool_errors"))) - - m = findMetric(rm, "toolhive_vmcp_optimizer_call_tool_not_found") - require.NotNil(t, m, "not_found counter should exist") - assert.Equal(t, int64(1), counterValue(m)) - - m = findMetric(rm, "toolhive_vmcp_optimizer_call_tool_duration") + assert.Equal(t, int64(1), counterValueForOutcome(m, "not_found"), + `call_tool_requests must increment with outcome="not_found" when result.IsError is true`) + assert.Equal(t, int64(0), counterValueForOutcome(m, "success")) + assert.Equal(t, int64(0), counterValueForOutcome(m, "error")) + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.call_tool.not_found"), + "the split call_tool_not_found counter must no longer exist") + + m = findMetric(rm, "stacklok.vmcp.optimizer.call_tool.duration") require.NotNil(t, m) assert.Equal(t, uint64(1), histogramCount(m)) }, @@ -254,15 +265,16 @@ func TestTelemetryOptimizer(t *testing.T) { }, assertFunc: func(t *testing.T, rm metricdata.ResourceMetrics) { t.Helper() - m := findMetric(rm, "toolhive_vmcp_optimizer_call_tool_requests") + m := findMetric(rm, "stacklok.vmcp.optimizer.call_tool.requests") require.NotNil(t, m) - assert.Equal(t, int64(1), counterValue(m)) - - m = findMetric(rm, "toolhive_vmcp_optimizer_call_tool_errors") - require.NotNil(t, m) - assert.Equal(t, int64(1), counterValue(m)) - - assert.Equal(t, int64(0), counterValue(findMetric(rm, "toolhive_vmcp_optimizer_call_tool_not_found"))) + assert.Equal(t, int64(1), counterValueForOutcome(m, "error"), + `call_tool_requests must increment with outcome="error" on a Go error`) + assert.Equal(t, int64(0), counterValueForOutcome(m, "success")) + assert.Equal(t, int64(0), counterValueForOutcome(m, "not_found")) + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.call_tool.errors"), + "the split call_tool_errors counter must no longer exist") + assert.Nil(t, findMetric(rm, "stacklok.vmcp.optimizer.call_tool.not_found"), + "the split call_tool_not_found counter must no longer exist") }, }, } diff --git a/pkg/vmcp/server/telemetry_integration_test.go b/pkg/vmcp/server/telemetry_integration_test.go index 0a23b05e43..96df0d2b3b 100644 --- a/pkg/vmcp/server/telemetry_integration_test.go +++ b/pkg/vmcp/server/telemetry_integration_test.go @@ -112,10 +112,10 @@ func (f *backendAwareTestFactory) newSession(id string) *backendAwareTestSession // metrics when the telemetry middleware is enabled via TelemetryProvider. // // This validates: -// 1. Incoming MCP requests are counted by toolhive_mcp_requests -// 2. Request latency is tracked by toolhive_mcp_request_duration -// 3. Backend calls are counted by toolhive_vmcp_backend_requests -// 4. Backend discovery count is reported by toolhive_vmcp_backends_discovered +// 1. Incoming MCP requests are tracked by mcp.server.operation.duration +// 2. Transport-level latency is tracked by http.server.request.duration +// 3. Backend calls are tracked by mcp.client.operation.duration +// 4. Backend health is reported by stacklok.vmcp.mcp_server.health // 5. All metrics are accessible via the /metrics Prometheus endpoint // // Note: This test does not use t.Parallel() because subtests share the same @@ -218,11 +218,11 @@ func TestIntegration_TelemetryMiddleware(t *testing.T) { // Create server with telemetry provider — this also wraps the backend // client with monitorBackends() which instruments outgoing backend calls. // Use backendAwareTestFactory so that CallTool delegates to the monitorBackends-wrapped - // backendClient, ensuring toolhive_vmcp_backend_requests metrics are recorded. + // backendClient, ensuring mcp.client.operation.duration metrics are recorded. // The core sources the advertised set by aggregating over mockBackendClient (prefix // resolver → "search-svc_search"). core.New wraps this same client with monitorBackends // for telemetry, and core.CallTool routes tool calls through that wrapped client — so - // the backend instrumentation (toolhive_vmcp_backend_requests) is exercised without the + // the backend instrumentation (mcp.client.operation.duration) is exercised without the // session factory needing to hold the wrapped client. telemetryAgg := aggregator.NewDefaultAggregator( mockBackendClient, aggregator.NewPrefixConflictResolver("{workload}_"), nil, nil) @@ -335,43 +335,61 @@ func TestIntegration_TelemetryMiddleware(t *testing.T) { require.NoError(t, err) metrics := string(body) - // --- Incoming request metrics (from telemetry middleware in pkg/telemetry/middleware.go) --- - - // Request counter - assert.Contains(t, metrics, "toolhive_mcp_requests", - "Should record incoming request counter") - assert.Contains(t, metrics, `server="telemetry-vmcp"`, - "Request metrics should identify the vMCP server name") + // --- Deleted legacy twins must be absent (single-pass cutover) --- + assert.NotContains(t, metrics, "toolhive_mcp_requests", + "deleted incoming-request counter twin must be gone") + assert.NotContains(t, metrics, "toolhive_mcp_request_duration", + "deleted incoming-request duration twin must be gone") + assert.NotContains(t, metrics, "toolhive_mcp_tool_calls", + "deleted tool-calls twin must be gone") + assert.NotContains(t, metrics, "toolhive_vmcp_backend_requests", + "deleted backend-request counter twin must be gone") + assert.NotContains(t, metrics, "toolhive_vmcp_backend_errors", + "deleted backend-error counter twin must be gone") + assert.NotContains(t, metrics, "toolhive_vmcp_backend_requests_duration", + "deleted backend-request duration twin must be gone") + + // --- Incoming request metrics: semconv replacements (pkg/telemetry/middleware.go) --- + + // mcp.server.operation.duration replaces the incoming request/duration twins + // for MCP-method-bearing requests. Rendered by the exporter to underscores. + assert.Contains(t, metrics, "mcp_server_operation_duration_seconds", + "Should record semconv server operation-duration histogram") + assert.Contains(t, metrics, `mcp_method_name="tools/call"`, + "operation duration should carry mcp.method.name for tool calls") + assert.Contains(t, metrics, `mcp_method_name="initialize"`, + "operation duration should carry mcp.method.name for initialize") + + // http.server.request.duration is the transport-level counterpart recorded + // for every request regardless of MCP method. + assert.Contains(t, metrics, "http_server_request_duration_seconds", + "Should record semconv HTTP server request-duration histogram") + + // Server identity: the central server -> mcp_server rename this branch + // performs is verified end-to-end here, on the one test that scrapes a real + // vMCP /metrics. Without this the rename itself is unasserted anywhere. + assert.Contains(t, metrics, `mcp_server="telemetry-vmcp"`, + "renamed mcp_server label must carry the vMCP server name") + // Anchored on the leading label delimiter: a plain NotContains(`server="..."`) + // is satisfied by mcp_server="..." as a substring and so could never fail. + assert.NotRegexp(t, `[{,]server="telemetry-vmcp"`, metrics, + "the pre-rename server label must be gone") assert.Contains(t, metrics, `transport="streamable-http"`, - "Request metrics should identify the transport type") - - // MCP method labels — the telemetry middleware should distinguish request types - assert.Contains(t, metrics, `mcp_method="tools/call"`, - "Request counter should have mcp_method label for tool calls") - assert.Contains(t, metrics, `mcp_method="initialize"`, - "Request counter should have mcp_method label for initialize") - - // Resource ID label — for tools/call the mcp_resource_id is the tool name - assert.Contains(t, metrics, `mcp_resource_id="search-svc_search"`, - "Request counter should have mcp_resource_id label with the called tool name") - - // Request duration histogram - assert.Contains(t, metrics, "toolhive_mcp_request_duration", - "Should record request duration histogram") + "active-connections gauge must carry the transport label") // --- Backend metrics (from backendtelemetry.MonitorBackends) --- - // Backend request counter — recorded when the tool call was routed to the backend - assert.Contains(t, metrics, "toolhive_vmcp_backend_requests", - "Should record backend request counter from tool call routing") - - // Backend request duration histogram - assert.Contains(t, metrics, "toolhive_vmcp_backend_requests_duration", - "Should record backend request duration histogram") + // mcp.client.operation.duration replaces the backend request/duration twins. + assert.Contains(t, metrics, "mcp_client_operation_duration_seconds", + "Should record semconv client operation-duration histogram from tool call routing") - // Backend discovery gauge — recorded during server.New() for the initial backend list - assert.Contains(t, metrics, "toolhive_vmcp_backends_discovered", - "Should record backend discovery count gauge") + // Backend health gauge — live per-backend health, renamed to stacklok.* + assert.Contains(t, metrics, "stacklok_vmcp_mcp_server_health", + "Should record live per-backend health gauge") + assert.NotContains(t, metrics, "toolhive_vmcp_mcp_server_health", + "the pre-rename health gauge name must be gone") + assert.NotContains(t, metrics, "toolhive_vmcp_backends_discovered", + "The fire-once backends_discovered gauge must be gone") // --- Custom resource attributes (from Config.CustomAttributes) --- // Custom attributes are added to the OTel resource and surface as labels on the @@ -513,10 +531,15 @@ func TestIntegration_TelemetryRunsBeforeClassificationRejection(t *testing.T) { require.NoError(t, err) metrics := string(metricsBody) - assert.Contains(t, metrics, "toolhive_mcp_requests", + // The request is rejected by classificationMiddleware before MCP dispatch, so + // no mcp.server.operation.duration is recorded — but the telemetry middleware + // runs first and records the transport-level http.server.request.duration with + // the rejection status. This is the semconv replacement for the deleted + // toolhive_mcp_requests twin (RFC §3.5). + assert.Contains(t, metrics, "http_server_request_duration_seconds", "telemetry must record the request even though classification rejected it downstream") - assert.Contains(t, metrics, `server="telemetry-ordering-vmcp"`, - "request metrics should identify this vMCP server") + assert.Contains(t, metrics, `http_response_status_code="400"`, + "the rejected request should be recorded with its 400 status") cancelServer() } diff --git a/test/e2e/osv_authz_test.go b/test/e2e/osv_authz_test.go index 9fa7c9c48b..3105214eee 100644 --- a/test/e2e/osv_authz_test.go +++ b/test/e2e/osv_authz_test.go @@ -239,46 +239,42 @@ var _ = Describe("OSV MCP Server with Authorization", Label("middleware", "authz GinkgoWriter.Printf("Metrics response length: %d bytes\n", len(metricsBody)) - // Look for ToolHive-specific metrics - Expect(metricsBody).To(ContainSubstring("toolhive_mcp_requests_total"), - "Should contain ToolHive MCP request counter") + // Look for ToolHive-specific metrics. The legacy toolhive_mcp_requests_total + // twin is deleted (RFC §3.5); http.server.request.duration is its + // transport-level semconv replacement and carries the HTTP status code. + Expect(metricsBody).To(ContainSubstring("http_server_request_duration_seconds"), + "Should contain semconv HTTP server request-duration metric") + + // Authorization outcome is reflected in the HTTP response status code + // for denied requests (403, written synchronously by the authz + // middleware). It is NOT reflected for authorized SSE tool calls: the + // POST to /messages gets a 202 Accepted immediately (the actual + // tools/call result is delivered async over the already-open SSE + // stream), so a successful call never produces an HTTP 200 here. The + // tools/call assertion below verifies the authorized call succeeded. + status403Count := extractMetricValue(metricsBody, "http_server_request_duration_seconds_count", "http_response_status_code=\"403\"") - // Parse and verify metrics contain both success and error status codes - successCount := extractMetricValue(metricsBody, "toolhive_mcp_requests_total", "status=\"success\"") - errorCount := extractMetricValue(metricsBody, "toolhive_mcp_requests_total", "status=\"error\"") - - GinkgoWriter.Printf("Success requests: %d\n", successCount) - GinkgoWriter.Printf("Error requests: %d\n", errorCount) - - // We should have at least 1 successful request (authorized) and 2 error requests (unauthorized) - Expect(successCount).To(BeNumerically(">=", 1), - "Should have at least 1 successful request") - Expect(errorCount).To(BeNumerically(">=", 2), - "Should have at least 2 error requests (authorization denials)") - - // Look for specific status codes - status200Count := extractMetricValue(metricsBody, "toolhive_mcp_requests_total", "status_code=\"200\"") - status403Count := extractMetricValue(metricsBody, "toolhive_mcp_requests_total", "status_code=\"403\"") - - GinkgoWriter.Printf("HTTP 200 responses: %d\n", status200Count) GinkgoWriter.Printf("HTTP 403 responses: %d\n", status403Count) - // We should see 403 responses for authorization denials + // We should have at least 2 authorization denials (403). Expect(status403Count).To(BeNumerically(">=", 2), "Should have at least 2 HTTP 403 responses for authorization denials") - // Look for tool-specific metrics - if strings.Contains(metricsBody, "toolhive_mcp_tool_calls_total") { - toolCallsCount := extractMetricValue(metricsBody, "toolhive_mcp_tool_calls_total", "tool=\"query_vulnerability\"") - GinkgoWriter.Printf("Tool calls for query_vulnerability: %d\n", toolCallsCount) + // Tool calls surface via the semconv server operation-duration histogram + // with mcp_method_name="tools/call" (the toolhive_mcp_tool_calls_total twin + // is deleted). This is the authoritative signal that the authorized + // call succeeded, since it carries no HTTP-status-code caveat. + Expect(metricsBody).To(ContainSubstring("mcp_server_operation_duration_seconds"), + "Should contain semconv MCP server operation-duration metric") + toolCallsCount := extractMetricValue(metricsBody, "mcp_server_operation_duration_seconds_count", "mcp_method_name=\"tools/call\"") + GinkgoWriter.Printf("Tool calls (tools/call): %d\n", toolCallsCount) - Expect(toolCallsCount).To(BeNumerically(">=", 1), - "Should have at least 1 successful tool call for query_vulnerability") - } + Expect(toolCallsCount).To(BeNumerically(">=", 1), + "Should have at least 1 tools/call operation recorded") By("Verifying server name is included in metrics") - Expect(metricsBody).To(ContainSubstring(fmt.Sprintf("server=\"%s\"", serverName)), - "Metrics should include the server name") + Expect(metricsBody).To(ContainSubstring(fmt.Sprintf("mcp_server=\"%s\"", serverName)), + "Metrics should include the MCP server name") GinkgoWriter.Printf("✅ Authorization metrics verification completed successfully\n") GinkgoWriter.Printf("📊 Metrics show proper tracking of authorized vs unauthorized requests\n") diff --git a/test/e2e/telemetry_metrics_validation_e2e_test.go b/test/e2e/telemetry_metrics_validation_e2e_test.go index 4369c4bf41..89218cff11 100644 --- a/test/e2e/telemetry_metrics_validation_e2e_test.go +++ b/test/e2e/telemetry_metrics_validation_e2e_test.go @@ -135,10 +135,12 @@ var _ = Describe("Telemetry Metrics Validation E2E", Label("middleware", "teleme metricsContent := fetchMetricsContent(metricsURL) By("Validating all core ToolHive metrics exist") + // The legacy toolhive_mcp_* twins are deleted (RFC §3.5); assert the + // semconv replacements and the renamed active-connections gauge. expectedMetrics := []string{ - "toolhive_mcp_requests_total", - "toolhive_mcp_request_duration_seconds", - "toolhive_mcp_active_connections", + "mcp_server_operation_duration_seconds", + "http_server_request_duration_seconds", + "stacklok_toolhive_proxy_active_connections", } for _, metric := range expectedMetrics { @@ -146,17 +148,19 @@ var _ = Describe("Telemetry Metrics Validation E2E", Label("middleware", "teleme fmt.Sprintf("Should contain metric: %s", metric)) } - By("Validating no metrics have empty server or transport labels") + By("Validating the active-connections gauge has non-empty server and transport labels") validateNoEmptyLabels(metricsContent, workloadName, "sse") By("Validating metrics contain expected MCP methods") + // mcp.method.name replaces the old mcp_method label, carried on the + // semconv server operation-duration metric. expectedMethods := []string{ "initialize", "tools/list", } for _, method := range expectedMethods { - methodPattern := fmt.Sprintf(`mcp_method="%s"`, method) + methodPattern := fmt.Sprintf(`mcp_method_name="%s"`, method) Expect(metricsContent).To(ContainSubstring(methodPattern), fmt.Sprintf("Should contain MCP method: %s", method)) } @@ -299,8 +303,8 @@ func validateTelemetryMetrics(config *e2e.TestConfig, workloadName, expectedServ return fetchMetricsContent(metricsURL) }, 15*time.Second, 2*time.Second).Should( And( - ContainSubstring("toolhive_mcp"), - ContainSubstring(fmt.Sprintf(`server="%s"`, expectedServerName)), + ContainSubstring("stacklok_toolhive_proxy_active_connections"), + ContainSubstring(fmt.Sprintf(`mcp_server="%s"`, expectedServerName)), ContainSubstring(fmt.Sprintf(`transport="%s"`, expectedTransport)), ), fmt.Sprintf("Should contain correct server name '%s' and transport '%s'", expectedServerName, expectedTransport), @@ -309,9 +313,11 @@ func validateTelemetryMetrics(config *e2e.TestConfig, workloadName, expectedServ metricsContent := fetchMetricsContent(metricsURL) By("Ensuring no metrics have empty server names") - Expect(metricsContent).ToNot(ContainSubstring(`server=""`), "No metrics should have empty server name") - Expect(metricsContent).ToNot(ContainSubstring(`server="message"`), "No metrics should have 'message' as server name") - Expect(metricsContent).ToNot(ContainSubstring(`server="health"`), "No metrics should have 'health' as server name") + // The MCP server name is carried on the mcp_server label (renamed from the + // legacy server label) on the active-connections gauge and semconv metrics. + Expect(metricsContent).ToNot(ContainSubstring(`mcp_server=""`), "No metrics should have empty server name") + Expect(metricsContent).ToNot(ContainSubstring(`mcp_server="message"`), "No metrics should have 'message' as server name") + Expect(metricsContent).ToNot(ContainSubstring(`mcp_server="health"`), "No metrics should have 'health' as server name") By("Ensuring no metrics have empty transport") Expect(metricsContent).ToNot(ContainSubstring(`transport=""`), "No metrics should have empty transport") @@ -324,19 +330,27 @@ func validateTelemetryMetrics(config *e2e.TestConfig, workloadName, expectedServ func validateNoEmptyLabels(metricsContent, expectedServerName, expectedTransport string) { lines := strings.Split(metricsContent, "\n") + // This scan narrowed from every toolhive_mcp line to a single gauge, so without + // a match counter the loop body never executing would pass silently — e.g. if + // instrument creation fell back to noop, or the metric were renamed again. + checkedLines := 0 + for _, line := range lines { - if strings.Contains(line, "toolhive_mcp") && !strings.HasPrefix(line, "#") { + // The active-connections gauge is the series that carries both mcp_server + // and transport labels, so validate label correctness there. + if strings.Contains(line, "stacklok_toolhive_proxy_active_connections") && !strings.HasPrefix(line, "#") { // Skip comment lines and only check actual metric lines if strings.Contains(line, "{") { // This is a metric with labels - Expect(line).ToNot(ContainSubstring(`server=""`), + checkedLines++ + Expect(line).ToNot(ContainSubstring(`mcp_server=""`), fmt.Sprintf("Metric line should not have empty server: %s", line)) Expect(line).ToNot(ContainSubstring(`transport=""`), fmt.Sprintf("Metric line should not have empty transport: %s", line)) // Ensure it has the expected labels - if strings.Contains(line, "server=") { - Expect(line).To(ContainSubstring(fmt.Sprintf(`server="%s"`, expectedServerName)), + if strings.Contains(line, "mcp_server=") { + Expect(line).To(ContainSubstring(fmt.Sprintf(`mcp_server="%s"`, expectedServerName)), fmt.Sprintf("Metric should have correct server name: %s", line)) } if strings.Contains(line, "transport=") { @@ -346,36 +360,45 @@ func validateNoEmptyLabels(metricsContent, expectedServerName, expectedTransport } } } + + Expect(checkedLines).To(BeNumerically(">", 0), + "expected at least one stacklok_toolhive_proxy_active_connections series with labels in the scrape") } // validateMetricValues validates that metric values are reasonable func validateMetricValues(metricsContent, expectedServerName, expectedTransport string) { - // Look for request count metrics - requestPattern := regexp.MustCompile(fmt.Sprintf( - `toolhive_mcp_requests_total\{.*server="%s".*transport="%s".*\} (\d+)`, - regexp.QuoteMeta(expectedServerName), - regexp.QuoteMeta(expectedTransport), - )) + // Request counts come from the semconv server operation-duration histogram's + // _count series (the toolhive_mcp_requests_total twin is deleted). The metric + // carries mcp_server, so the series is pinned to this workload rather than + // matching any operation-duration series in the scrape. + requestPattern := regexp.MustCompile( + fmt.Sprintf(`mcp_server_operation_duration_seconds_count\{[^}]*mcp_server="%s"[^}]*\} (\d+)`, + regexp.QuoteMeta(expectedServerName)), + ) matches := requestPattern.FindAllStringSubmatch(metricsContent, -1) - if len(matches) > 0 { - totalRequests := 0 - for _, match := range matches { - if len(match) >= 2 { - count, err := strconv.Atoi(match[1]) - if err == nil { - totalRequests += count - } + // Asserted rather than guarded: a zero-match regex previously skipped the + // whole body, including the count assertion, so the helper passed silently. + Expect(matches).ToNot(BeEmpty(), + fmt.Sprintf("expected mcp_server_operation_duration_seconds_count series for mcp_server=%q in scrape", + expectedServerName)) + + totalRequests := 0 + for _, match := range matches { + if len(match) >= 2 { + count, err := strconv.Atoi(match[1]) + if err == nil { + totalRequests += count } } + } - Expect(totalRequests).To(BeNumerically(">", 0), - "Should have recorded at least some requests") + Expect(totalRequests).To(BeNumerically(">", 0), + "Should have recorded at least some requests") - GinkgoWriter.Printf("Validated %d total requests for server '%s' with transport '%s'\n", - totalRequests, expectedServerName, expectedTransport) - } + GinkgoWriter.Printf("Validated %d total requests for server '%s' with transport '%s'\n", + totalRequests, expectedServerName, expectedTransport) } // getMetricsURL constructs the metrics URL for a given workload @@ -532,26 +555,34 @@ func parseToolCallMetrics(metricsContent, expectedServerName string) *ToolCallMe continue // Skip comments and empty lines } - // Count different types of requests - if strings.Contains(line, "toolhive_mcp_requests_total") && strings.Contains(line, fmt.Sprintf(`server="%s"`, expectedServerName)) { - if strings.Contains(line, `mcp_method="initialize"`) { + // Count different types of requests. Method counts come from the semconv + // server operation-duration histogram's _count series, keyed by + // mcp_method_name (the toolhive_mcp_requests_total twin is deleted). This + // metric does not carry the server label, so we don't filter on it here. + if strings.Contains(line, "mcp_server_operation_duration_seconds_count") { + if strings.Contains(line, `mcp_method_name="initialize"`) { metrics.InitializeCallCount += extractMetricCount(line) - } else if strings.Contains(line, `mcp_method="tools/list"`) { + } else if strings.Contains(line, `mcp_method_name="tools/list"`) { metrics.ToolsListCallCount += extractMetricCount(line) - } else if strings.Contains(line, `mcp_method="tools/call"`) { + } else if strings.Contains(line, `mcp_method_name="tools/call"`) { metrics.ToolCallCount += extractMetricCount(line) } + } - // Count successful vs error calls - if strings.Contains(line, `status="success"`) { + // Success vs error is reflected in the HTTP response status code on the + // transport-level semconv metric: 2xx is success, >=400 is an error. + if strings.Contains(line, "http_server_request_duration_seconds_count") { + if strings.Contains(line, `http_response_status_code="200"`) { metrics.SuccessfulCalls += extractMetricCount(line) - } else if strings.Contains(line, `status="error"`) { + } else if strings.Contains(line, `http_response_status_code="4`) || + strings.Contains(line, `http_response_status_code="5`) { metrics.ErrorCalls += extractMetricCount(line) } } - // Collect response time information - if strings.Contains(line, "toolhive_mcp_request_duration_seconds_sum") && strings.Contains(line, fmt.Sprintf(`server="%s"`, expectedServerName)) { + // Collect response time information from the semconv server + // operation-duration histogram's _sum series. + if strings.Contains(line, "mcp_server_operation_duration_seconds_sum") { responseTimeSum += extractMetricFloatValue(line) responseTimeCount++ } @@ -686,18 +717,19 @@ func analyzeTraceAttributes(metricsContent, expectedServerName, expectedTranspor continue } - // Count request metrics as indicators of trace generation - if strings.Contains(line, "toolhive_mcp_requests_total") { + // The active-connections gauge carries the mcp_server and transport labels, + // so it is the series that reflects server-name/transport correctness. + if strings.Contains(line, "stacklok_toolhive_proxy_active_connections") { validation.TracesGenerated++ // Check server name attributes - if strings.Contains(line, fmt.Sprintf(`server="%s"`, expectedServerName)) { + if strings.Contains(line, fmt.Sprintf(`mcp_server="%s"`, expectedServerName)) { correctServerNameSpans++ - } else if strings.Contains(line, `server=""`) { + } else if strings.Contains(line, `mcp_server=""`) { emptyServerNameSpans++ - } else if strings.Contains(line, `server="message"`) { + } else if strings.Contains(line, `mcp_server="message"`) { messageServerNameSpans++ - } else if strings.Contains(line, `server="health"`) { + } else if strings.Contains(line, `mcp_server="health"`) { healthServerNameSpans++ } @@ -707,10 +739,13 @@ func analyzeTraceAttributes(metricsContent, expectedServerName, expectedTranspor } else if strings.Contains(line, `transport=""`) { emptyTransportSpans++ } + } - // Extract method names to count different request types + // Method names are carried on the semconv server operation-duration metric + // via mcp_method_name (renamed from mcp_method). + if strings.Contains(line, "mcp_server_operation_duration_seconds_count") { for _, method := range []string{"initialize", "tools/list", "resources/list"} { - if strings.Contains(line, fmt.Sprintf(`mcp_method="%s"`, method)) { + if strings.Contains(line, fmt.Sprintf(`mcp_method_name="%s"`, method)) { requestMetrics[method] = extractMetricCount(line) } } diff --git a/test/e2e/telemetry_middleware_e2e_test.go b/test/e2e/telemetry_middleware_e2e_test.go index ea53d84289..98e8650d85 100644 --- a/test/e2e/telemetry_middleware_e2e_test.go +++ b/test/e2e/telemetry_middleware_e2e_test.go @@ -234,8 +234,8 @@ var _ = Describe("Telemetry Middleware E2E", Label("middleware", "telemetry", "e metricsContent := string(body) GinkgoWriter.Printf("Found metrics on port %s:\n%s\n", port, metricsContent) - // Look for ToolHive-specific metrics - if strings.Contains(metricsContent, "toolhive_mcp") { + // Look for ToolHive-specific metrics (stacklok.* namespace) + if strings.Contains(metricsContent, "stacklok_toolhive") { metricsFound = true break } diff --git a/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go b/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go index 96363c4422..6bc075aa01 100644 --- a/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go +++ b/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go @@ -258,21 +258,21 @@ var _ = ginkgo.Describe("VirtualMCPServer Rate Limiting", ginkgo.Ordered, func() if scrapeErr != nil { return scrapeErr } - if !rateLimitCounterIsNonZero(metricFamilies, "toolhive_rate_limit_decisions", map[string]string{ + if !rateLimitCounterIsNonZero(metricFamilies, "stacklok_toolhive_ratelimit_decisions", map[string]string{ "decision": "allowed", "scope": "per_user", "operation_type": "server", }) { return fmt.Errorf("allowed rate limit decision counter is zero") } - if !rateLimitCounterIsNonZero(metricFamilies, "toolhive_rate_limit_decisions", map[string]string{ + if !rateLimitCounterIsNonZero(metricFamilies, "stacklok_toolhive_ratelimit_decisions", map[string]string{ "decision": "rejected", "scope": "per_user", "operation_type": "server", }) { return fmt.Errorf("rejected rate limit decision counter is zero") } - if !rateLimitHistogramIsNonZero(metricFamilies, "toolhive_rate_limit_check_latency") { + if !rateLimitHistogramIsNonZero(metricFamilies, "stacklok_toolhive_ratelimit_check_latency") { return fmt.Errorf("rate limit check latency histogram is empty") } return nil diff --git a/test/integration/vmcp/vmcp_integration_test.go b/test/integration/vmcp/vmcp_integration_test.go index 91e296b810..f331fbbb8c 100644 --- a/test/integration/vmcp/vmcp_integration_test.go +++ b/test/integration/vmcp/vmcp_integration_test.go @@ -446,25 +446,27 @@ func TestVMCPServer_Telemetry_CompositeToolMetrics(t *testing.T) { // Log metrics for debugging t.Logf("Metrics content:\n%s", metricsContent) - // Verify workflow execution metrics are present (composite tool). - assert.True(t, strings.Contains(metricsContent, "toolhive_vmcp_workflow_executions_total"), - "Should contain workflow executions total metric") - assert.True(t, strings.Contains(metricsContent, "toolhive_vmcp_workflow_duration_seconds"), - "Should contain workflow duration metric") - assert.True(t, strings.Contains(metricsContent, `workflow_name="echo_workflow"`), - "Should contain workflow name label") - - // Verify backend metrics are present. - assert.True(t, strings.Contains(metricsContent, "toolhive_vmcp_backend_requests_total"), - "Should contain backend requests total metric") - assert.True(t, strings.Contains(metricsContent, "toolhive_vmcp_backend_requests_duration"), - "Should contain backend requests duration metric") - - // Verify HTTP middleware metrics are present (incoming MCP requests). - assert.True(t, strings.Contains(metricsContent, "toolhive_mcp_requests_total"), - "Should contain HTTP middleware requests total metric") - assert.True(t, strings.Contains(metricsContent, "toolhive_mcp_request_duration_seconds"), - "Should contain HTTP middleware request duration metric") + // Verify composite-tool execution metrics are present (renamed from the + // toolhive_vmcp_workflow_* twins to the stacklok.vmcp.composite_tool.* vocabulary). + assert.True(t, strings.Contains(metricsContent, "stacklok_vmcp_composite_tool_executions_total"), + "Should contain composite-tool executions total metric") + assert.True(t, strings.Contains(metricsContent, "stacklok_vmcp_composite_tool_duration_seconds"), + "Should contain composite-tool duration metric") + assert.True(t, strings.Contains(metricsContent, `composite_tool="echo_workflow"`), + "Should contain composite_tool name label") + + // Verify backend metrics are present. The toolhive_vmcp_backend_requests* twins + // are deleted (RFC §3.5); the semconv client operation-duration histogram replaces them. + assert.True(t, strings.Contains(metricsContent, "mcp_client_operation_duration_seconds"), + "Should contain semconv client operation-duration metric for backend calls") + + // Verify incoming-request metrics are present. The toolhive_mcp_request* twins are + // deleted; mcp.server.operation.duration (MCP-method-bearing requests) and + // http.server.request.duration (transport level) are their semconv replacements. + assert.True(t, strings.Contains(metricsContent, "mcp_server_operation_duration_seconds"), + "Should contain semconv server operation-duration metric") + assert.True(t, strings.Contains(metricsContent, "http_server_request_duration_seconds"), + "Should contain semconv HTTP server request-duration metric") } // TestVMCPServer_DefaultResults_ConditionalSkip verifies that when a conditional step