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/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/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/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/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 14a0caf..ad09291 100644 --- a/src/main.rs +++ b/src/main.rs @@ -48,24 +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( - req: axum::http::Request, - next: axum::middleware::Next, -) -> axum::response::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::info!(%method, %path, status, elapsed_ms, "http request"); - resp -} /// The landing page served at `/`: a self-contained design bundle exported from /// Claude Design (`assets/index.html`, compiled in via `include_str!`, no @@ -298,6 +280,27 @@ 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. + // 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()); + // 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 +382,74 @@ 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); + + 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, + [( + 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 +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(log_request)); + // 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 new file mode 100644 index 0000000..ccca6f3 --- /dev/null +++ b/src/metrics.rs @@ -0,0 +1,618 @@ +//! 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 +//! 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. +//! +//! 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 axum::{ + extract::{MatchedPath, Request, State}, + middleware::Next, + response::Response, +}; +use prometheus::{ + 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"; + +/// 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 +/// 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 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 { + requests: IntCounterVec, + duration: HistogramVec, + live_sessions: IntGaugeVec, + active_sessions: IntGaugeVec, + scrapes: Histogram, +} + +impl Metrics { + /// Register this crate's collectors into `registry` and return a handle for + /// recording against them. + /// + /// 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. 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( + metric!("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( + metric!("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( + 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.", + ), + &["instance"], + )?; + registry.register(Box::new(live_sessions.clone()))?; + + let active_sessions = IntGaugeVec::new( + Opts::new( + 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.", + ), + &["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( + 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]), + )?; + 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( + metric!("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); + + // 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 \ + last restarted. Every deploy restarts the service.", + )?; + registry.register(Box::new(start_time.clone()))?; + start_time.set(started_at as i64); + + Ok(Self { + requests, + duration, + live_sessions, + active_sessions, + scrapes, + }) + } + + /// 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. + 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); + } + + /// 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. +/// +/// 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, + } +} + +/// 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 as HttpRequest, routing::get, Router}; + use prometheus::{Encoder, TextEncoder}; + use tower::ServiceExt; + + /// 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 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_with_state( + m, + write_request_metrics, + )) + } + + fn request_series(out: &str) -> Vec<&str> { + out.lines() + .filter(|l| l.starts_with(metric!("http_requests_total")) && l.contains('{')) + .collect() + } + + #[test] + fn unmatched_requests_share_one_label() { + 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"); + } + + #[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 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(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 (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 = encode(&r); + assert!( + out.contains(concat!( + metric!("http_requests_total"), + r#"{method="GET",route="/version",status="200"} 2"# + )), + "{out}" + ); + assert!( + out.contains(concat!(metric!("live_sessions"), r#"{instance="prod"} 7"#)), + "{out}" + ); + assert!( + out.contains(concat!(metric!("active_sessions"), r#"{instance="prod"} 3"#)), + "{out}" + ); + } + + #[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 (r, m) = fixture(); + for i in 0..200 { + 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 = 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]); + } + + #[tokio::test] + async fn a_flood_of_extension_methods_yields_one_series() { + let (r, m) = fixture(); + for i in 0..100 { + 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 = 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]); + + let buckets = out + .lines() + .filter(|l| l.starts_with(concat!(metric!("http_request_duration_seconds"), "_bucket"))) + .count(); + assert_eq!( + buckets, + LATENCY_BUCKETS.len() + 1, + "one label set means one bucket family (+Inf), got:\n{out}" + ); + } + + #[tokio::test] + async fn real_routes_keep_their_identity() { + let (r, m) = fixture(); + let req = HttpRequest::builder() + .uri("/version") + .body(Body::empty()) + .unwrap(); + app(m.clone()).oneshot(req).await.unwrap(); + assert!( + encode(&r).contains(concat!( + metric!("http_requests_total"), + r#"{method="GET",route="/version",status="200"} 1"# + )), + "{}", + encode(&r) + ); + } +}