Observability

You’ve built a service that caches, scales, rate-limits, and offloads work to a queue. Here’s the uncomfortable question: when it’s running on a server you can’t see, how do you know it’s healthy? Not “did it start” — but is it serving requests, is the cache actually helping, is something quietly failing?

That’s observability: the property of a system you can ask questions of from the outside, after the fact, without attaching a debugger. A service you can’t observe is a service you can only pray over.

WHY: the three pillars

Observability is conventionally split into three kinds of signal, and they answer different questions:

• Logs — a timestamped record of discrete events. “What happened, and in what order?” Great for debugging a specific request after it went wrong.
• Metrics — numbers aggregated over time. “How is the system behaving in aggregate?” How many requests, how often the cache hits, how many 404s. Cheap to store, perfect for dashboards and alerts.
• Traces — the path of a single request as it hops across services. “Where did the time go?” This is what you reach for once you have many services calling each other.

Snip implements the first two directly, and is structured so traces could be layered on. Let’s see each one in the code.

Logs: structured, via tracing

A println! is a log, technically — but it’s a string, and strings are miserable to search and filter at scale. Rust’s tracing ecosystem gives us structured logging instead: events carry fields and levels, and a subscriber decides how to render and filter them. We wire it up in the first lines of main:

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")))
    .init();

• tracing_subscriber::fmt() sets up a subscriber that formats events as human-readable lines to stdout.
• with_env_filter(...) controls which events get through, by level and module. EnvFilter reads the RUST_LOG environment variable — so you can run RUST_LOG=debug cargo run --bin snip to see more, or RUST_LOG=warn to see only problems, without recompiling.
• unwrap_or_else(|_| EnvFilter::new("info")) is the fallback: if RUST_LOG isn’t set (or is garbage), default to info and above. Sensible default, easy override.

Once that’s initialized, emitting a log is one macro call. The startup line uses it:

tracing::info!("Snip listening on {bind_addr}");

In production you’d switch the subscriber to emit JSON instead of plain text, so a log aggregator can index every field. The point of going through tracing rather than println! is that this is a configuration change, not a rewrite — the call sites stay the same.

:::note Why this matters in a stateless, multi-replica world Back when we scaled out, Snip became many identical replicas behind nginx. You can’t SSH into “the server” anymore — there are several, and any of them might have handled the request you’re debugging. Structured logs shipped to one place are how you make sense of a fleet. :::

Health: the load balancer’s heartbeat

The /health endpoint is almost insultingly simple:

async fn health() -> impl IntoResponse {
    (StatusCode::OK, "ok")
}

It does nothing but return 200 OK. WHY is that useful? Because it’s not for you — it’s for the load balancer and orchestrator. Docker, Kubernetes, and your cloud’s load balancer periodically hit a health endpoint on each replica. If a replica stops returning 200, the balancer stops sending it traffic and the orchestrator may restart it. (Open-source nginx is the odd one out: active health probes are a commercial nginx Plus feature, so in our stack the probing would be Docker’s job.) This is a liveness probe: “are you alive enough to take requests?”

The simplicity is a feature. A health check must be fast and dependency-light — if /health itself queried Postgres, then a slow database would make every replica look dead, and the balancer would yank them all out of rotation exactly when you need them most. So this probe answers only “is the process up and accepting connections?” That’s the right question for liveness. (A deeper readiness check that does verify dependencies is a fine thing to add separately.)

Metrics: atomic counters and /metrics

Snip tracks five numbers. They live in a Metrics struct made entirely of atomic counters:

#[derive(Default)]
struct Metrics {
    shortens: AtomicU64,
    redirects: AtomicU64,
    cache_hits: AtomicU64,
    cache_misses: AtomicU64,
    not_found: AtomicU64,
}

Why AtomicU64 and not a plain u64? Because many requests run concurrently across many tasks, and they all want to bump the same counter. A normal u64 += 1 from two threads at once is a data race — undefined behavior, and Rust won’t even let you share a plain mutable integer across threads. An AtomicU64 makes the increment a single, indivisible hardware operation: no two increments can clobber each other, and no lock is needed. That last part is the win — a Mutex would serialize every request behind the counter; an atomic lets them all bump it in parallel.

Incrementing happens at each interesting moment in the handlers. From redirect, for example:

state.metrics.redirects.fetch_add(1, Ordering::Relaxed);

and on a cache hit versus miss:

state.metrics.cache_hits.fetch_add(1, Ordering::Relaxed);
// ...elsewhere...
state.metrics.cache_misses.fetch_add(1, Ordering::Relaxed);

fetch_add(1, ...) atomically adds one. The second argument, Ordering::Relaxed, tells the compiler how strict to be about the ordering of this operation relative to other memory operations. For a plain counter where we only care that the total is correct — not that it’s synchronized with other variables — Relaxed is the cheapest correct choice. (Coordinating between atomics needs stronger orderings; a lone tally doesn’t.)

