diff --git a/docs/observability.md b/docs/observability.md index 5dc1543cbc..9f7730536c 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -188,37 +188,31 @@ 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.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 300]` | Attribute | Type | Condition | Description | |-----------|------|-----------|-------------| @@ -232,25 +226,65 @@ 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` (tool name, resource URI, or prompt name) is +> deliberately omitted from this metric's attributes to bound cardinality; it +> feeds `gen_ai.tool.name`/`gen_ai.prompt.name` instead, which are themselves +> only present for the method kinds that have a name to report. -Total number of MCP tool invocations (only recorded for `tools/call` requests). +#### `http.server.request.duration` (Histogram, seconds) -| Attribute | Type | Description | -|-----------|------|-------------| -| `server` | string | MCP server name | -| `tool` | string | Tool name | -| `status` | string | `"success"` or `"error"` | +Duration of every HTTP request the middleware handles, per the +[OTEL HTTP semantic conventions](https://opentelemetry.io/docs/specs/semconv/http/). +Recorded for every request — including SSE-open GETs and session-delete +DELETEs that carry no MCP method — so transport-level coverage doesn't depend +on a resolvable MCP method the way `mcp.server.operation.duration` does. For +SSE connections, recorded once the connection closes (not per-chunk). -#### `toolhive_mcp_active_connections` (UpDownCounter) +**Bucket boundaries** (`coremetrics.BucketsFastHTTP()`): `[0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]` -Number of currently active MCP connections. +| Attribute | Type | Condition | Description | +|-----------|------|-----------|-------------| +| `http.request.method` | string | Always | HTTP method (`GET`, `POST`, `DELETE`) | +| `http.response.status_code` | int | Always | HTTP status code | +| `error.type` | string | On HTTP 5xx | HTTP status code as string | + +#### `stacklok.build_info` (Gauge) + +Registered once per process via the shared `coremetrics.RegisterBuildInfo` +helper (`pkg/telemetry/middleware.go`). Always reports `1`, carrying version +metadata as attributes. | 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 +293,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 +303,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 +326,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 +433,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..c0c0174102 100644 --- a/docs/operator/virtualmcpserver-observability.md +++ b/docs/operator/virtualmcpserver-observability.md @@ -24,91 +24,78 @@ 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 -### Backend Metrics - -Backend metrics track requests to individual backend MCP servers. +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. -#### `toolhive_vmcp_backends_discovered` (Gauge) +### Backend Metrics -Number of backends discovered. Recorded once at startup. +Backend metrics track requests to individual backend MCP servers +(`pkg/vmcp/internal/backendtelemetry/backendtelemetry.go`). -#### `toolhive_vmcp_backend_requests` (Counter) +#### `stacklok.vmcp.mcp_server.health` (Gauge) -Total number of requests sent to backend MCP servers. +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 | |-----------|------|-------------| -| `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`) | - -Method-specific attributes (added in addition to the above): - -| 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) | - -#### `toolhive_vmcp_backend_errors` (Counter) - -Total number of errors from backend MCP servers. - -**Attributes**: Same as `toolhive_vmcp_backend_requests`. - -#### `toolhive_vmcp_backend_requests_duration` (Histogram, seconds) - -Duration of requests to backend MCP servers. Uses default histogram bucket -boundaries. - -**Attributes**: Same as `toolhive_vmcp_backend_requests`. +| `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**: `[0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300]` +**Bucket boundaries** (`coremetrics.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 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`) | -### Workflow Metrics +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. + +### Composite Tool (Workflow) Metrics -Workflow metrics track composite tool workflow executions. +Composite tool metrics track workflow executions +(`pkg/vmcp/core/core_telemetry.go`, `pkg/vmcp/server/sessionmanager/factory.go`). -#### `toolhive_vmcp_workflow_executions` (Counter) +#### `stacklok.vmcp.composite_tool.executions` (Counter) -Total number of workflow executions. +Total number of composite tool workflow executions, split by outcome. | Attribute | Type | Description | |-----------|------|-------------| -| `workflow.name` | string | Workflow name | +| `composite_tool` | string | Composite tool (workflow) name | +| `outcome` | string | `"success"` or `"error"` | -#### `toolhive_vmcp_workflow_errors` (Counter) +#### `stacklok.vmcp.composite_tool.duration` (Histogram, seconds) -Total number of workflow execution errors. +Duration of composite tool workflow executions, recorded regardless of outcome. -**Attributes**: Same as `toolhive_vmcp_workflow_executions`. +**Bucket boundaries** (`coremetrics.BucketsMCPProxy()`): `[0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, 300]` -#### `toolhive_vmcp_workflow_duration` (Histogram, seconds) - -Duration of workflow executions. - -**Attributes**: Same as `toolhive_vmcp_workflow_executions`. +| Attribute | Type | Description | +|-----------|------|-------------| +| `composite_tool` | string | Composite tool (workflow) name | ## Distributed Tracing diff --git a/docs/telemetry-migration-guide.md b/docs/telemetry-migration-guide.md index 2cc22b795d..f5f6175e2d 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 @@ -43,10 +63,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 +212,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 +269,71 @@ 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. + +| Legacy Metric/Label | New Metric/Label | Notes | +|----------------------|-------------------|-------| +| `server` (label, proxy + rate limit metrics) | `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` | | +| `toolhive_mcp_active_connections` | `stacklok.toolhive.proxy.active_connections` | Renamed, not deleted | +| `toolhive_rate_limit_decisions` | `stacklok.toolhive.ratelimit.decisions` | Renamed, not deleted | +| `toolhive_rate_limit_redis_errors` | `stacklok.toolhive.ratelimit.redis_errors` | Renamed, not deleted | +| `toolhive_rate_limit_check_latency` | `stacklok.toolhive.ratelimit.check_latency` | Renamed, not deleted | +| `toolhive_vmcp_workflow_executions` | `stacklok.vmcp.composite_tool.executions` | Now split by `outcome` label instead of a separate errors counter | +| `toolhive_vmcp_workflow_errors` | `stacklok.vmcp.composite_tool.executions` (filtered to `outcome="error"`) | Merged into the executions counter above, not a standalone metric | +| `toolhive_vmcp_workflow_duration` | `stacklok.vmcp.composite_tool.duration` | | +| `toolhive_vmcp_backend_requests_duration` | `mcp.client.operation.duration` | OTEL MCP semconv histogram | +| `toolhive_vmcp_backends_discovered` | `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 | +| `toolhive_vmcp_optimizer_find_tool_requests` / `_find_tool_errors` | `stacklok.vmcp.optimizer.find_tool.requests` | Merged into one counter split by `outcome` label | +| `toolhive_vmcp_optimizer_find_tool_duration` | `stacklok.vmcp.optimizer.find_tool.duration` | | +| `toolhive_vmcp_optimizer_find_tool_results` | `stacklok.vmcp.optimizer.find_tool.results` | | +| `toolhive_vmcp_optimizer_token_savings_percent` | `stacklok.vmcp.optimizer.token_savings` | | +| `toolhive_vmcp_optimizer_call_tool_requests` / `_call_tool_errors` / `_call_tool_not_found` | `stacklok.vmcp.optimizer.call_tool.requests` | 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` | | +| `toolhive_vmcp_backend_revision_reclassifications` | `stacklok.vmcp.backend.revision_reclassifications` | 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`). +### 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 +348,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..1e9192a77e 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": "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, 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, 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" } 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..abb889c32b 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": "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, 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, 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" } 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..548ada46d3 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": "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, 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, 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" } 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..08063f1cc5 100644 --- a/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json +++ b/examples/otel/grafana-dashboards/toolhive-mcp-otel-semconv-dashboard.json @@ -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" } 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/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..08d040560b --- /dev/null +++ b/pkg/telemetry/buildinfo_test.go @@ -0,0 +1,44 @@ +// SPDX-FileCopyrightText: Copyright 2025 Stacklok, Inc. +// SPDX-License-Identifier: Apache-2.0 + +package telemetry + +import ( + "context" + "net/http" + "net/http/httptest" + "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)) + + _ = NewHTTPMiddleware(Config{}, tracenoop.NewTracerProvider(), mp, "github", "stdio") + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + rw := httptest.NewRecorder() + handler.ServeHTTP(rw, req) + body := rw.Body.String() + + require.Contains(t, body, "stacklok_build_info", "build_info metric should be exported") + 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") +} diff --git a/pkg/telemetry/integration_test.go b/pkg/telemetry/integration_test.go index 269ed2417d..b0132d475d 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) { @@ -160,11 +170,16 @@ 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). + if strings.Contains(metricsBody, "stacklok_toolhive_proxy") { + assert.Contains(t, metricsBody, metricActiveConnections) + assert.Contains(t, metricsBody, metricHTTPServerDuration) } } else { // If metrics endpoint fails, just log it but don't fail the test @@ -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 d3d137506c..f6dcf9088a 100644 --- a/pkg/telemetry/middleware.go +++ b/pkg/telemetry/middleware.go @@ -19,12 +19,16 @@ import ( "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" + 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 ( @@ -38,11 +42,6 @@ const ( 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 = []float64{0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5, 10, 30, 60, 120, 300} - // HTTPMiddleware provides OpenTelemetry instrumentation for HTTP requests. type HTTPMiddleware struct { config Config @@ -54,11 +53,9 @@ 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 + activeConnections metric.Int64UpDownCounter } // NewHTTPMiddleware creates a new HTTP middleware for OpenTelemetry instrumentation. @@ -72,69 +69,70 @@ 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{} } operationDuration, err := meter.Float64Histogram( "mcp.server.operation.duration", metric.WithDescription("Duration of MCP server operations"), metric.WithUnit("s"), - metric.WithExplicitBucketBoundaries(MCPHistogramBuckets...), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) if err != nil { slog.Debug("failed to create operation duration metric", "error", err) + operationDuration = noop.Float64Histogram{} } - toolCallCounter, err := meter.Int64Counter( - "toolhive_mcp_tool_calls", - metric.WithDescription("Total number of MCP tool calls"), + // OTEL HTTP semantic-convention metric. Name kept verbatim (no stacklok_ + // prefix) so OTel-aware tooling recognizes it. Recorded for every request + // the middleware handles — including SSE-open GETs and session-delete + // DELETEs that carry no MCP method — restoring transport-level coverage + // that the MCP-scoped operation-duration metric misses. + 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 tool call counter metric", "error", err) + slog.Debug("failed to create http server request duration metric", "error", err) + httpServerReqDuration = noop.Float64Histogram{} } + registerBuildInfo(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, + activeConnections: activeConnections, } return middleware.Handler } +// registerBuildInfo registers the stacklok.build_info gauge via the shared +// toolhive-core helper, stamping this component's identity (toolhive) plus the +// build version/commit. +func registerBuildInfo(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. @@ -151,15 +149,23 @@ 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 the HTTP semconv duration on close so the + // long-lived SSE-open GET (which never reaches recordMetrics) still + // contributes a transport-level observation. + sseStart := time.Now() + rw := &responseWriter{ResponseWriter: w, statusCode: http.StatusOK} + defer func() { + m.recordHTTPServerDuration(ctx, r.Method, rw.statusCode, time.Since(sseStart)) + }() + next.ServeHTTP(rw, r) return } @@ -178,12 +184,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 @@ -674,36 +680,21 @@ 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, regardless of MCP + // method. This is the transport-level counterpart that stays valid for + // GET (SSE open) and DELETE (session terminate) requests carrying no MCP + // method. + m.recordHTTPServerDuration(ctx, r.Method, 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 @@ -717,18 +708,23 @@ 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 only semconv attribute keys: +// http.request.method, http.response.status_code, and error.type (set only on +// failure, mirroring the 5xx convention used elsewhere in this middleware). +func (m *HTTPMiddleware) recordHTTPServerDuration( + ctx context.Context, method string, statusCode int, duration time.Duration, +) { + specAttrs := []attribute.KeyValue{ + attribute.String("http.request.method", method), + attribute.Int("http.response.status_code", statusCode), + } + if statusCode >= 500 { + specAttrs = append(specAttrs, attribute.String("error.type", strconv.Itoa(statusCode))) } + m.httpServerReqDuration.Record(ctx, duration.Seconds(), metric.WithAttributes(specAttrs...)) } // recordOperationDuration records the mcp.server.operation.duration metric @@ -809,19 +805,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..b193e4353a 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,171 @@ 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] { + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == "http.server.request.duration" { + if h, ok := m.Data.(metricdata.Histogram[float64]); ok { + return &h + } + } + } + } + return nil +} + +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", + }, + } + + 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") + + // 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()) + + 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()) + + 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_HTTPServerRequestDuration_SSEBranch exercises the SSE +// branch of Handler specifically (path suffix "/sse"), which records +// http.server.request.duration in its own deferred call on connection close +// rather than through recordMetrics. TestHTTPMiddleware_HTTPServerRequestDuration +// above only covers the non-SSE branch (its "/mcp" paths never take the "/sse" +// suffix check), so this must be a separate test rather than another table case. +func TestHTTPMiddleware_HTTPServerRequestDuration_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)) + + hist := findHTTPServerDuration(rm) + require.NotNil(t, hist, "http.server.request.duration must be emitted for the SSE branch") + require.Len(t, hist.DataPoints, 1) + dp := hist.DataPoints[0] + + mv, ok := dp.Attributes.Value(attribute.Key("http.request.method")) + require.True(t, ok, "http.request.method must be present") + assert.Equal(t, http.MethodGet, mv.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, int64(http.StatusOK), sv.AsInt64()) + + _, hasErr := dp.Attributes.Value(attribute.Key("error.type")) + assert.False(t, hasErr, "error.type must be absent on a 2xx SSE close") +} 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..d462605b4b 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,10 @@ func (s *UnifiedMeterStrategy) CreateMeterProvider( promConfig := prometheus.Config{ EnableMetricsPath: true, IncludeRuntimeMetrics: true, + OwnershipLabels: map[string]string{ + coremetrics.AttrStacklokComponent: ComponentName, + coremetrics.AttrStacklokProduct: 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..39728a77bb 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,42 @@ 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. +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) + + req := httptest.NewRequest(http.MethodGet, "/metrics", nil) + 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.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..634f82d45d 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.BucketsMCPProxy()...), ) 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..7a98eb814d 100644 --- a/pkg/vmcp/core/core_vmcp.go +++ b/pkg/vmcp/core/core_vmcp.go @@ -80,11 +80,28 @@ 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 both on New's error paths — after the backend-health gauge +// callback has been registered but construction later fails, so it doesn't +// stay attached to the shared meter provider 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. +func unregisterHealthLogged(unregister func() error) { + 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,31 +126,47 @@ 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 } + + // 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). var workflowAuditor *audit.WorkflowAuditor if cfg.AuditConfig != nil { if err := cfg.AuditConfig.Validate(); err != nil { + unregisterHealthLogged(unregisterBackendHealth) return nil, fmt.Errorf("invalid audit configuration: %w", err) } var err error workflowAuditor, err = audit.NewWorkflowAuditor(cfg.AuditConfig) if err != nil { + unregisterHealthLogged(unregisterBackendHealth) return nil, fmt.Errorf("failed to create workflow auditor: %w", err) } slog.Info("workflow audit logging enabled") @@ -168,6 +201,7 @@ func New(cfg *Config) (VMCP, error) { instruments, err := newWorkflowInstruments(cfg.TelemetryProvider) if err != nil { stopStore() + unregisterHealthLogged(unregisterBackendHealth) return nil, fmt.Errorf("failed to create workflow telemetry instruments: %w", err) } @@ -195,6 +229,7 @@ func New(cfg *Config) (VMCP, error) { workflowDefs, err := validateWorkflowDefs(validationEngine, cfg.WorkflowDefs) if err != nil { stopStore() + unregisterHealthLogged(unregisterBackendHealth) return nil, fmt.Errorf("workflow validation failed: %w", err) } @@ -206,19 +241,30 @@ func New(cfg *Config) (VMCP, error) { healthMonitor, healthProvider, err := buildHealthMonitor(cfg) if err != nil { stopStore() + unregisterHealthLogged(unregisterBackendHealth) 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) + } + 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,9 +583,12 @@ 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() @@ -548,6 +597,7 @@ func (c *coreVMCP) Close() error { 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..809b102d29 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,89 @@ 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 (invalid AuditConfig, workflow-auditor construction +// failure, workflow-instrument creation 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. +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) { + m.reg.EXPECT().List(gomock.Any()).Return(nil).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") + }) + } +} + func TestNew_ElicitationRequiredWhenWorkflowElicits(t *testing.T) { t.Parallel() @@ -768,6 +857,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..02f40549cc 100644 --- a/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go +++ b/pkg/vmcp/internal/backendtelemetry/backendtelemetry.go @@ -13,6 +13,7 @@ package backendtelemetry import ( "context" "fmt" + "maps" "sync" "time" @@ -22,16 +23,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 +67,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 +77,191 @@ 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 (health.Monitor is built after MonitorBackends is called in +// core.New, since it depends on the decorated client already existing). 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 or pruned + // here; membership at collection time comes from registry.List, below. + // record() only distinguishes success/failure, so it can only ever set + // BackendHealthy or BackendUnhealthy; the richer states (degraded, unknown, + // unauthenticated) 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{} + + clientOperationDuration, err := meter.Float64Histogram( + "mcp.client.operation.duration", + metric.WithDescription("Duration of MCP client operations"), + metric.WithUnit("s"), + metric.WithExplicitBucketBoundaries(coremetrics.BucketsMCPProxy()...), ) 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() + for _, backend := range registry.List(ctx) { + 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)), + )) + } + } + 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 — which happens +// after MonitorBackends is called, since the monitor is constructed from the +// decorated backend client MonitorBackends returns. 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() only ever receives +// BackendHealthy/BackendUnhealthy (record() has no visibility into the +// finer-grained states); those come from the registry instead, as a fallback for +// backends the map has no entry for yet (see MonitorBackends). +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 } 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) @@ -181,7 +311,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 +345,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 +365,23 @@ 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) + t.health.set(target.WorkloadID, vmcp.BackendUnhealthy) 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 +402,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 +420,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 +436,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 +456,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..9297403113 100644 --- a/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go +++ b/pkg/vmcp/internal/backendtelemetry/backendtelemetry_test.go @@ -5,10 +5,23 @@ package backendtelemetry import ( "context" + "errors" + "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 +122,343 @@ 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) +} diff --git a/pkg/vmcp/server/sessionmanager/factory.go b/pkg/vmcp/server/sessionmanager/factory.go index 38f1747e87..77c82010e5 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 @@ -264,33 +270,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), @@ -300,7 +298,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), @@ -310,34 +308,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) @@ -354,13 +336,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 } @@ -373,14 +352,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 } @@ -393,7 +369,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) @@ -401,12 +376,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) @@ -414,32 +390,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..e0717d0c01 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,49 @@ 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") - 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") + // --- 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") // --- 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 +519,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..d699556ccd 100644 --- a/test/e2e/osv_authz_test.go +++ b/test/e2e/osv_authz_test.go @@ -239,46 +239,41 @@ 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") - // 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\"") + // Authorization outcome is reflected in the HTTP response status code: + // authorized requests get 200, denied requests get 403. + status200Count := extractMetricValue(metricsBody, "http_server_request_duration_seconds_count", "http_response_status_code=\"200\"") + status403Count := extractMetricValue(metricsBody, "http_server_request_duration_seconds_count", "http_response_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 1 authorized request (200) and at least 2 + // authorization denials (403). + Expect(status200Count).To(BeNumerically(">=", 1), + "Should have at least 1 successful (HTTP 200) request") 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). + if strings.Contains(metricsBody, "mcp_server_operation_duration_seconds") { + 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") + "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..b701adff79 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") @@ -325,18 +331,20 @@ func validateNoEmptyLabels(metricsContent, expectedServerName, expectedTransport lines := strings.Split(metricsContent, "\n") 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=""`), + 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=") { @@ -350,12 +358,13 @@ func validateNoEmptyLabels(metricsContent, expectedServerName, expectedTransport // 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). This metric + // carries mcp_method_name but not the server/transport labels, which now live + // on the active-connections gauge. + requestPattern := regexp.MustCompile( + `mcp_server_operation_duration_seconds_count\{[^}]*\} (\d+)`, + ) matches := requestPattern.FindAllStringSubmatch(metricsContent, -1) @@ -532,26 +541,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 +703,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 +725,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 7a7c02134c..df9cf76ff5 100644 --- a/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go +++ b/test/e2e/thv-operator/virtualmcp/virtualmcp_rate_limiting_test.go @@ -233,21 +233,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