tidaldb/tidal-server/src/http_metrics.rs
jordan 4766f566de feat(observability): HTTP metrics, structured logs, dashboard, live tidalctl
There was no metric anywhere that could answer "how much traffic are we serving"
or "what is our error rate". The engine published a rich DOMAIN surface (search
latency, WAL fsync, quorum timeouts, replication lag) and nothing about HTTP, so
a cluster could serve 401s or 503s indefinitely with every existing gauge looking
healthy. Logs were collected but unusable. There was no way to ask a RUNNING node
anything.

1. HTTP metrics. tidaldb_http_requests_total{route,method,status} plus a
   per-route duration histogram, recorded by one layer placed OUTSIDE the auth,
   timeout and rate-limit layers so it sees the status actually returned to the
   client. Cardinality is the whole design: the route label is axum's MatchedPath
   TEMPLATE, not the path, and unmatched requests collapse into one <unmatched>
   bucket so a 404 flood cannot mint series. A hard cap folds anything past it
   into an overflow bucket while established series keep counting.

   The engine owns the /metrics listener but must not learn what a route or a
   status code is, so it gained one registration hook
   (MetricsState::set_extra_renderer) and tidal-server publishes through it. One
   scrape target per node, not two.

2. Structured logs. The previous init was a bare tracing_subscriber::fmt(), which
   produced two real defects: ANSI escapes leaked into collected logs, and every
   line failed the collector's JSON parse and was stamped level=info — so
   `level:error` matched NOTHING and errors were invisible to the log platform
   while being collected. JSON_LOGS=1 emits the collector's exact wire format
   (ts/level/service/env/msg), span fields are lifted so request_id lands on every
   line of a request, and ANSI is off unconditionally in both formats.

   Verified against the running binary, which caught a defect no unit test would
   have: dependencies logging through the `log` crate arrived with target="log"
   and four log.* metadata fields (absolute cargo registry paths, indexed
   forever). The real module is now lifted into target and the bridge metadata
   pruned.

3. Dashboard. docs/ops/grafana-tidaldb.json, 13 panels, mirrored into the fleet
   as a grafana-database-dashboards key. Every metric name was checked against a
   live endpoint and all 26 PromQL expressions were executed against the live
   TSDB before commit, because a dashboard full of "No data" is worse than none.
   Confirmed loaded in Grafana (uid tidaldb-overview, Databases folder).

4. tidalctl live mode. Every other subcommand reads a data dir AT REST, some
   requiring a stopped node. `search`, `feed`, `cluster-status` and `watch` take
   --url and talk to a running server, with --ca/--insecure because a cluster's
   client port is served with the INTERNAL cluster CA. Exit codes follow the crate
   contract, so `tidalctl cluster-status && deploy` gates on convergence.

   Its first real run immediately found a reporting defect: the aggregated
   /cluster/status reported two HEALTHY peers as UNREACHABLE PARTITIONED at 13.3M
   lag, having derived lag against an uninitialised applied=0, while every node's
   own status reported lag=0, reseed=false and identical frontiers, with
   pod-to-pod connectivity open and nothing logged. cluster-status now names that
   signature "NO REPORT (aggregated view; query the node directly)" instead of
   repeating it as replication lag; a genuine non-zero-applied lag still reports
   BEHIND. The underlying gap is documented as open work in
   docs/ops/observability.md.

Verified: 2101 + 175 engine/server unit tests, 8 standalone integration (3 new,
including the cardinality proof and the cross-crate metrics seam), 23 tidalctl
(10 new), reseed + catchup + admin-gate e2e green, clippy clean, and both the
metrics and the log format exercised against a real running binary.
2026-08-23 10:31:57 -06:00

378 lines
14 KiB
Rust
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

