From a44511df62be287592a5f266ecd204c0ce89d012 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 5 Aug 2026 16:00:17 +0000 Subject: [PATCH 1/4] metrics: expose Prometheus exposition at /metrics MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Wires a Prometheus registry into the router so the org's Prometheus / Victoria Metrics clusters can scrape this service directly, rather than inferring its state from a status page. Uses the `prometheus` crate pinned to the version dfinity/ic already depends on, since these series land in the same estate and two exposition dialects there would be nobody's win. What it reports: request counters and a latency histogram, taken from the facts the request-logging middleware already computed and previously only wrote to a log; the live and active session gauges that /version publishes, read at scrape time because they are derived state; build version and commit as labels on a build_info gauge, so any series can be attributed to an exact commit; process start time under the conventional name, so a redeploy is a step change rather than something to infer; and CPU, resident memory and file descriptors from the crate's process collector, compiled only on Linux since it reads /proc. Label cardinality is the whole design problem, not a detail. Every series is a row Prometheus holds in memory, so a label whose value an outsider picks is a memory-exhaustion primitive — and this service is internet-facing and continuously scanned, with a request log full of paths nobody here wrote. The route label is therefore never the requested path; it is axum's MatchedPath, the route template, which is bounded by the route table by construction and stays correct as routes are added. Unmatched requests have no template and collapse into one shared bucket. A test asserts that property rather than trusting the comment: 500 distinct unmatched paths produce exactly one series. Verified against a running server too, where 25 probe paths stayed one series while real routes kept their templates. Not published to the public internet. The app binds 0.0.0.0:8000, so a scraper reaches /metrics on the host's private address over the VPN — the same path the deploy already uses — and nothing needs exposing to make that work. Caddy returns 404 for the path rather than 403, so it is not advertised as existing. Metrics are not secret, but they are a free operational read (request volumes and error rates per route, session counts, process memory) and a public scrape target is also an amplification lever, since each request makes the process gather and encode its whole registry. The endpoint measures itself as well: a scrape that quietly got slow is how a target starts being dropped for timing out, and the resulting gap looks like an outage that never happened. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01R8ZshwKmjD5fZ4Hs9dS6zh --- Cargo.lock | 83 ++++++++++- Cargo.toml | 6 + deploy/native/Caddyfile | 15 ++ src/main.rs | 96 ++++++++++++- src/metrics.rs | 312 ++++++++++++++++++++++++++++++++++++++++ 5 files changed, 508 insertions(+), 4 deletions(-) create mode 100644 src/metrics.rs diff --git a/Cargo.lock b/Cargo.lock index f57bff7..b8bcacd 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1774,6 +1774,7 @@ dependencies = [ "http-body-util", "ic-agent", "pocket-ic", + "prometheus", "regex", "reqwest 0.13.4", "rmcp", @@ -1990,6 +1991,12 @@ dependencies = [ "libc", ] +[[package]] +name = "linux-raw-sys" +version = "0.4.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d26c52dbd32dccf2d10cac7725f8eae5296885fb5703b261f7d0a0739ec807ab" + [[package]] name = "linux-raw-sys" version = "0.12.1" @@ -2510,6 +2517,65 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "procfs" +version = "0.17.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cc5b72d8145275d844d4b5f6d4e1eef00c8cd889edb6035c21675d1bb1f45c9f" +dependencies = [ + "bitflags", + "hex", + "procfs-core", + "rustix 0.38.44", +] + +[[package]] +name = "procfs-core" +version = "0.17.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "239df02d8349b06fc07398a3a1697b06418223b1c7725085e801e7c0fc6a12ec" +dependencies = [ + "bitflags", + "hex", +] + +[[package]] +name = "prometheus" +version = "0.14.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3ca5326d8d0b950a9acd87e6a3f94745394f62e4dae1b1ee22b2bc0c394af43a" +dependencies = [ + "cfg-if", + "fnv", + "lazy_static", + "libc", + "memchr", + "parking_lot", + "procfs", + "protobuf", + "thiserror 2.0.18", +] + +[[package]] +name = "protobuf" +version = "3.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d65a1d4ddae7d8b5de68153b48f6aa3bba8cb002b243dbdbc55a5afbc98f99f4" +dependencies = [ + "once_cell", + "protobuf-support", + "thiserror 1.0.69", +] + +[[package]] +name = "protobuf-support" +version = "3.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3e36c2f31e0a47f9280fb347ef5e461ffcd2c52dd520d8e216b52f93b0b0d7d6" +dependencies = [ + "thiserror 1.0.69", +] + [[package]] name = "psm" version = "0.1.31" @@ -2901,6 +2967,19 @@ dependencies = [ "semver", ] +[[package]] +name = "rustix" +version = "0.38.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fdb5bc1ae2baa591800df16c9ca78619bf65c0488b41b96ccec5d11220d8c154" +dependencies = [ + "bitflags", + "errno", + "libc", + "linux-raw-sys 0.4.15", + "windows-sys 0.52.0", +] + [[package]] name = "rustix" version = "1.1.4" @@ -2910,7 +2989,7 @@ dependencies = [ "bitflags", "errno", "libc", - "linux-raw-sys", + "linux-raw-sys 0.12.1", "windows-sys 0.61.2", ] @@ -3535,7 +3614,7 @@ dependencies = [ "fastrand", "getrandom 0.4.2", "once_cell", - "rustix", + "rustix 1.1.4", "windows-sys 0.61.2", ] diff --git a/Cargo.toml b/Cargo.toml index 142d297..1a2b92f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -35,6 +35,12 @@ tracing-subscriber = { version = "0.3", features = ["env-filter"] } tokio-util = "0.7" uuid = { version = "1", features = ["v4"] } tower-http = { version = "0.7", features = ["cors"] } +# Metrics exposition at /metrics. Pinned to the version dfinity/ic uses: these +# series are destined for the same Prometheus / Victoria Metrics clusters that +# scrape the IC, so matching the org's client keeps one exposition dialect in the +# estate. The `process` feature adds CPU / RSS / file-descriptor collectors on +# Linux, which is the deploy target. +prometheus = { version = "0.14", features = ["process"] } sha2 = "0.11.0" base64 = "0.22.1" hex = "0.4.3" diff --git a/deploy/native/Caddyfile b/deploy/native/Caddyfile index eb35356..2722a37 100644 --- a/deploy/native/Caddyfile +++ b/deploy/native/Caddyfile @@ -10,6 +10,21 @@ __DOMAIN__ { reverse_proxy 127.0.0.1:8137 } + # Prometheus exposition is NOT published to the public internet. The app serves + # /metrics on 0.0.0.0:8000, so a scraper reaches it directly on the host's + # private address over the VPN — the same path the deploy already uses — and + # nothing needs to be exposed here to make that work. + # + # Returning 404 rather than 403 so the endpoint is not advertised as existing. + # Metrics are not secret, but they are a free operational read: request volumes + # and error rates by route, live session counts, process memory. That is + # reconnaissance for anyone probing the service, and a public scrape target is + # also an amplification lever, since each request makes the process gather and + # encode its whole registry. + handle /metrics { + respond 404 + } + # Everything else is the MCP server. handle { # Retry the upstream for a few seconds if the dial fails, so the ~1-3s gap diff --git a/src/main.rs b/src/main.rs index 14a0caf..4133288 100644 --- a/src/main.rs +++ b/src/main.rs @@ -28,6 +28,8 @@ use imcp2::{auth_callbacks_router, Agent, IiInstance, McpConfig, McpServer, Shar use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; /// Bind address. Honours `$PORT` (set by most PaaS), defaulting to 8000. +mod metrics; + fn bind_address() -> String { let port = std::env::var("PORT").unwrap_or_else(|_| "8000".to_string()); format!("0.0.0.0:{port}") @@ -54,16 +56,34 @@ fn serve_beta() -> bool { /// keeping any single-use `?code=` out of logs) — and request bodies are never /// logged (the redeem POST carries the connection-scoped `state` and delegation). async fn log_request( + metrics: metrics::Metrics, req: axum::http::Request, next: axum::middleware::Next, ) -> axum::response::Response { let method = req.method().clone(); let path = req.uri().path().to_string(); + // The route *template* the router matched, for the metrics label. Read before + // `next.run` consumes the request. Deliberately not `path`: an outsider + // chooses the path, and a label they choose is an unbounded-series primitive + // on an internet-facing service. See metrics::route_label. + let matched = req + .extensions() + .get::() + .map(|m| m.as_str().to_string()); let started = std::time::Instant::now(); let resp = next.run(req).await; let status = resp.status().as_u16(); - let elapsed_ms = started.elapsed().as_millis() as u64; + let elapsed = started.elapsed(); + let elapsed_ms = elapsed.as_millis() as u64; + // The log keeps the full path — it is the record of what external clients + // actually probe, and its cardinality costs nothing there. The metric cannot. tracing::info!(%method, %path, status, elapsed_ms, "http request"); + metrics.observe_request( + metrics::route_label(matched.as_deref()), + method.as_str(), + status, + elapsed.as_secs_f64(), + ); resp } @@ -298,6 +318,19 @@ async fn main() -> anyhow::Result<()> { // gauge reports zero for it when the staging instance isn't served. let (ver_prod, ver_beta) = (prod.clone(), beta.clone()); + // Metrics registry. Built once; the handle is cloned into the middleware and + // the /metrics route. A failure here means duplicate collector names, i.e. a + // programming error, so surface it at startup rather than serving a + // half-registered endpoint. + let metrics = metrics::Metrics::new( + env!("CARGO_PKG_VERSION"), + option_env!("GIT_SHA").unwrap_or("unknown"), + started_at, + )?; + // The session gauges are read at scrape time, so /metrics needs the same + // handles /version uses. + let (met_prod, met_beta) = (prod.clone(), beta.clone()); + // Which II each served mount hands off to. Built once (fixed for the process) // and cloned per request. This is the only way an external monitor can learn // the pairing: neither the mount path nor the origin implies it — @@ -379,6 +412,62 @@ async fn main() -> anyhow::Result<()> { } }), ) + // Prometheus exposition. Unauthenticated like /version; see the note in + // deploy/native/Caddyfile on why this path is not published publicly. + .route( + "/metrics", + get({ + let metrics = metrics.clone(); + move || { + let metrics = metrics.clone(); + let met_prod = met_prod.clone(); + let met_beta = met_beta.clone(); + async move { + // Refresh the derived gauges from the authoritative + // session maps before encoding. Beta reports zero when the + // staging instance is not served, so the series exists + // continuously rather than appearing and vanishing with + // the deployment shape — a gap in a gauge is much harder + // to reason about than a flat zero. + let p = met_prod.session_gauges().await; + metrics.set_sessions("prod", p.live as i64, p.active as i64); + let (b_live, b_active) = match &met_beta { + Some(b) => { + let g = b.session_gauges().await; + (g.live as i64, g.active as i64) + } + None => (0, 0), + }; + metrics.set_sessions("beta", b_live, b_active); + + match metrics.render() { + Ok(body) => ( + axum::http::StatusCode::OK, + [( + axum::http::header::CONTENT_TYPE, + "text/plain; version=0.0.4; charset=utf-8", + )], + body, + ), + // A scrape failure must not be silent: Prometheus + // reads a non-200 as the target being down, which is + // the honest reading. + Err(e) => { + tracing::error!(error = %e, "failed to encode metrics"); + ( + axum::http::StatusCode::INTERNAL_SERVER_ERROR, + [( + axum::http::header::CONTENT_TYPE, + "text/plain; charset=utf-8", + )], + String::from("failed to encode metrics\n"), + ) + } + } + } + } + }), + ) // `nest_service`, not `nest`: it also forwards the bare trailing-slash // form (`/mcp/`), which axum's `nest` never routes into the nested router. .nest_service(prod.mcp_path(), prod.mcp_router()) @@ -410,7 +499,10 @@ async fn main() -> anyhow::Result<()> { // what external clients actually hit — discovery probes, unknown paths, // etc. Only the path is logged, never the query string, so single-use // secrets (`?code=`) don't land in logs. - .layer(axum::middleware::from_fn(log_request)); + .layer(axum::middleware::from_fn(move |req, next| { + let metrics = metrics.clone(); + async move { log_request(metrics, req, next).await } + })); let bind = bind_address(); let listener = tokio::net::TcpListener::bind(&bind).await?; diff --git a/src/metrics.rs b/src/metrics.rs new file mode 100644 index 0000000..ed581bd --- /dev/null +++ b/src/metrics.rs @@ -0,0 +1,312 @@ +//! Prometheus metrics for the deployment binary, exposed at `GET /metrics` in +//! the standard text exposition format. +//! +//! Uses the `prometheus` crate at the version `dfinity/ic` pins, since these +//! series are destined for the same Prometheus/Victoria Metrics clusters that +//! scrape the IC — matching the org's client avoids two exposition dialects in +//! one estate. +//! +//! What is here and why: +//! +//! * **Request counters and a latency histogram.** The request-logging +//! middleware already computes method, path, status and elapsed time for +//! every request; this records the same facts as series rather than as +//! lines nobody aggregates. +//! * **Session gauges**, mirroring `/version`'s `live_sessions` and +//! `active_sessions`. Read at scrape time rather than pushed, because they +//! are derived state: the authoritative value is whatever the session map +//! says when asked. +//! * **Build and start info**, so a series can be attributed to an exact +//! commit and a redeploy is visible as a step change rather than inferred. +//! * **Process collector** (Linux only): CPU, RSS, open file descriptors. +//! Free with the crate, and the first thing anyone asks for when a host +//! misbehaves. +//! +//! ## Label cardinality is the whole design problem +//! +//! Every series is a row Prometheus keeps in memory, so a label whose value an +//! outsider chooses is a memory-exhaustion primitive. Labelling by raw request +//! path would be exactly that: this service is internet-facing and continuously +//! scanned, and the request log is full of paths nobody here ever wrote. Each +//! unique 404 path would mint a permanent series. +//! +//! So the `route` label is never the requested path. It is axum's +//! [`MatchedPath`] — the route *template* the router matched — which is bounded +//! by the route table by construction, and stays correct when routes are added +//! without anyone remembering to update a list here. Anything the router did not +//! match has no template and collapses to a single `other` bucket. + +use prometheus::{ + Encoder, Histogram, HistogramOpts, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Opts, + Registry, TextEncoder, +}; + +/// The bucket every unmatched request shares. One series for the entire +/// internet's worth of probing, rather than one per path attempted. +const UNMATCHED_ROUTE: &str = "other"; + +/// Latency buckets in seconds. Chosen for what this service actually does: the +/// static pages and `/version` answer in single-digit milliseconds, while an MCP +/// tool call that talks to the IC is a network round trip and lands in the +/// hundreds. The default `prometheus` buckets top out at 10s, which is fine, but +/// they have no resolution below 5ms where most responses here live. +const LATENCY_BUCKETS: &[f64] = &[ + 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, +]; + +/// Handle for recording and rendering metrics. Cheap to clone: everything inside +/// is `Arc`-backed by the `prometheus` crate, so clones share one registry. +#[derive(Clone)] +pub struct Metrics { + registry: Registry, + requests: IntCounterVec, + duration: HistogramVec, + live_sessions: IntGaugeVec, + active_sessions: IntGaugeVec, + scrapes: Histogram, +} + +impl Metrics { + /// Build the registry and register every collector. + /// + /// `commit` and `version` become labels on a single `build_info` gauge — the + /// conventional way to attach immutable facts to a target without pinning + /// them onto every other series. + pub fn new(version: &str, commit: &str, started_at: u64) -> prometheus::Result { + let registry = Registry::new(); + + let requests = IntCounterVec::new( + Opts::new( + "imcp2_http_requests_total", + "Total HTTP requests, by matched route template, method and status code.", + ), + &["route", "method", "status"], + )?; + registry.register(Box::new(requests.clone()))?; + + // No status label: a histogram multiplies series by its bucket count, so + // adding a third dimension here costs far more than on the counter, and + // "how slow was it" is rarely a question about one status code. + let duration = HistogramVec::new( + HistogramOpts::new( + "imcp2_http_request_duration_seconds", + "HTTP request latency in seconds, by matched route template and method.", + ) + .buckets(LATENCY_BUCKETS.to_vec()), + &["route", "method"], + )?; + registry.register(Box::new(duration.clone()))?; + + let live_sessions = IntGaugeVec::new( + Opts::new( + "imcp2_live_sessions", + "Authenticated sessions holding a currently-valid Internet Identity grant. \ + A session counts from grant redemption until the grant expires, idle or not.", + ), + &["instance"], + )?; + registry.register(Box::new(live_sessions.clone()))?; + + let active_sessions = IntGaugeVec::new( + Opts::new( + "imcp2_active_sessions", + "The subset of live sessions that also made a request within the activity \ + window. Always <= imcp2_live_sessions. Use this to time a low-disruption \ + redeploy.", + ), + &["instance"], + )?; + registry.register(Box::new(active_sessions.clone()))?; + + // Self-observability for the endpoint itself. A scrape that quietly got + // slow is how a monitoring target starts being dropped for timing out, + // and the resulting gap looks like an outage that never happened. + let scrapes = Histogram::with_opts( + HistogramOpts::new( + "imcp2_metrics_scrape_duration_seconds", + "Time spent gathering and encoding this endpoint's own response.", + ) + .buckets(vec![0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.5]), + )?; + registry.register(Box::new(scrapes.clone()))?; + + // Immutable deployment facts. Value is always 1; the information is in + // the labels, so `imcp2_build_info` joined onto another series attributes + // it to a commit. + let build_info = IntGaugeVec::new( + Opts::new( + "imcp2_build_info", + "Always 1. Carries the running version and commit as labels.", + ), + &["version", "commit"], + )?; + registry.register(Box::new(build_info.clone()))?; + build_info.with_label_values(&[version, commit]).set(1); + + // Conventional name and semantics, matching what node_exporter and the + // client libraries use, so existing dashboards and "restarted recently" + // alert expressions work without special-casing this target. + let start_time = IntGauge::new( + "imcp2_process_start_time_seconds", + "Unix epoch seconds at which this process started, i.e. when the deployment \ + last restarted. Every deploy restarts the service.", + )?; + registry.register(Box::new(start_time.clone()))?; + start_time.set(started_at as i64); + + // CPU, resident memory and file descriptors. Only compiled where the + // crate can implement it: it reads /proc, so it is Linux-only. The deploy + // target is Amazon Linux; this keeps a macOS dev build working. + #[cfg(target_os = "linux")] + registry.register(Box::new( + prometheus::process_collector::ProcessCollector::for_self(), + ))?; + + Ok(Self { + registry, + requests, + duration, + live_sessions, + active_sessions, + scrapes, + }) + } + + /// Record one completed request. `route` must already be a bounded template + /// — see [`route_label`]. + pub fn observe_request(&self, route: &str, method: &str, status: u16, elapsed_secs: f64) { + // `status` is rendered rather than bucketed: HTTP codes are a small + // closed set in practice, and keeping the exact code lets a query + // separate 401 from 404 from 500, which grouping into 4xx/5xx destroys. + let status = status.to_string(); + self.requests + .with_label_values(&[route, method, &status]) + .inc(); + self.duration + .with_label_values(&[route, method]) + .observe(elapsed_secs); + } + + /// Publish one instance's session counts. Called during a scrape, so the + /// value reported is the one read at scrape time. + pub fn set_sessions(&self, instance: &str, live: i64, active: i64) { + self.live_sessions.with_label_values(&[instance]).set(live); + self.active_sessions + .with_label_values(&[instance]) + .set(active); + } + + /// Gather and encode the registry in Prometheus text format. + pub fn render(&self) -> prometheus::Result { + let timer = self.scrapes.start_timer(); + let mut buf = Vec::new(); + TextEncoder::new().encode(&self.registry.gather(), &mut buf)?; + timer.observe_duration(); + String::from_utf8(buf) + .map_err(|e| prometheus::Error::Msg(format!("metrics output was not UTF-8: {e}"))) + } +} + +/// The `route` label for a request: the route template the router matched, or +/// [`UNMATCHED_ROUTE`] when it matched nothing. +/// +/// Taking the template rather than the path is what bounds cardinality. It also +/// means a new route starts being reported the moment it is added to the router, +/// with no list here to fall out of date — and a request for +/// `/wp-login.php` contributes to one shared series instead of minting its own. +pub fn route_label(matched: Option<&str>) -> &str { + match matched { + Some(t) if !t.is_empty() => t, + _ => UNMATCHED_ROUTE, + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn unmatched_requests_share_one_label() { + // The property that matters: nothing an outsider sends can mint a series. + assert_eq!(route_label(None), UNMATCHED_ROUTE); + assert_eq!(route_label(Some("")), UNMATCHED_ROUTE); + } + + #[test] + fn matched_requests_keep_their_template() { + assert_eq!(route_label(Some("/version")), "/version"); + assert_eq!(route_label(Some("/mcp")), "/mcp"); + } + + #[test] + fn renders_text_format_with_build_info_and_start_time() { + let m = Metrics::new("1.2.3", "abc1234", 1_700_000_000).unwrap(); + let out = m.render().unwrap(); + assert!(out.contains("imcp2_build_info"), "{out}"); + assert!(out.contains(r#"version="1.2.3""#), "{out}"); + assert!(out.contains(r#"commit="abc1234""#), "{out}"); + assert!( + out.contains("imcp2_process_start_time_seconds 1700000000"), + "{out}" + ); + } + + #[test] + fn records_requests_and_sessions() { + let m = Metrics::new("0", "0", 0).unwrap(); + m.observe_request("/version", "GET", 200, 0.002); + m.observe_request("/version", "GET", 200, 0.003); + m.observe_request(UNMATCHED_ROUTE, "GET", 404, 0.001); + m.set_sessions("prod", 7, 3); + + let out = m.render().unwrap(); + assert!( + out.contains( + r#"imcp2_http_requests_total{method="GET",route="/version",status="200"} 2"# + ), + "{out}" + ); + assert!( + out.contains(r#"imcp2_http_requests_total{method="GET",route="other",status="404"} 1"#), + "{out}" + ); + assert!( + out.contains(r#"imcp2_live_sessions{instance="prod"} 7"#), + "{out}" + ); + assert!( + out.contains(r#"imcp2_active_sessions{instance="prod"} 3"#), + "{out}" + ); + // The histogram must carry the observations, not just exist. + assert!( + out.contains( + r#"imcp2_http_request_duration_seconds_count{method="GET",route="/version"} 2"# + ), + "{out}" + ); + } + + #[test] + fn a_flood_of_distinct_paths_does_not_grow_the_series_count() { + // The cardinality guarantee, asserted rather than asserted-in-a-comment: + // 500 different unmatched paths must still be one series. + let m = Metrics::new("0", "0", 0).unwrap(); + for i in 0..500 { + let path = format!("/{i}-{}", "x".repeat(i % 17)); + // What the middleware does for an unrouted request. + m.observe_request(route_label(None), "GET", 404, 0.001); + let _ = path; + } + let out = m.render().unwrap(); + let series = out + .lines() + .filter(|l| l.starts_with("imcp2_http_requests_total{")) + .count(); + assert_eq!(series, 1, "expected exactly one series, got:\n{out}"); + assert!( + out.contains(r#"status="404"} 500"#), + "all 500 should land in the one series:\n{out}" + ); + } +} From 00225e6859b5847619bf55e12d26a42dbe9d46e6 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 5 Aug 2026 19:15:05 +0000 Subject: [PATCH 2/4] metrics: bound the method label, and test the bound end to end MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two review findings, both correct, and the first is a clean bypass of the guard this change was built around. The route label was bounded while the method label beside it was not. HTTP permits arbitrary extension method tokens and the public listener forwards them, so a request line reading WIBBLE / HTTP/1.1 minted its own series. Measured before fixing: twelve nonsense methods against a single path produced thirteen counter series and 182 histogram bucket lines, because a histogram multiplies every label set by its bucket count. The same twelve now produce one series and the buckets drop to 65. Methods are allow-listed to the standard nine and the helper returns &'static str, so the bound holds by type rather than by care. Worth naming the pattern rather than just the bug: I bounded the label I had been thinking about and left the one immediately next to it wide open, having written a module doc that presented cardinality as the central design problem. The doc now says the rule applies to every request-influenced label, and notes why status is the one that does not need it — the server chooses it, from a small closed set. The cardinality test was also vacuous, which is the more uncomfortable of the two. It built 500 distinct paths, discarded them, and called the recorder 500 times with a constant. That asserts a pure function is deterministic. It says nothing about the middleware deriving a bounded label from a hostile one, and would have passed unchanged if the middleware started using the raw URI — precisely the regression it existed to prevent. Both cardinality tests now drive real requests through an axum router with the real middleware installed. Confirmed by mutation: making the middleware use the raw path fails the path test and nothing else, and making the method label a pass-through fails the two method tests and nothing else. The old test survived the first of those mutations, which is the whole argument for the rewrite. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01R8ZshwKmjD5fZ4Hs9dS6zh --- src/main.rs | 4 +- src/metrics.rs | 153 +++++++++++++++++++++++++++++++++++++++++-------- 2 files changed, 131 insertions(+), 26 deletions(-) diff --git a/src/main.rs b/src/main.rs index 4133288..ed4ddba 100644 --- a/src/main.rs +++ b/src/main.rs @@ -80,7 +80,9 @@ async fn log_request( tracing::info!(%method, %path, status, elapsed_ms, "http request"); metrics.observe_request( metrics::route_label(matched.as_deref()), - method.as_str(), + // Allow-listed for the same reason as the route: HTTP permits arbitrary + // extension method tokens, so this is attacker-chosen too. + metrics::method_label(method.as_str()), status, elapsed.as_secs_f64(), ); diff --git a/src/metrics.rs b/src/metrics.rs index ed581bd..36519e2 100644 --- a/src/metrics.rs +++ b/src/metrics.rs @@ -35,6 +35,14 @@ //! by the route table by construction, and stays correct when routes are added //! without anyone remembering to update a list here. Anything the router did not //! match has no template and collapses to a single `other` bucket. +//! +//! The same reasoning applies to **every** label a request can influence, which +//! is easy to forget once one of them is handled. `method` is equally +//! attacker-chosen: HTTP permits arbitrary extension method tokens, so a request +//! line reading `WIBBLE / HTTP/1.1` would otherwise mint its own series — and +//! its own full set of histogram buckets, which multiplies the cost by roughly +//! the bucket count. It is allow-listed to the standard methods for that reason. +//! `status` is safe by contrast: the server chooses it, from a small closed set. use prometheus::{ Encoder, Histogram, HistogramOpts, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Opts, @@ -45,6 +53,16 @@ use prometheus::{ /// internet's worth of probing, rather than one per path attempted. const UNMATCHED_ROUTE: &str = "other"; +/// The same, for request methods outside the standard set. +const UNKNOWN_METHOD: &str = "other"; + +/// Methods that may appear as a label. HTTP permits arbitrary extension method +/// tokens, so this is an allow-list rather than a deny-list: anything unlisted +/// collapses into [`UNKNOWN_METHOD`]. +const KNOWN_METHODS: [&str; 9] = [ + "GET", "HEAD", "POST", "PUT", "PATCH", "DELETE", "OPTIONS", "TRACE", "CONNECT", +]; + /// Latency buckets in seconds. Chosen for what this service actually does: the /// static pages and `/version` answer in single-digit milliseconds, while an MCP /// tool call that talks to the IC is a network round trip and lands in the @@ -221,13 +239,51 @@ pub fn route_label(matched: Option<&str>) -> &str { } } +/// The `method` label for a request: the method itself when it is one of the +/// standard set, otherwise [`UNKNOWN_METHOD`]. +/// +/// Returns `&'static str` deliberately — it is not possible for a caller to +/// smuggle a borrowed request value through this function, so the bound holds by +/// type rather than by discipline. +pub fn method_label(method: &str) -> &'static str { + match KNOWN_METHODS.iter().position(|m| *m == method) { + Some(i) => KNOWN_METHODS[i], + None => UNKNOWN_METHOD, + } +} + #[cfg(test)] mod tests { use super::*; + use axum::{body::Body, http::Request, routing::get, Router}; + use tower::ServiceExt; + + /// A router shaped like the real one: one real route, and the same + /// `log_request` middleware the binary installs. + /// + /// The cardinality tests below go through this rather than calling + /// `observe_request` directly. That distinction is the entire point: calling + /// the recorder with a pre-computed label only proves the recorder is + /// deterministic. Driving real requests proves the *middleware* derives a + /// bounded label from a hostile one — which is the property being claimed, + /// and the one that would break if someone later passed the raw URI. + fn app(m: Metrics) -> Router { + Router::new() + .route("/version", get(|| async { "ok" })) + .layer(axum::middleware::from_fn(move |req, next| { + let m = m.clone(); + async move { crate::log_request(m, req, next).await } + })) + } + + fn request_series(out: &str) -> Vec<&str> { + out.lines() + .filter(|l| l.starts_with("imcp2_http_requests_total{")) + .collect() + } #[test] fn unmatched_requests_share_one_label() { - // The property that matters: nothing an outsider sends can mint a series. assert_eq!(route_label(None), UNMATCHED_ROUTE); assert_eq!(route_label(Some("")), UNMATCHED_ROUTE); } @@ -238,6 +294,16 @@ mod tests { assert_eq!(route_label(Some("/mcp")), "/mcp"); } + #[test] + fn standard_methods_pass_through_and_the_rest_collapse() { + for m in KNOWN_METHODS { + assert_eq!(method_label(m), m); + } + for m in ["WIBBLE", "get", "", "GET ", "X-CUSTOM"] { + assert_eq!(method_label(m), UNKNOWN_METHOD, "{m:?} should collapse"); + } + } + #[test] fn renders_text_format_with_build_info_and_start_time() { let m = Metrics::new("1.2.3", "abc1234", 1_700_000_000).unwrap(); @@ -256,7 +322,6 @@ mod tests { let m = Metrics::new("0", "0", 0).unwrap(); m.observe_request("/version", "GET", 200, 0.002); m.observe_request("/version", "GET", 200, 0.003); - m.observe_request(UNMATCHED_ROUTE, "GET", 404, 0.001); m.set_sessions("prod", 7, 3); let out = m.render().unwrap(); @@ -266,19 +331,11 @@ mod tests { ), "{out}" ); - assert!( - out.contains(r#"imcp2_http_requests_total{method="GET",route="other",status="404"} 1"#), - "{out}" - ); - assert!( - out.contains(r#"imcp2_live_sessions{instance="prod"} 7"#), - "{out}" - ); + assert!(out.contains(r#"imcp2_live_sessions{instance="prod"} 7"#), "{out}"); assert!( out.contains(r#"imcp2_active_sessions{instance="prod"} 3"#), "{out}" ); - // The histogram must carry the observations, not just exist. assert!( out.contains( r#"imcp2_http_request_duration_seconds_count{method="GET",route="/version"} 2"# @@ -287,26 +344,72 @@ mod tests { ); } - #[test] - fn a_flood_of_distinct_paths_does_not_grow_the_series_count() { - // The cardinality guarantee, asserted rather than asserted-in-a-comment: - // 500 different unmatched paths must still be one series. + /// 200 distinct paths, sent as real requests, must produce one series. + #[tokio::test] + async fn a_flood_of_distinct_paths_yields_one_series() { + let m = Metrics::new("0", "0", 0).unwrap(); + for i in 0..200 { + let req = Request::builder() + .uri(format!("/scan-{i}-{}", "x".repeat(i % 13))) + .body(Body::empty()) + .unwrap(); + app(m.clone()).oneshot(req).await.unwrap(); + } + let out = m.render().unwrap(); + let series = request_series(&out); + assert_eq!(series.len(), 1, "expected one series, got:\n{out}"); + assert!(series[0].contains(r#"route="other""#), "{}", series[0]); + assert!(series[0].ends_with(" 200"), "{}", series[0]); + } + + /// The same property for the method label. HTTP permits arbitrary extension + /// tokens, and each unique one previously minted a counter series *and* a + /// full set of histogram buckets — the histogram multiplying the cost by + /// roughly the bucket count. + #[tokio::test] + async fn a_flood_of_extension_methods_yields_one_series() { let m = Metrics::new("0", "0", 0).unwrap(); - for i in 0..500 { - let path = format!("/{i}-{}", "x".repeat(i % 17)); - // What the middleware does for an unrouted request. - m.observe_request(route_label(None), "GET", 404, 0.001); - let _ = path; + for i in 0..100 { + let req = Request::builder() + .method(format!("WIBBLE{i}").as_str()) + .uri("/version") + .body(Body::empty()) + .unwrap(); + app(m.clone()).oneshot(req).await.unwrap(); } let out = m.render().unwrap(); - let series = out + let series = request_series(&out); + assert_eq!(series.len(), 1, "expected one series, got:\n{out}"); + assert!(series[0].contains(r#"method="other""#), "{}", series[0]); + + // The histogram is where the real damage would be, so bound it too. + let buckets = out .lines() - .filter(|l| l.starts_with("imcp2_http_requests_total{")) + .filter(|l| l.starts_with("imcp2_http_request_duration_seconds_bucket")) .count(); - assert_eq!(series, 1, "expected exactly one series, got:\n{out}"); + assert_eq!( + buckets, + LATENCY_BUCKETS.len() + 1, + "one label set means one bucket family (+Inf), got:\n{out}" + ); + } + + /// Real traffic still resolves to its own template, so bounding the labels + /// has not flattened everything into `other` and made the metric useless. + #[tokio::test] + async fn real_routes_keep_their_identity() { + let m = Metrics::new("0", "0", 0).unwrap(); + let req = Request::builder() + .uri("/version") + .body(Body::empty()) + .unwrap(); + app(m.clone()).oneshot(req).await.unwrap(); + let out = m.render().unwrap(); assert!( - out.contains(r#"status="404"} 500"#), - "all 500 should land in the one series:\n{out}" + out.contains( + r#"imcp2_http_requests_total{method="GET",route="/version",status="200"} 1"# + ), + "{out}" ); } } From 2ecfd7e4afe01555f8735e245ca968c88c859c9c Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 13:56:24 +0000 Subject: [PATCH 3/4] metrics: make the instrumentation usable from the library MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Addresses consumer feedback that none of this was reachable: `mod metrics;` lived in main.rs, so the module was private to the bin target and an embedder depending on the crate got nothing. It is `pub mod metrics` in lib.rs now. Split log_request into write_request_metrics and write_request_logs, both exported. They are separated because their constraints genuinely differ rather than for tidiness: metrics must bound every label, while a log line can afford the full request path and is more useful carrying it. Splitting also lets an embedder take either one alone. The log moves from info to debug — it fires on every request including the noise floor of an internet-facing service, so at info it drowns the handful of lines an operator actually wants. Metrics::new now registers into a Registry the caller supplies and keeps none of its own. A host embedding this crate already has a registry and already exposes it; series published into a private one would simply never be seen. Exposition follows the registry, so render() is gone and the binary gathers its own; the scrape-duration signal survives as observe_scrape, recorded by whoever renders. Registering the process collector also stops being the library's business. `process_*` is un-namespaced and describes the whole OS process, which belongs to the embedding application rather than to this crate, and would collide with a host that already has one. It is now an explicit register_process_collector the standalone binary calls, since the binary is the application. The metric prefix is factored into a macro rather than repeated. A macro over a const plus format! keeps the names &'static str and keeps them greppable in full, so searching an alert rule's imcp2_http_requests_total still finds the line that defines it. Fixed rather than caller-configurable on purpose: a metric name identifies the software emitting it, and one dashboard working across every deployment depends on that. Verified from outside the crate, not only by unit tests: a scratch consumer crate registers imcp2's collectors into its own registry alongside its own metric, does its own exposition, and asserts no process_* leaked in. Also confirmed the log line is absent at default level and present under RUST_LOG=imcp2=debug, and that the binary still serves /metrics with the process collector it registers itself. Two library-safety properties the review raised are now pinned by tests rather than assumed: a second Metrics::new against one registry returns AlreadyReg instead of panicking, and Metrics::new registers no process_* series. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01R8ZshwKmjD5fZ4Hs9dS6zh --- src/lib.rs | 4 + src/main.rs | 78 +++++------ src/metrics.rs | 357 +++++++++++++++++++++++++++++++++++++------------ 3 files changed, 304 insertions(+), 135 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 92d4c7d..be5cdf2 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -69,6 +69,10 @@ mod auth; mod calls; +/// Prometheus instrumentation, usable by embedders as well as by the bundled +/// binary. Exports the [`metrics::Metrics`] handle and the two request +/// middlewares. +pub mod metrics; mod discover; mod identities; mod management; diff --git a/src/main.rs b/src/main.rs index ed4ddba..ad09291 100644 --- a/src/main.rs +++ b/src/main.rs @@ -28,8 +28,6 @@ use imcp2::{auth_callbacks_router, Agent, IiInstance, McpConfig, McpServer, Shar use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; /// Bind address. Honours `$PORT` (set by most PaaS), defaulting to 8000. -mod metrics; - fn bind_address() -> String { let port = std::env::var("PORT").unwrap_or_else(|_| "8000".to_string()); format!("0.0.0.0:{port}") @@ -50,44 +48,6 @@ fn serve_beta() -> bool { .unwrap_or(false) } -/// Log each inbound request: method, path, response status, and latency — gives -/// visibility into what external MCP clients probe (discovery URLs, unknown -/// paths) at `RUST_LOG=info`. The query string is never logged (defense in depth, -/// keeping any single-use `?code=` out of logs) — and request bodies are never -/// logged (the redeem POST carries the connection-scoped `state` and delegation). -async fn log_request( - metrics: metrics::Metrics, - req: axum::http::Request, - next: axum::middleware::Next, -) -> axum::response::Response { - let method = req.method().clone(); - let path = req.uri().path().to_string(); - // The route *template* the router matched, for the metrics label. Read before - // `next.run` consumes the request. Deliberately not `path`: an outsider - // chooses the path, and a label they choose is an unbounded-series primitive - // on an internet-facing service. See metrics::route_label. - let matched = req - .extensions() - .get::() - .map(|m| m.as_str().to_string()); - let started = std::time::Instant::now(); - let resp = next.run(req).await; - let status = resp.status().as_u16(); - let elapsed = started.elapsed(); - let elapsed_ms = elapsed.as_millis() as u64; - // The log keeps the full path — it is the record of what external clients - // actually probe, and its cardinality costs nothing there. The metric cannot. - tracing::info!(%method, %path, status, elapsed_ms, "http request"); - metrics.observe_request( - metrics::route_label(matched.as_deref()), - // Allow-listed for the same reason as the route: HTTP permits arbitrary - // extension method tokens, so this is attacker-chosen too. - metrics::method_label(method.as_str()), - status, - elapsed.as_secs_f64(), - ); - resp -} /// The landing page served at `/`: a self-contained design bundle exported from /// Claude Design (`assets/index.html`, compiled in via `include_str!`, no @@ -324,11 +284,19 @@ async fn main() -> anyhow::Result<()> { // the /metrics route. A failure here means duplicate collector names, i.e. a // programming error, so surface it at startup rather than serving a // half-registered endpoint. - let metrics = metrics::Metrics::new( + // This binary is the standalone case, so it owns the registry. An embedder + // passes its own instead; see imcp2::metrics. + let registry = prometheus::Registry::new(); + let metrics = imcp2::metrics::Metrics::new( + ®istry, env!("CARGO_PKG_VERSION"), option_env!("GIT_SHA").unwrap_or("unknown"), started_at, )?; + // CPU / RSS / file descriptors. Registered here rather than by the library: + // `process_*` describes the whole OS process, which belongs to the + // application, and this binary *is* the application. + imcp2::metrics::register_process_collector(®istry)?; // The session gauges are read at scrape time, so /metrics needs the same // handles /version uses. let (met_prod, met_beta) = (prod.clone(), beta.clone()); @@ -442,7 +410,19 @@ async fn main() -> anyhow::Result<()> { }; metrics.set_sessions("beta", b_live, b_active); - match metrics.render() { + let started = std::time::Instant::now(); + let encoded = { + use prometheus::Encoder; + let mut buf = Vec::new(); + prometheus::TextEncoder::new() + .encode(®istry.gather(), &mut buf) + .map_err(|e| e.to_string()) + .and_then(|()| { + String::from_utf8(buf).map_err(|e| e.to_string()) + }) + }; + metrics.observe_scrape(started.elapsed().as_secs_f64()); + match encoded { Ok(body) => ( axum::http::StatusCode::OK, [( @@ -501,10 +481,16 @@ async fn main() -> anyhow::Result<()> { // what external clients actually hit — discovery probes, unknown paths, // etc. Only the path is logged, never the query string, so single-use // secrets (`?code=`) don't land in logs. - .layer(axum::middleware::from_fn(move |req, next| { - let metrics = metrics.clone(); - async move { log_request(metrics, req, next).await } - })); + // Two layers rather than one. They have different constraints — metrics + // must bound every label, a log line is more useful carrying the full + // path — and splitting them lets an embedder take either independently. + .layer(axum::middleware::from_fn_with_state( + metrics.clone(), + imcp2::metrics::write_request_metrics, + )) + .layer(axum::middleware::from_fn( + imcp2::metrics::write_request_logs, + )); let bind = bind_address(); let listener = tokio::net::TcpListener::bind(&bind).await?; diff --git a/src/metrics.rs b/src/metrics.rs index 36519e2..6f4bc7a 100644 --- a/src/metrics.rs +++ b/src/metrics.rs @@ -1,11 +1,23 @@ -//! Prometheus metrics for the deployment binary, exposed at `GET /metrics` in -//! the standard text exposition format. +//! Prometheus instrumentation for this crate, usable from the library rather +//! than only from the bundled binary. //! //! Uses the `prometheus` crate at the version `dfinity/ic` pins, since these //! series are destined for the same Prometheus/Victoria Metrics clusters that //! scrape the IC — matching the org's client avoids two exposition dialects in //! one estate. //! +//! ## The registry belongs to the caller +//! +//! [`Metrics::new`] registers its collectors into a [`Registry`] you supply and +//! keeps no registry of its own. A host embedding this crate already has one, +//! already exposes it somewhere, and would never see series published into a +//! registry this module kept to itself. Exposition is therefore the host's job +//! too: this module has no `render` — gather your own registry. +//! +//! One consequence worth stating: registering twice into the same registry +//! returns [`prometheus::Error::AlreadyReg`] rather than panicking, so build one +//! `Metrics` per registry and clone it. Cloning shares the collectors. +//! //! What is here and why: //! //! * **Request counters and a latency histogram.** The request-logging @@ -44,11 +56,31 @@ //! the bucket count. It is allow-listed to the standard methods for that reason. //! `status` is safe by contrast: the server chooses it, from a small closed set. +use axum::{ + extract::{MatchedPath, Request, State}, + middleware::Next, + response::Response, +}; use prometheus::{ - Encoder, Histogram, HistogramOpts, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Opts, - Registry, TextEncoder, + Histogram, HistogramOpts, HistogramVec, IntCounterVec, IntGauge, IntGaugeVec, Opts, Registry, }; +/// Every metric this crate publishes is named `imcp2_*`. The prefix is factored +/// out so it cannot drift between the seven definitions and the assertions that +/// check them, and it is a macro rather than a `const` + `format!` so the names +/// stay `&'static str` and stay greppable in full — searching an alert rule's +/// `imcp2_http_requests_total` should land on the line that defines it. +/// +/// Deliberately fixed, not caller-configurable: a metric name identifies the +/// software emitting it, and `imcp2_http_requests_total` meaning the same thing +/// on every deployment is what lets one dashboard and one alert rule work +/// everywhere. +macro_rules! metric { + ($suffix:literal) => { + concat!("imcp2_", $suffix) + }; +} + /// The bucket every unmatched request shares. One series for the entire /// internet's worth of probing, rather than one per path attempted. const UNMATCHED_ROUTE: &str = "other"; @@ -72,11 +104,13 @@ const LATENCY_BUCKETS: &[f64] = &[ 0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, ]; -/// Handle for recording and rendering metrics. Cheap to clone: everything inside -/// is `Arc`-backed by the `prometheus` crate, so clones share one registry. +/// Handle for recording this crate's metrics. Cheap to clone: every collector is +/// `Arc`-backed by the `prometheus` crate, so clones share one set of series. +/// +/// Holds no [`Registry`] — see the module docs. Clone this into your middleware +/// state and wherever else you record from. #[derive(Clone)] pub struct Metrics { - registry: Registry, requests: IntCounterVec, duration: HistogramVec, live_sessions: IntGaugeVec, @@ -85,17 +119,31 @@ pub struct Metrics { } impl Metrics { - /// Build the registry and register every collector. + /// Register this crate's collectors into `registry` and return a handle for + /// recording against them. /// - /// `commit` and `version` become labels on a single `build_info` gauge — the + /// The registry is borrowed, never retained: exposition stays the caller's + /// job, so a host embedding this crate publishes these series from wherever + /// it already publishes its own. + /// + /// `version` and `commit` become labels on a single `build_info` gauge — the /// conventional way to attach immutable facts to a target without pinning - /// them onto every other series. - pub fn new(version: &str, commit: &str, started_at: u64) -> prometheus::Result { - let registry = Registry::new(); + /// them onto every other series. They are constructor arguments rather than + /// a separate setter so that forgetting them is impossible; a silently + /// absent `build_info` is hard to notice and annoying to debug. + /// + /// Returns [`prometheus::Error::AlreadyReg`] if called twice against the same + /// registry. Build one and clone it. + pub fn new( + registry: &Registry, + version: &str, + commit: &str, + started_at: u64, + ) -> prometheus::Result { let requests = IntCounterVec::new( Opts::new( - "imcp2_http_requests_total", + metric!("http_requests_total"), "Total HTTP requests, by matched route template, method and status code.", ), &["route", "method", "status"], @@ -107,7 +155,7 @@ impl Metrics { // "how slow was it" is rarely a question about one status code. let duration = HistogramVec::new( HistogramOpts::new( - "imcp2_http_request_duration_seconds", + metric!("http_request_duration_seconds"), "HTTP request latency in seconds, by matched route template and method.", ) .buckets(LATENCY_BUCKETS.to_vec()), @@ -117,7 +165,7 @@ impl Metrics { let live_sessions = IntGaugeVec::new( Opts::new( - "imcp2_live_sessions", + metric!("live_sessions"), "Authenticated sessions holding a currently-valid Internet Identity grant. \ A session counts from grant redemption until the grant expires, idle or not.", ), @@ -127,7 +175,7 @@ impl Metrics { let active_sessions = IntGaugeVec::new( Opts::new( - "imcp2_active_sessions", + metric!("active_sessions"), "The subset of live sessions that also made a request within the activity \ window. Always <= imcp2_live_sessions. Use this to time a low-disruption \ redeploy.", @@ -141,7 +189,7 @@ impl Metrics { // and the resulting gap looks like an outage that never happened. let scrapes = Histogram::with_opts( HistogramOpts::new( - "imcp2_metrics_scrape_duration_seconds", + metric!("metrics_scrape_duration_seconds"), "Time spent gathering and encoding this endpoint's own response.", ) .buckets(vec![0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.5]), @@ -153,7 +201,7 @@ impl Metrics { // it to a commit. let build_info = IntGaugeVec::new( Opts::new( - "imcp2_build_info", + metric!("build_info"), "Always 1. Carries the running version and commit as labels.", ), &["version", "commit"], @@ -165,23 +213,14 @@ impl Metrics { // client libraries use, so existing dashboards and "restarted recently" // alert expressions work without special-casing this target. let start_time = IntGauge::new( - "imcp2_process_start_time_seconds", + metric!("process_start_time_seconds"), "Unix epoch seconds at which this process started, i.e. when the deployment \ last restarted. Every deploy restarts the service.", )?; registry.register(Box::new(start_time.clone()))?; start_time.set(started_at as i64); - // CPU, resident memory and file descriptors. Only compiled where the - // crate can implement it: it reads /proc, so it is Linux-only. The deploy - // target is Amazon Linux; this keeps a macOS dev build working. - #[cfg(target_os = "linux")] - registry.register(Box::new( - prometheus::process_collector::ProcessCollector::for_self(), - ))?; - Ok(Self { - registry, requests, duration, live_sessions, @@ -214,17 +253,105 @@ impl Metrics { .set(active); } - /// Gather and encode the registry in Prometheus text format. - pub fn render(&self) -> prometheus::Result { - let timer = self.scrapes.start_timer(); - let mut buf = Vec::new(); - TextEncoder::new().encode(&self.registry.gather(), &mut buf)?; - timer.observe_duration(); - String::from_utf8(buf) - .map_err(|e| prometheus::Error::Msg(format!("metrics output was not UTF-8: {e}"))) + /// Record how long a scrape took to gather and encode. + /// + /// Exposition belongs to whoever owns the registry, so this crate cannot time + /// it — but the signal is worth keeping: a scrape that quietly got slow is how + /// a target starts being dropped for timing out, and the resulting gap looks + /// like an outage that never happened. Call this from your `/metrics` handler. + pub fn observe_scrape(&self, seconds: f64) { + self.scrapes.observe(seconds); } } +/// Register the process collector — CPU, resident memory, open file descriptors. +/// +/// Separate from [`Metrics::new`], and deliberately so. It emits un-namespaced +/// `process_*` series describing the whole OS process, which belongs to the +/// application rather than to this crate; registering it from library code would +/// both claim series that are not ours and collide with any host that already has +/// one. Standalone binaries should call it; embedders generally should not. +/// +/// A no-op off Linux, where the crate cannot implement it (it reads `/proc`). +pub fn register_process_collector(registry: &Registry) -> prometheus::Result<()> { + #[cfg(target_os = "linux")] + registry.register(Box::new( + prometheus::process_collector::ProcessCollector::for_self(), + ))?; + #[cfg(not(target_os = "linux"))] + let _ = registry; + Ok(()) +} + +/// Middleware: record request count and latency. +/// +/// Split from [`write_request_logs`] because the two have genuinely different +/// constraints and a combined layer forces the stricter one on both. Metrics must +/// bound every label — see the module docs — while a log line can afford the full +/// path, and is in fact more useful for carrying it. Separating them also lets a +/// host take one and not the other. +/// +/// Apply with the handle as state: +/// +/// ```ignore +/// use axum::middleware::from_fn_with_state; +/// let metrics = imcp2::metrics::Metrics::new(®istry, version, commit, started_at)?; +/// let app = router.layer(from_fn_with_state( +/// metrics.clone(), +/// imcp2::metrics::write_request_metrics, +/// )); +/// ``` +pub async fn write_request_metrics( + State(metrics): State, + req: Request, + next: Next, +) -> Response { + // Read the matched template before `next.run` consumes the request. + let route = req + .extensions() + .get::() + .map(|m| m.as_str().to_string()); + let method = req.method().clone(); + let started = std::time::Instant::now(); + let resp = next.run(req).await; + metrics.observe_request( + route_label(route.as_deref()), + method_label(method.as_str()), + resp.status().as_u16(), + started.elapsed().as_secs_f64(), + ); + resp +} + +/// Middleware: log one line per request — method, path, status, elapsed. +/// +/// At `debug` level. This fires on every request including the noise floor of an +/// internet-facing service, so it does not belong at `info`, where it drowns the +/// handful of lines an operator actually wants. `RUST_LOG=imcp2=debug` turns it on. +/// +/// Only the path is logged, never the query string, so single-use secrets +/// (`?code=`) do not land in logs. Request bodies are never logged either — the +/// redeem POST carries the connection-scoped `state` and the delegation. +/// +/// Unlike [`write_request_metrics`] this keeps the *full* path rather than the +/// route template: it is the record of what external clients actually probe, and +/// unbounded cardinality costs nothing in a log. +/// +/// ```ignore +/// use axum::middleware::from_fn; +/// let app = router.layer(from_fn(imcp2::metrics::write_request_logs)); +/// ``` +pub async fn write_request_logs(req: Request, next: Next) -> Response { + let method = req.method().clone(); + let path = req.uri().path().to_string(); + let started = std::time::Instant::now(); + let resp = next.run(req).await; + let status = resp.status().as_u16(); + let elapsed_ms = started.elapsed().as_millis() as u64; + tracing::debug!(%method, %path, status, elapsed_ms, "http request"); + resp +} + /// The `route` label for a request: the route template the router matched, or /// [`UNMATCHED_ROUTE`] when it matched nothing. /// @@ -255,30 +382,45 @@ pub fn method_label(method: &str) -> &'static str { #[cfg(test)] mod tests { use super::*; - use axum::{body::Body, http::Request, routing::get, Router}; + use axum::{body::Body, http::Request as HttpRequest, routing::get, Router}; + use prometheus::{Encoder, TextEncoder}; use tower::ServiceExt; - /// A router shaped like the real one: one real route, and the same - /// `log_request` middleware the binary installs. + /// Stand-in for what a host does at scrape time, now that this crate does not + /// render: gather the caller's registry and encode it. + fn encode(registry: &Registry) -> String { + let mut buf = Vec::new(); + TextEncoder::new() + .encode(®istry.gather(), &mut buf) + .unwrap(); + String::from_utf8(buf).unwrap() + } + + fn fixture() -> (Registry, Metrics) { + let r = Registry::new(); + let m = Metrics::new(&r, "1.2.3", "abc1234", 1_700_000_000).unwrap(); + (r, m) + } + + /// A router shaped like a host's: a real route, and the exported middleware. /// - /// The cardinality tests below go through this rather than calling - /// `observe_request` directly. That distinction is the entire point: calling - /// the recorder with a pre-computed label only proves the recorder is - /// deterministic. Driving real requests proves the *middleware* derives a - /// bounded label from a hostile one — which is the property being claimed, - /// and the one that would break if someone later passed the raw URI. + /// The cardinality tests go through this rather than calling `observe_request` + /// directly. Calling the recorder with a pre-computed label only proves the + /// recorder is deterministic; driving real requests proves the *middleware* + /// derives a bounded label from a hostile one, which is the actual claim and + /// the thing that breaks if someone later passes the raw URI. fn app(m: Metrics) -> Router { Router::new() .route("/version", get(|| async { "ok" })) - .layer(axum::middleware::from_fn(move |req, next| { - let m = m.clone(); - async move { crate::log_request(m, req, next).await } - })) + .layer(axum::middleware::from_fn_with_state( + m, + write_request_metrics, + )) } fn request_series(out: &str) -> Vec<&str> { out.lines() - .filter(|l| l.starts_with("imcp2_http_requests_total{")) + .filter(|l| l.starts_with(metric!("http_requests_total")) && l.contains('{')) .collect() } @@ -291,7 +433,6 @@ mod tests { #[test] fn matched_requests_keep_their_template() { assert_eq!(route_label(Some("/version")), "/version"); - assert_eq!(route_label(Some("/mcp")), "/mcp"); } #[test] @@ -305,87 +446,126 @@ mod tests { } #[test] - fn renders_text_format_with_build_info_and_start_time() { - let m = Metrics::new("1.2.3", "abc1234", 1_700_000_000).unwrap(); - let out = m.render().unwrap(); - assert!(out.contains("imcp2_build_info"), "{out}"); + fn collectors_land_in_the_callers_registry() { + let (r, _m) = fixture(); + let out = encode(&r); + assert!(out.contains(metric!("build_info")), "{out}"); assert!(out.contains(r#"version="1.2.3""#), "{out}"); assert!(out.contains(r#"commit="abc1234""#), "{out}"); assert!( - out.contains("imcp2_process_start_time_seconds 1700000000"), + out.contains(concat!(metric!("process_start_time_seconds"), " 1700000000")), "{out}" ); } + /// The library must not claim the host's process-level series. `process_*` is + /// un-namespaced and describes the whole OS process, which belongs to the + /// application embedding this crate, not to this crate. + #[test] + fn new_does_not_register_the_process_collector() { + let (r, _m) = fixture(); + let out = encode(&r); + assert!( + !out.contains("process_cpu_seconds_total"), + "Metrics::new must not register process_* series:\n{out}" + ); + // It is available, just opt-in and separate. + register_process_collector(&r).unwrap(); + #[cfg(target_os = "linux")] + assert!(encode(&r).contains("process_cpu_seconds_total")); + } + + /// Registering twice into one registry is an error, not a panic — so a host + /// that wires this up twice gets a `Result` it can act on. Build one and clone. + #[test] + fn double_registration_is_an_error_not_a_panic() { + let (r, _m) = fixture(); + match Metrics::new(&r, "1.2.3", "abc1234", 0) { + Err(prometheus::Error::AlreadyReg) => {} + Err(e) => panic!("expected AlreadyReg, got {e:?}"), + Ok(_) => panic!("expected the second registration to fail"), + } + } + + /// Two independent registries do not collide, which is what makes the + /// clone-or-rebuild guidance workable. + #[test] + fn separate_registries_are_independent() { + let (_r1, _m1) = fixture(); + let (_r2, _m2) = fixture(); + } + #[test] fn records_requests_and_sessions() { - let m = Metrics::new("0", "0", 0).unwrap(); + let (r, m) = fixture(); m.observe_request("/version", "GET", 200, 0.002); m.observe_request("/version", "GET", 200, 0.003); m.set_sessions("prod", 7, 3); - - let out = m.render().unwrap(); + let out = encode(&r); assert!( - out.contains( - r#"imcp2_http_requests_total{method="GET",route="/version",status="200"} 2"# - ), + out.contains(concat!( + metric!("http_requests_total"), + r#"{method="GET",route="/version",status="200"} 2"# + )), "{out}" ); - assert!(out.contains(r#"imcp2_live_sessions{instance="prod"} 7"#), "{out}"); assert!( - out.contains(r#"imcp2_active_sessions{instance="prod"} 3"#), + out.contains(concat!(metric!("live_sessions"), r#"{instance="prod"} 7"#)), "{out}" ); assert!( - out.contains( - r#"imcp2_http_request_duration_seconds_count{method="GET",route="/version"} 2"# - ), + out.contains(concat!(metric!("active_sessions"), r#"{instance="prod"} 3"#)), "{out}" ); } - /// 200 distinct paths, sent as real requests, must produce one series. + #[test] + fn scrape_duration_is_recordable_by_the_host() { + let (r, m) = fixture(); + m.observe_scrape(0.004); + assert!( + encode(&r).contains(concat!(metric!("metrics_scrape_duration_seconds"), "_count 1")), + "{}", + encode(&r) + ); + } + #[tokio::test] async fn a_flood_of_distinct_paths_yields_one_series() { - let m = Metrics::new("0", "0", 0).unwrap(); + let (r, m) = fixture(); for i in 0..200 { - let req = Request::builder() + let req = HttpRequest::builder() .uri(format!("/scan-{i}-{}", "x".repeat(i % 13))) .body(Body::empty()) .unwrap(); app(m.clone()).oneshot(req).await.unwrap(); } - let out = m.render().unwrap(); + let out = encode(&r); let series = request_series(&out); assert_eq!(series.len(), 1, "expected one series, got:\n{out}"); assert!(series[0].contains(r#"route="other""#), "{}", series[0]); assert!(series[0].ends_with(" 200"), "{}", series[0]); } - /// The same property for the method label. HTTP permits arbitrary extension - /// tokens, and each unique one previously minted a counter series *and* a - /// full set of histogram buckets — the histogram multiplying the cost by - /// roughly the bucket count. #[tokio::test] async fn a_flood_of_extension_methods_yields_one_series() { - let m = Metrics::new("0", "0", 0).unwrap(); + let (r, m) = fixture(); for i in 0..100 { - let req = Request::builder() + let req = HttpRequest::builder() .method(format!("WIBBLE{i}").as_str()) .uri("/version") .body(Body::empty()) .unwrap(); app(m.clone()).oneshot(req).await.unwrap(); } - let out = m.render().unwrap(); + let out = encode(&r); let series = request_series(&out); assert_eq!(series.len(), 1, "expected one series, got:\n{out}"); assert!(series[0].contains(r#"method="other""#), "{}", series[0]); - // The histogram is where the real damage would be, so bound it too. let buckets = out .lines() - .filter(|l| l.starts_with("imcp2_http_request_duration_seconds_bucket")) + .filter(|l| l.starts_with(concat!(metric!("http_request_duration_seconds"), "_bucket"))) .count(); assert_eq!( buckets, @@ -394,22 +574,21 @@ mod tests { ); } - /// Real traffic still resolves to its own template, so bounding the labels - /// has not flattened everything into `other` and made the metric useless. #[tokio::test] async fn real_routes_keep_their_identity() { - let m = Metrics::new("0", "0", 0).unwrap(); - let req = Request::builder() + let (r, m) = fixture(); + let req = HttpRequest::builder() .uri("/version") .body(Body::empty()) .unwrap(); app(m.clone()).oneshot(req).await.unwrap(); - let out = m.render().unwrap(); assert!( - out.contains( - r#"imcp2_http_requests_total{method="GET",route="/version",status="200"} 1"# - ), - "{out}" + encode(&r).contains(concat!( + metric!("http_requests_total"), + r#"{method="GET",route="/version",status="200"} 1"# + )), + "{}", + encode(&r) ); } } From 0f729509a32a312326afd6773b7bb2c614e2788e Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 7 Aug 2026 15:14:22 +0000 Subject: [PATCH 4/4] metrics: close a cardinality hole the public API opened, and keep the deployed request log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three findings from review of the library move, all real. observe_request was public and took route and method as raw &str, writing both straight in as labels. Only the middleware normalised them, so the bound this module exists to enforce lived one direct call away from being bypassed — and an embedder reaching for the obvious-looking recording API would have bypassed it without noticing. That hole did not exist before the move, because nothing outside the binary could call it; making the module public created it. It is pub(crate) now, with the middleware as the supported entry point, and it normalises the method itself so the invariant holds at the recording site rather than depending on every caller. Reducing the surface now is also cheap in a way it will not be later: taking a public function away after release is a break. The process-start gauge claimed a conventional name it does not have. The prefix macro makes it imcp2_process_start_time_seconds, while the process collector the binary registers exports the actual conventional process_start_time_seconds — and the two measure different moments, observed three seconds apart on a real run: the collector reports OS process start, this reports when the server finished initialising and began serving, which is when a redeploy becomes visible to clients. Both are worth having and an embedder gets only ours, since the library does not register the collector. The comment now says that instead of the opposite. Moving the request log to debug would have silently deleted it in production. Both imcp2.service and the Dockerfile pin RUST_LOG=info, so the line that records what external clients actually probe would simply have stopped appearing on deployed hosts — the full paths the metrics deliberately discard, gone from the one place that keeps them. Both now set info,imcp2::metrics=debug: quiet by default for embedders and local runs, which is what moving it to debug was for, while the deployed hosts keep the record. Verified both filters against a running server: 0 lines under plain info, present with the target enabled. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01R8ZshwKmjD5fZ4Hs9dS6zh --- Dockerfile | 4 +++- deploy/native/imcp2.service | 6 +++++- src/metrics.rs | 36 ++++++++++++++++++++++++++++++------ 3 files changed, 38 insertions(+), 8 deletions(-) diff --git a/Dockerfile b/Dockerfile index 21f5309..5b3ffc1 100644 --- a/Dockerfile +++ b/Dockerfile @@ -23,7 +23,9 @@ RUN apt-get update && apt-get install -y --no-install-recommends ca-certificates COPY --from=build /app/target/release/imcp2 /usr/local/bin/imcp2 # Static assets (signing frontend + WASM codec) are served relative to the workdir. COPY static ./static -ENV RUST_LOG=info +# See deploy/native/imcp2.service: the per-request log line is debug-level, and +# is worth keeping on a deployed host. +ENV RUST_LOG=info,imcp2::metrics=debug # PaaS injects $PORT; the server honours it (default 8000). PUBLIC_URL must be set # to the deployment's public https URL so OAuth discovery + the /app link are correct. CMD ["imcp2"] diff --git a/deploy/native/imcp2.service b/deploy/native/imcp2.service index a5cf622..59ac8d1 100644 --- a/deploy/native/imcp2.service +++ b/deploy/native/imcp2.service @@ -9,7 +9,11 @@ User=ec2-user WorkingDirectory=/opt/imcp2 Environment=PORT=8000 Environment=PUBLIC_URL=__PUBLIC_URL__ -Environment=RUST_LOG=info +# The per-request line moved to debug so it does not drown `info` for embedders +# and local runs. On a deployed host that line is the record of what external +# clients actually probe, so keep it: enable debug for that target only, rather +# than turning the whole crate to debug. +Environment=RUST_LOG=info,imcp2::metrics=debug # Also serve the beta II instance at /mcp-beta on STAGING only. deploy.sh # substitutes __MCP_SERVE_BETA__ per environment: `1` on staging, empty on # production. An empty value reads as off, so production serves /mcp (production diff --git a/src/metrics.rs b/src/metrics.rs index 6f4bc7a..ccca6f3 100644 --- a/src/metrics.rs +++ b/src/metrics.rs @@ -209,9 +209,16 @@ impl Metrics { registry.register(Box::new(build_info.clone()))?; build_info.with_label_values(&[version, commit]).set(1); - // Conventional name and semantics, matching what node_exporter and the - // client libraries use, so existing dashboards and "restarted recently" - // alert expressions work without special-casing this target. + // NOT the conventional `process_start_time_seconds` — the prefix makes it + // `imcp2_process_start_time_seconds`, and it deliberately measures a + // different thing. The process collector's conventional series is the OS + // process start; this is when the server finished initialising and began + // serving, which is the moment a redeploy actually becomes visible to + // clients. On a real host the two differ by a second or two. + // + // Both are worth having, and an embedder gets only this one, since the + // library does not register the process collector — see + // `register_process_collector`. let start_time = IntGauge::new( metric!("process_start_time_seconds"), "Unix epoch seconds at which this process started, i.e. when the deployment \ @@ -229,9 +236,26 @@ impl Metrics { }) } - /// Record one completed request. `route` must already be a bounded template - /// — see [`route_label`]. - pub fn observe_request(&self, route: &str, method: &str, status: u16, elapsed_secs: f64) { + /// Record one completed request. + /// + /// Deliberately **not** public. Making it so would hand an embedder a way to + /// write arbitrary strings straight into `route` and `method`, reintroducing + /// exactly the unbounded cardinality this module exists to prevent — the + /// bound would then live only in the middleware, and be one direct call away + /// from being bypassed. The supported entry point is + /// [`write_request_metrics`], which derives both labels from the request. + /// + /// `method` is normalised here as well as in the middleware. Belt and braces + /// is cheap, and it means the invariant holds at the recording site rather + /// than depending on every caller remembering. + pub(crate) fn observe_request( + &self, + route: &str, + method: &str, + status: u16, + elapsed_secs: f64, + ) { + let method = method_label(method); // `status` is rendered rather than bucketed: HTTP codes are a small // closed set in practice, and keeping the exact code lets a query // separate 401 from 404 from 500, which grouping into 4xx/5xx destroys.