tidaldb/docs/ops/observability.md
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

6.4 KiB

Observability: usage, errors, and live debugging

Four surfaces, in the order you reach for them during an incident.

Question Surface
How much traffic, and how much of it is failing? Grafana → tidalDB — usage, errors, and cluster health
What exactly failed, for which request? VictoriaLogs, level:error, correlate on request_id
Is the cluster converged right now? tidalctl cluster-status / tidalctl watch
What does a query actually return? tidalctl search / tidalctl feed

1. Metrics

Every node serves Prometheus text on its --metrics address (:9091 in the shipped manifests). Never expose that port externally — it is unauthenticated. In-cluster it is reachable only from the observability namespace (k8s/cluster/networkpolicy.yaml).

Two families answer the usage/error questions:

tidaldb_http_requests_total{route,method,status}   counter
tidaldb_http_request_duration_us{route}            histogram

route is the matched route template (/cluster/shards/{id}/transfer), not the concrete path, so cardinality is bounded by the router rather than by traffic. Unmatched requests collapse into a single <unmatched> bucket — a 404 flood cannot mint series.

These are published by tidal-server onto the engine's existing listener (via MetricsState::set_extra_renderer), so a node remains one scrape target.

Useful queries:

# request rate by route
sum by (route) (rate(tidaldb_http_requests_total[5m]))

# server-fault ratio
  sum(rate(tidaldb_http_requests_total{status=~"5.."}[5m]))
/ sum(rate(tidaldb_http_requests_total[5m]))

# who is being refused, and where
sum by (status, route) (rate(tidaldb_http_requests_total{status=~"401|403"}[5m]))

# client-observed p99, in ms
histogram_quantile(0.99,
  sum by (route, le) (rate(tidaldb_http_request_duration_us_bucket[5m]))) / 1000

Read 403 precisely: it means a valid data bearer was used against an operator verb (/cluster/*). A sustained 403 rate is a client holding the wrong key, or someone probing — not a server fault.

Dashboard

docs/ops/grafana-tidaldb.json is the source of truth, mirrored into the fleet as the tidaldb-overview.json key of the grafana-database-dashboards ConfigMap — the same convention docs/ops/prometheus-alerts.yaml follows. Edit here, then mirror. It lands in Grafana's Databases folder as tidaldb-overview.


2. Logs

Set JSON_LOGS=1 (or TIDAL_LOG_FORMAT=json) to emit one JSON object per line in the collector's wire format:

{"ts":"2026-08-23T15:57:57.090256Z","level":"info","service":"tidal-server",
 "env":"prod","msg":"committing 5","target":"tantivy::indexer","request_id":"418"}

Why it matters: the fleet's Vector collector parses each line as JSON and, on success, replaces the event with that object; on failure it keeps the text and stamps level = "info". Without JSON, every tidalDB line was recorded as info and level:error matched nothing — errors were collected but invisible.

  • level is lowercase, matching the collector's enum (critical|error|warn|info|debug).
  • request_id from the per-request span appears on every line emitted inside it, so one request's work is correlatable rather than grep-adjacent.
  • target is the real module even for dependencies logging through the log crate (their bridge metadata is pruned rather than indexed forever).
  • ANSI colour is off in both formats. It used to leak escape codes into stored logs.

Tunables: TIDAL_SERVER_LOG (env-filter, e.g. tidal_server=debug,tantivy=warn,info to quiet a noisy dependency), TIDAL_SERVICE_NAME, TIDAL_ENV.

# errors, last 15 minutes
_time:15m AND kubernetes.pod_namespace:tidaldb-cluster AND level:error

# one request end to end
_time:1h AND request_id:"418"

3. Live debugging with tidalctl

Every other tidalctl command reads a data directory at rest — some require a stopped node. These take --url and talk to a running server.

export TIDAL_API_KEY=...          # or pass --key

# Is it converged? Exits 2 when not, so it gates a deploy.
tidalctl cluster-status --url http://127.0.0.1:9500

# Watch convergence (Ctrl-C to stop, or bound it with --count)
tidalctl watch --url http://127.0.0.1:9500 --interval 5 --count 12

# What does a query actually return?
tidalctl search --url http://127.0.0.1:9500 --query "cold brew" --limit 5
tidalctl feed   --url http://127.0.0.1:9500 --profile trending --user-id 42

TLS. A cluster node's client port is served with the internal cluster CA, issued for in-cluster DNS names, so a port-forward fails both CA and hostname verification. Pin the CA with --ca ca.pem, or use --insecure for a local forward:

kubectl -n tidaldb-cluster port-forward svc/tidaldb 9500:9500 &
tidalctl cluster-status --url https://127.0.0.1:9500 --insecure

Exit codes follow the crate contract: 0 ok, 1 usage error, 2 degraded — unreachable, non-2xx, or not converged. A 403 response prints the hint to use the admin key.


4. Known caveat: the aggregated /cluster/status under-reports peers

The aggregated view can report a peer it holds no frontier report for as applied_events: 0, and derive lag_events against that zero — so a fully converged peer appears to be the leader's entire history behind, sometimes with reachable: false / partitioned: true alongside.

Observed 2026-08-23: two healthy nodes shown as UNREACHABLE PARTITIONED at 13.3M lag, while every node's own /cluster/status/local reported lag=0, reseed_required=false, and identical per-group frontiers. Pod-to-pod connectivity was open and no error was logged.

tidalctl cluster-status detects that signature (applied == 0 with non-zero lag) and prints NO REPORT (aggregated view; query the node directly) rather than repeating it as replication lag. A genuine lag report — non-zero applied with non-zero lag — still reports BEHIND.

When you see NO REPORT, confirm against the nodes themselves before treating it as an incident:

for i in 0 1 2; do
  kubectl -n tidaldb-cluster port-forward tidaldb-$i 1970$i:9500 >/dev/null 2>&1 &
  sleep 8
  curl -sk -H "Authorization: Bearer $TIDAL_API_KEY" \
    "https://127.0.0.1:1970$i/cluster/status/local" | jq '{region, reseed_required, shards}'
  kill %1
done

The underlying reporting gap in the aggregated surface is open work; it is a reporting defect, not a replication one.