//! HTTP surface metrics: request counts by route/method/status, and per-route
//! latency.
//!
//! WHY THIS EXISTS: the engine publishes a rich DOMAIN surface (search latency,
//! WAL fsync, quorum timeouts, replication lag) but nothing about HTTP. There
//! was no way to answer "how many requests did we serve" or "what is our error
//! rate" from metrics at all — a production cluster could serve 401s or 503s
//! indefinitely with every existing gauge looking healthy.
//!
//! CARDINALITY IS THE WHOLE DESIGN CONSTRAINT. A naive `path` label explodes:
//! `/items/12345` is a distinct series per entity. Two defences:
//!
//! 1. The route label is axum's [`MatchedPath`] — the route TEMPLATE
//! (`/cluster/shards/{id}/transfer`), not the concrete path. Bounded by the
//! router's route count, whatever the traffic.
//! 2. A hard [`MAX_SERIES`] cap. Anything past it folds into an explicit
//! overflow bucket, so a future router change (or an unmatched-path flood)
//! degrades the labels rather than the process.
//!
//! Unmatched requests carry no `MatchedPath`, so they are attributed to a single
//! constant [`UNMATCHED_ROUTE`] rather than their (attacker-controlled) path.
use std::collections::HashMap;
use std::sync::Mutex;
use std::time::Instant;
use axum::extract::MatchedPath;
use axum::extract::Request;
use axum::middleware::Next;
use axum::response::Response;
use tidaldb::{LatencyHistogram, QUERY_LATENCY_BOUNDS};
/// Route label for a request that matched no route (404s, and anything rejected
/// before routing). A single constant, never the caller-supplied path — that
/// path is attacker-controlled and would be an unbounded label.
const UNMATCHED_ROUTE: &str = "<unmatched>";
/// Route label used once [`MAX_SERIES`] distinct keys exist.
const OVERFLOW_ROUTE: &str = "<over-cap>";
/// Hard ceiling on distinct (route, method, status) keys.
///
/// The template-based route label already bounds this to roughly
/// routes × methods × observed-statuses (~250 for the cluster router). The cap
/// exists so a future refactor that accidentally admits a dynamic route label
/// cannot grow this map without bound; it degrades to [`OVERFLOW_ROUTE`].
const MAX_SERIES: usize = 512;
/// One counted series: a route template, method, and HTTP status.
#[derive(PartialEq, Eq, Hash, Clone)]
struct Key {
route: Box<str>,
method: &'static str,
status: u16,
}
/// HTTP request counters and per-route latency for one server process.
///
/// Registered with the engine's metrics listener via
/// `MetricsState::set_extra_renderer`, so these series appear on the SAME
/// scrape target as the engine's own — one target per node, not two.
pub struct HttpMetrics {
/// Counts keyed by (route, method, status).
///
/// `std::sync::Mutex<HashMap>` rather than a lock-free structure or
/// `parking_lot`, deliberately. The critical section is one hash and one
/// `u64` increment (tens of nanoseconds) against requests that already do
/// WAL fsyncs and vector searches (hundreds of microseconds and up), and the
/// in-flight cap at `router::MAX_CONCURRENCY` bounds the contention ceiling.
/// `std::sync` is also what the rest of this workspace uses — introducing
/// `parking_lot` for one module would plant a second convention. Poisoning
/// is handled, never unwrapped: losing a metric sample must not fail a
/// request that already succeeded.
counts: Mutex<HashMap<Key, u64>>,
/// Per-route end-to-end latency, in microseconds.
latency: Mutex<HashMap<Box<str>, LatencyHistogram>>,
}
/// The process-wide HTTP metrics.
///
/// A process serves one HTTP surface through one `/metrics` listener, so a
/// single instance is the honest model — and it keeps the recording layer from
/// having to be threaded through all three router builders (standalone,
/// single-process cluster, multi-process region) and their call sites.
static GLOBAL: std::sync::LazyLock<std::sync::Arc<HttpMetrics>> =
std::sync::LazyLock::new(|| std::sync::Arc::new(HttpMetrics::new()));
/// Handle to the process-wide HTTP metrics.
#[must_use]
pub fn global() -> std::sync::Arc<HttpMetrics> {
std::sync::Arc::clone(&GLOBAL)
}
/// Publish this process's HTTP series on the engine's existing `/metrics`
/// listener.
///
/// Call once after opening the database. Returns `false` if a renderer was
/// already registered (the engine ignores the second call rather than
/// double-rendering).
pub fn publish_to(metrics: &tidaldb::MetricsState) -> bool {
metrics.set_extra_renderer(Box::new(|out| global().render_into(out)))
}
impl std::fmt::Debug for HttpMetrics {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
let series = self.counts.lock().map_or(0, |m| m.len());
f.debug_struct("HttpMetrics")
.field("series", &series)
.finish_non_exhaustive()
}
}
impl Default for HttpMetrics {
fn default() -> Self {
Self::new()
}
}
impl HttpMetrics {
#[must_use]
pub fn new() -> Self {
Self {
counts: Mutex::new(HashMap::new()),
latency: Mutex::new(HashMap::new()),
}
}
/// Record one completed request.
///
/// `route` should be the matched TEMPLATE. Poisoned locks are ignored rather
/// than propagated: losing a metric sample must never fail a request that
/// already succeeded.
pub fn record(&self, route: &str, method: &'static str, status: u16, elapsed_us: u64) {
if let Ok(mut counts) = self.counts.lock() {
let key = Key {
route: route.into(),
method,
status,
};
// Only admit a NEW key while under the cap; existing keys always
// increment, so an established series never stops counting because
// the map happens to be full.
if let Some(hit) = counts.get_mut(&key) {
*hit += 1;
} else if counts.len() < MAX_SERIES {
counts.insert(key, 1);
} else {
*counts
.entry(Key {
route: OVERFLOW_ROUTE.into(),
method,
status,
})
.or_insert(0) += 1;
}
}
if let Ok(mut latency) = self.latency.lock() {
if let Some(hist) = latency.get(route) {
hist.observe(elapsed_us);
} else if latency.len() < MAX_SERIES {
let hist = LatencyHistogram::new(QUERY_LATENCY_BOUNDS);
hist.observe(elapsed_us);
latency.insert(route.into(), hist);
}
}
}
/// Append this process's HTTP series in Prometheus text format.
///
/// Label values are escaped: a route template is repo-controlled, but
/// emitting an unescaped label is the kind of thing that silently corrupts a
/// whole scrape, so it is not left to chance.
pub fn render_into(&self, out: &mut String) {
use std::fmt::Write;
if let Ok(counts) = self.counts.lock() {
let _ = write!(
out,
"\n# HELP tidaldb_http_requests_total Total HTTP requests served, by matched route \
template, method, and response status.\n\
# TYPE tidaldb_http_requests_total counter\n"
);
// Sorted so a diff of two scrapes is readable and the output is
// deterministic for tests.
let mut rows: Vec<_> = counts.iter().collect();
rows.sort_unstable_by(|(a, _), (b, _)| {
(&a.route, a.method, a.status).cmp(&(&b.route, b.method, b.status))
});
for (key, count) in rows {
let _ = writeln!(
out,
"tidaldb_http_requests_total{{route=\"{}\",method=\"{}\",status=\"{}\"}} {count}",
escape_label(&key.route),
key.method,
key.status
);
}
}
if let Ok(latency) = self.latency.lock() {
let mut routes: Vec<_> = latency.iter().collect();
routes.sort_unstable_by(|(a, _), (b, _)| a.cmp(b));
for (route, hist) in routes {
out.push_str(&hist.render_prometheus_labeled(
"tidaldb_http_request_duration_us",
"HTTP request end-to-end latency in microseconds, by matched route template.",
&format!("route=\"{}\"", escape_label(route)),
));
}
}
}
}
/// Escape a Prometheus label value per the exposition format: backslash, double
/// quote, and newline.
fn escape_label(raw: &str) -> String {
if !raw.contains(['\\', '"', '\n']) {
return raw.to_string();
}
let mut out = String::with_capacity(raw.len() + 8);
for c in raw.chars() {
match c {
'\\' => out.push_str("\\\\"),
'"' => out.push_str("\\\""),
'\n' => out.push_str("\\n"),
other => out.push(other),
}
}
out
}
/// Map a method to a `'static` label, so the common ones cost no allocation and
/// an exotic one cannot become an unbounded label value.
fn method_label(method: &axum::http::Method) -> &'static str {
match *method {
axum::http::Method::GET => "GET",
axum::http::Method::POST => "POST",
axum::http::Method::PUT => "PUT",
axum::http::Method::DELETE => "DELETE",
axum::http::Method::PATCH => "PATCH",
axum::http::Method::HEAD => "HEAD",
axum::http::Method::OPTIONS => "OPTIONS",
_ => "OTHER",
}
}
/// Middleware recording every request into `metrics`.
///
/// Applied as the OUTERMOST layer on each router so it observes the response
/// actually returned to the client — including the 401/403 from the auth gates,
/// the 408 from the timeout layer, and the 429 from the rate limiter. A layer
/// applied further in would miss exactly the failures worth counting.
pub async fn track(metrics: std::sync::Arc<HttpMetrics>, req: Request, next: Next) -> Response {
// The template, not the concrete path. Absent for unmatched requests.
let route = req
.extensions()
.get::<MatchedPath>()
.map_or(UNMATCHED_ROUTE, |m| m.as_str())
.to_string();
let method = method_label(req.method());
let started = Instant::now();
let response = next.run(req).await;
let elapsed_us = u64::try_from(started.elapsed().as_micros()).unwrap_or(u64::MAX);
metrics.record(&route, method, response.status().as_u16(), elapsed_us);
response
}
#[cfg(test)]
#[allow(clippy::unwrap_used)]
mod tests {
use super::*;
#[test]
fn counts_are_keyed_by_route_method_and_status() {
let m = HttpMetrics::new();
m.record("/items", "POST", 201, 10);
m.record("/items", "POST", 201, 20);
m.record("/items", "POST", 401, 5);
m.record("/search", "GET", 200, 30);
let mut out = String::new();
m.render_into(&mut out);
assert!(out.contains(
"tidaldb_http_requests_total{route=\"/items\",method=\"POST\",status=\"201\"} 2"
));
assert!(out.contains(
"tidaldb_http_requests_total{route=\"/items\",method=\"POST\",status=\"401\"} 1"
));
assert!(out.contains(
"tidaldb_http_requests_total{route=\"/search\",method=\"GET\",status=\"200\"} 1"
));
}
/// The error surface is the reason this module exists, so prove a 5xx is
/// distinguishable from a success on the same route.
#[test]
fn errors_are_countable_separately_from_successes() {
let m = HttpMetrics::new();
for _ in 0..7 {
m.record("/feed", "GET", 200, 100);
}
m.record("/feed", "GET", 503, 100);
let mut out = String::new();
m.render_into(&mut out);
assert!(out.contains("route=\"/feed\",method=\"GET\",status=\"200\"} 7"));
assert!(out.contains("route=\"/feed\",method=\"GET\",status=\"503\"} 1"));
}
#[test]
fn latency_histogram_is_rendered_per_route() {
let m = HttpMetrics::new();
m.record("/search", "GET", 200, 1_500);
let mut out = String::new();
m.render_into(&mut out);
assert!(out.contains("tidaldb_http_request_duration_us"));
assert!(out.contains("route=\"/search\""));
// A histogram must carry bucket + count series, not just a gauge.
assert!(out.contains("_bucket"), "expected le buckets: {out}");
assert!(out.contains("_count"));
}
/// Cardinality is the failure mode this design exists to prevent: past the
/// cap, NEW keys must fold into one overflow bucket instead of growing the
/// map, while already-tracked series keep counting.
#[test]
fn series_are_capped_and_existing_keys_keep_counting() {
let m = HttpMetrics::new();
for i in 0..MAX_SERIES {
m.record(&format!("/r{i}"), "GET", 200, 1);
}
// Established key still increments at the cap.
m.record("/r0", "GET", 200, 1);
// A brand new key does NOT add a series.
m.record("/brand-new", "GET", 200, 1);
let counts = m.counts.lock().unwrap();
assert!(
counts.len() <= MAX_SERIES + 1,
"map grew past the cap (+1 overflow bucket): {}",
counts.len()
);
assert_eq!(
*counts
.get(&Key {
route: "/r0".into(),
method: "GET",
status: 200
})
.unwrap(),
2
);
assert!(
counts.keys().any(|k| &*k.route == OVERFLOW_ROUTE),
"over-cap requests must be attributed to the overflow bucket"
);
assert!(
!counts.keys().any(|k| &*k.route == "/brand-new"),
"a new route past the cap must NOT create its own series"
);
}
#[test]
fn label_values_are_escaped() {
assert_eq!(escape_label("/items"), "/items");
assert_eq!(escape_label("a\"b"), "a\\\"b");
assert_eq!(escape_label("a\\b"), "a\\\\b");
assert_eq!(escape_label("a\nb"), "a\\nb");
}
#[test]
fn exotic_methods_collapse_to_a_bounded_label() {
assert_eq!(method_label(&axum::http::Method::GET), "GET");
assert_eq!(method_label(&axum::http::Method::TRACE), "OTHER");
}
}