Reading them back is the /metrics endpoint:

async fn metrics_handler(State(state): State<AppState>) -> impl IntoResponse {
    let m = &state.metrics;
    let body = format!(
        "shortens {}\nredirects {}\ncache_hits {}\ncache_misses {}\nnot_found {}\n",
        m.shortens.load(Ordering::Relaxed),
        m.redirects.load(Ordering::Relaxed),
        m.cache_hits.load(Ordering::Relaxed),
        m.cache_misses.load(Ordering::Relaxed),
        m.not_found.load(Ordering::Relaxed),
    );
    (StatusCode::OK, body)
}

load(Ordering::Relaxed) reads each counter’s current value, and we format them as plain name value lines — the same shape Prometheus scrapes. A metrics system polls this endpoint every few seconds and graphs the rate of change, turning these raw totals into “redirects per second” and friends.

Why instrument the cache-hit ratio specifically

cache_hits and cache_misses aren’t arbitrary. Back in Caching with Redis the entire bet was that most redirects would be served from cache. That bet is invisible unless you measure it. The cache-hit ratio — hits / (hits + misses) — tells you directly whether the cache is earning its keep:

• A high ratio (say 0.95) means the cache is doing its job; 95% of redirects skip Postgres entirely.
• A falling ratio is an early warning — maybe traffic shifted to brand-new links, or your TTL is too short, or someone is scanning random codes. You see the symptom in a graph before users feel it as latency.

This is the discipline the whole part has pushed: don’t claim a win, measure it. The cache-hit ratio is that measurement, exposed.

Try it

Start the service (cargo run --bin snip), then generate a little traffic so the counters have something to show:

# one shorten
code=$(curl -s -X POST localhost:8080/shorten \
  -H 'content-type: application/json' \
  -d '{"url":"https://example.com"}' | grep -o '"code":"[^"]*"' | cut -d'"' -f4)

# hit the redirect several times — first is a miss, rest are hits
for i in $(seq 1 5); do curl -s localhost:8080/$code -o /dev/null; done

# one guaranteed miss → not_found
curl -s localhost:8080/nope999 -o /dev/null

# confirm liveness
curl localhost:8080/health

# read the metrics
curl localhost:8080/metrics

You should see something like:

shortens 1
redirects 6
cache_hits 4
cache_misses 2
not_found 1

Now do the math the dashboards would: cache_hits / (cache_hits + cache_misses) = 4 / 6 ≈ 0.67. The first redirect missed (cache was empty), the not_found request missed (and counted as not_found), and the rest hit. Hammer the same code more times and watch the ratio climb toward 1.0 — proof, in a number, that the cache is working.

Check your understanding

1. Logs, metrics, and traces each answer a different question. Match each pillar to the question it answers best, and say which two Snip implements directly.
2. Why must /health stay dependency-light? What goes wrong for the whole fleet if it queries Postgres and the database gets slow?
3. Why is AtomicU64 used for the counters instead of a plain u64 guarded by nothing — and why is it preferable to a Mutex<u64> here?
4. What does Ordering::Relaxed mean for fetch_add, and why is it an acceptable choice for these particular counters?
5. Given cache_hits 4 and cache_misses 2, compute the cache-hit ratio. Name one real cause that would make this ratio fall over time, and explain why you’d want an alert on it.

Show answers

1. Logs answer “what happened, and in what order?” (discrete timestamped events); metrics answer “how is the system behaving in aggregate?” (numbers over time); traces answer “where did the time go?” (one request’s path across services). Snip implements the first two — logs and metrics — directly, and is structured so traces could be layered on.
2. A health check must be fast and dependency-light because it’s a liveness probe — “is the process up and accepting connections?” If /health queried Postgres and the database got slow, every replica would look dead, so the load balancer would yank them all out of rotation at once — exactly when you need them most. (Verifying dependencies is a separate readiness check.)
3. Many requests bump the same counter concurrently, and a plain u64 += 1 from two threads is a data race — undefined behavior that Rust won’t even let you share across threads. AtomicU64 makes the increment a single indivisible hardware operation with no lock; a Mutex<u64> would work but serialize every request behind the counter, whereas an atomic lets them all bump it in parallel.
4. Ordering::Relaxed tells the compiler not to enforce any ordering of this increment relative to other memory operations — it only guarantees the increment itself is atomic. It’s acceptable for these counters because we care only that the total is eventually correct, not that it’s synchronized with other variables, so it’s the cheapest correct choice. (Coordinating between atomics would need a stronger ordering.)
5. 4 / (4 + 2) = 0.67. A real cause of a falling ratio is traffic shifting to brand-new links (every first hit is a miss), or a too-short TTL, or someone scanning random codes. You’d alert on it because a falling hit ratio is an early warning — you see the symptom in a graph before users feel it as added latency from extra Postgres round-trips. This is the part’s whole discipline: don’t claim a win, measure it.