Phase 4 · Chapter 5

Observability: Logs, Metrics & Distributed Tracing

How to see inside a running distributed system — and why printf debugging kills you at scale

You cannot attach a debugger to production. You cannot reproduce most production failures locally. The only way to understand what a distributed system is doing — or what it did when it failed at 3am — is to have instrumented it correctly beforehand. Observability is the practice of making a system's internal state inferrable from its external outputs. After this chapter you will understand the three pillars of observability, why each one exists, what specific questions each one answers, and how they connect into a coherent system for diagnosing production failures. You will also understand why naive logging approaches fail under scale and how structured logging, metric cardinality, and distributed trace propagation solve problems that no amount of ad-hoc debugging can.

Part 1: The Problem — You Are Flying Blind

Consider what happens when a user reports "the app is slow." On a single-server Node.js app, you might SSH in, run top, tail the logs, and figure it out. Now consider the same complaint on a system with:

• A Next.js frontend on Vercel
• Three Node.js API servers behind a load balancer
• A BullMQ worker cluster with 5 instances
• Redis for caching and job queues
• Postgres primary with two replicas
• Two third-party APIs (payment processor, email provider)

The request touched multiple systems. The slowness could be in any one of them. The relevant logs are spread across six different machines. The state at the time of the failure no longer exists — the process has moved on, the Redis state has changed, the Postgres lock has released.

This is the fundamental challenge of distributed systems observability: failures are transient, distributed, and causally entangled. By the time you notice them, the evidence is already dispersed or gone.

The solution is not better logging. It is a systematic approach to capturing three different types of signals, each answering a different question:

• Metrics: What is the system doing right now, in aggregate? (Is it healthy? Where are the hotspots?)
• Logs: What specific events happened, in what order, with what data? (What did the system do during a specific incident?)
• Traces: How did a specific request flow through the system? (Which service caused the latency? Where did this error originate?)

These are the three pillars of observability. No single one is sufficient alone. Together they give you complete visibility into a running system.

Part 2: Metrics — Aggregate Signals Over Time

A metric is a numerical measurement taken at regular intervals. A time series of metrics tells you how the system is behaving over time — not what any individual request did, but what the population of requests is doing.

What metrics answer

• Is the system healthy right now?
• Is latency increasing over time?
• Is error rate elevated compared to baseline?
• Which endpoint has the highest request volume?
• Is the database connection pool saturation growing?
• When did memory usage start climbing?

These questions require aggregate data over time. A log that says "this request took 300ms" does not tell you whether 300ms is normal or a degradation. A metric that says "p99 latency was 45ms last week and is 300ms today" tells you something changed.

The four golden signals

Google's Site Reliability Engineering book defines four signals that together characterise the health of any service. These are not aspirational — they are the minimum viable metric set.

Latency: How long does it take to serve a request? Measure as percentiles, not averages. A latency average of 50ms hides the fact that 1% of requests take 5 seconds — the users experiencing those 5-second requests are your most frustrated users and most likely churners. Standard percentiles: p50 (median), p95, p99, p999.

Traffic: How much demand is the system handling? Requests per second, queries per second, bytes transferred. Traffic tells you the scale context for all other signals — a p99 latency of 200ms at 10 req/s is very different from 200ms at 10,000 req/s.

Errors: What fraction of requests are failing? Measure error rate as a percentage of total traffic, not as an absolute count. 100 errors/second during 10,000 req/s traffic is a 1% error rate. 100 errors/second during 110 req/s traffic is a 91% error rate. The absolute number is meaningless without traffic context.

Saturation: How full is the system's most constrained resource? CPU utilisation, memory usage, database connection pool utilisation, queue depth. Saturation predicts future failures before they happen. A connection pool at 95% utilisation will hit 100% soon.

Cardinality — why naive metric labelling fails

A metric is useless unless you can slice it by the dimensions that matter. You need to know not just "what is the average API latency" but "what is the p99 latency for the /api/evaluate endpoint for Pro plan users from the Mumbai region."

The way you express these dimensions in metrics is through labels (also called tags or dimensions depending on the system). A metric like http_request_duration_seconds might have labels: endpoint, method, status_code, user_plan.

Cardinality is the number of unique label value combinations. This is where naive metric design becomes expensive.

endpoint might have 50 values. method has 5. status_code has 20. user_plan has 3. Total cardinality: 50 × 5 × 20 × 3 = 15,000 time series. Manageable.

Now add user_id as a label. If you have 100,000 users, cardinality explodes to 1.5 billion time series. Prometheus (the standard metrics system) stores each time series separately in memory. 1.5 billion time series kills your metrics infrastructure.

The rule: Never use high-cardinality values (user IDs, request IDs, email addresses, IP addresses) as metric labels. High-cardinality dimensions belong in logs and traces, not metrics. Metrics are for aggregate signals. If you need per-user data, query the database or traces.

Prometheus and the metrics pipeline

Prometheus is the standard metrics system for backend services. The architecture:

Your service exposes an HTTP endpoint /metrics that returns current metric values in Prometheus text format. Prometheus scrapes this endpoint on a schedule and stores the values. Grafana queries Prometheus and renders dashboards.

In Node.js:

import { register, Counter, Histogram } from 'prom-client';

// Counter: monotonically increasing, never decreases
const httpRequestsTotal = new Counter({
  name: 'http_requests_total',
  help: 'Total HTTP requests',
  labelNames: ['method', 'endpoint', 'status_code'],
});

// Histogram: records distribution of values (for latency)
const httpRequestDuration = new Histogram({
  name: 'http_request_duration_seconds',
  help: 'HTTP request duration in seconds',
  labelNames: ['method', 'endpoint'],
  buckets: [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5],
});

// In your middleware:
app.use((req, res, next) => {
  const end = httpRequestDuration.startTimer({
    method: req.method,
    endpoint: req.route?.path ?? 'unknown',
  });

  res.on('finish', () => {
    httpRequestsTotal.inc({
      method: req.method,
      endpoint: req.route?.path ?? 'unknown',
      status_code: res.statusCode,
    });
    end();
  });

  next();
});

// Expose metrics endpoint
app.get('/metrics', async (req, res) => {
  res.set('Content-Type', register.contentType);
  res.send(await register.metrics());
});

The four metric types: Counter (only increases — total requests, total errors), Gauge (can go up or down — current connection count, memory usage), Histogram (distribution of values with configurable buckets — latency, request size), Summary (like histogram but computes percentiles client-side — use histogram instead, Prometheus aggregates histograms across instances; summaries cannot be aggregated).

Part 3: Logs — Event Records With Context

A log is a timestamped record of a discrete event. Unlike metrics, logs are not aggregated — every individual event produces a log entry. Logs answer "what happened" for specific events.

Why printf logging fails at scale

The natural instinct is to log like this:

console.log(`User ${userId} submitted test ${testId}, score: ${score}`);
console.log(`Error processing payment for order ${orderId}: ${error.message}`);

This produces log lines that humans can read. At scale, it breaks down:

Searching is slow. Logs are stored as text. Finding all log lines where userId = 12345 requires a text search — either grep (impractical at terabytes of logs) or a regex scan on your log aggregation system. Without structure, you cannot query logs efficiently.

Correlation is impossible. A request touches five services. Each service logs its own messages in its own format. There is no field connecting the log lines for the same request across services. You cannot reconstruct what happened to a specific request.

Parsing is fragile. To extract userId from the above log line, a log aggregation system must parse the text with a regex or grok pattern. Patterns break when message formats change.

Structured logging

The fix is to emit logs as structured data — JSON objects — where every field is explicitly named and typed.

// Bad: unstructured
console.log(`User ${userId} submitted test ${testId}, score: ${score}`);

// Good: structured
logger.info({
  event: 'test_submitted',
  userId,
  testId,
  score,
  durationMs: Date.now() - startTime,
  requestId: req.headers['x-request-id'],
});

Structured log output:

{
  "level": "info",
  "timestamp": "2025-03-15T14:23:45.123Z",
  "event": "test_submitted",
  "userId": 12345,
  "testId": 89,
  "score": 78,
  "durationMs": 234,
  "requestId": "req_8f3k2m9p",
  "service": "api-server",
  "version": "2.3.1"
}

Now your log aggregation system (Loki, Datadog, CloudWatch Logs) can index these fields. You can query: event = "test_submitted" AND score < 50 AND durationMs > 1000 — find all slow, low-scoring test submissions in the last hour. This query runs in milliseconds against indexed structured logs, versus minutes against a text grep.

Log levels and when to use them

ERROR   → something failed and requires attention. A request failed, a job crashed,
          an external API returned 5xx. Every error should be actionable.

WARN    → something unexpected happened but the system recovered.
          A retry succeeded. A cache miss hit the database. A rate limit was hit.
          Warns should be investigated if they are frequent.

INFO    → normal operational events worth recording.
          Request completed. Job processed. User authenticated.
          One INFO log per significant business event, not per function call.

DEBUG   → detailed diagnostic data. Not logged in production by default.
          Enabled selectively when diagnosing a specific issue.

The most common mistake is logging too much at INFO level. If every function call logs an INFO message, a service handling 1,000 req/s generates millions of log lines per hour. Log aggregation systems charge by ingestion volume. Signal drowns in noise. Log significant events, not activity.

The request ID — the thread connecting distributed logs

Every incoming request should be assigned a unique ID. This ID propagates through every service the request touches and appears in every log line related to that request. This is the mechanism that lets you reconstruct the full story of a single request across services.

// In your API gateway / first service:
app.use((req, res, next) => {
  req.requestId = req.headers['x-request-id'] || crypto.randomUUID();
  res.setHeader('x-request-id', req.requestId);
  next();
});

// When calling downstream services:
fetch('http://evaluations-service/evaluate', {
  headers: {
    'x-request-id': req.requestId,  // propagate the ID
  }
});

// In every log call:
logger.info({ event: 'evaluation_started', requestId: req.requestId, userId });

Now when a user reports "my evaluation at 2:34pm failed," you find the request ID from the response header or from the frontend error log, and you can query every log line across every service that carries that ID. The full request trace — in log form — is reconstructed in seconds.

Part 4: Distributed Tracing — The Full Request Journey

Logs with request IDs give you the events associated with a request. But they do not tell you the timeline — what happened in what order, for how long, and which part was slow.

A distributed trace is a structured record of a request's journey through a system. It models the request as a tree of spans — each span represents a unit of work with a start time, duration, service name, operation name, and arbitrary metadata.

Without tracing, you know the request took 843ms. With tracing, you know that 85% of the time was spent in the Gemini API call. You did not need to guess or add timing logs in five different places — the trace assembled this automatically.

Trace propagation — how spans know they belong together

Each trace has a trace ID — a random 128-bit identifier assigned when the first service handles the request. Each span within the trace has a span ID. When a service calls a downstream service, it passes the trace ID and its own span ID in HTTP headers:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
              ↑  ─────── trace ID ────────────────  ── span ID ─────

The downstream service reads these headers, creates its own child span with the received trace ID and parent span ID, does its work, and propagates the same trace ID to any services it calls. At the end, all spans with the same trace ID are assembled into the tree you see above.

This propagation is why x-request-id alone is not sufficient for full observability. A request ID identifies which logs belong together. A trace ID plus span IDs identifies the causal hierarchy — which service called which service, in what order, for how long.

OpenTelemetry — the standard

OpenTelemetry (OTel) is the open standard for distributed tracing (and now also metrics and logs). It provides SDKs in every language that:

• Automatically instrument common libraries (Express, Prisma, Redis, HTTP clients)
• Propagate trace context across service boundaries
• Export spans to a backend (Jaeger, Zipkin, Datadog, Grafana Tempo)

// Node.js OpenTelemetry setup (in a separate instrumentation file loaded first)
import { NodeSDK } from '@opentelemetry/sdk-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { PrismaInstrumentation } from '@prisma/instrumentation';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';

const sdk = new NodeSDK({
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT,
  }),
  instrumentations: [
    new HttpInstrumentation(),
    new ExpressInstrumentation(),
    new PrismaInstrumentation(),
  ],
});

sdk.start();

With this setup, every HTTP request, every Prisma query, and every outbound HTTP call is automatically instrumented. Spans are created, timed, and exported without adding a single line of tracing code to your business logic. The automatic instrumentation is what makes OpenTelemetry practical — you get observability without polluting your application code.

Adding custom spans for business logic

Automatic instrumentation covers infrastructure calls. For business logic that matters — the Gemini API call, the rubric evaluation, the credit check — add custom spans:

import { trace } from '@opentelemetry/api';

const tracer = trace.getTracer('samiksha-api');

async function evaluateAnswer(answer, rubric, userId) {
  return tracer.startActiveSpan('evaluate_answer', async (span) => {
    span.setAttributes({
      'user.id': userId,
      'answer.length': answer.length,
      'rubric.id': rubric.id,
    });

    try {
      const result = await callGemini(answer, rubric);
      span.setAttributes({ 'evaluation.score': result.score });
      return result;
    } catch (error) {
      span.recordException(error);
      span.setStatus({ code: SpanStatusCode.ERROR });
      throw error;
    } finally {
      span.end();
    }
  });
}

Now the trace for an evaluation request will include a span named evaluate_answer with the user ID, answer length, rubric ID, and resulting score. When an evaluation is slow, you can see in the trace whether the slowness is in the Gemini call, the database write, or the rubric fetching — and you can filter all evaluations for a specific user or rubric to find patterns.

Part 5: Connecting the Three Pillars

Metrics, logs, and traces are not three separate systems bolted together. They form a diagnostic workflow where each one leads you to the next.

The workflow:

1. Metrics alert. Your Grafana dashboard shows p99 latency spiked from 200ms to 3s at 14:32. Error rate climbed from 0.1% to 4%. This is the "something is wrong" signal.

2. Metrics narrow the scope. You slice the latency metric by endpoint and see that only /api/evaluate is slow. Other endpoints are unaffected. You slice by service and see the spike is in the api-server, not the worker. You now know where to look.

3. Traces find the specific failure. You open Jaeger and filter for traces on /api/evaluate between 14:32 and 14:35 where duration > 2s. You find 2,300 slow traces. You open one and see: the Gemini API span shows 2.8s. Usually it is 400ms. You check five more traces — all show the same pattern. The Gemini API is the bottleneck.

4. Logs provide the specific error. You take the trace ID from one slow trace and search logs for it. You find a log entry: gemini_api_error: rate limit exceeded, retry 3 of 3, final error: 429 Too Many Requests. The Gemini rate limit was hit. Your retry logic added 3 × 800ms = 2.4s of retry delay.

5. Root cause identified. You hit the Gemini API rate limit. The fix: add a circuit breaker, implement proper backoff, or upgrade the Gemini API tier. The entire diagnosis took 8 minutes. Without observability, this would have taken hours.

Correlation: connecting logs to traces

The key that makes step 4 fast is that your trace IDs appear in your logs. OpenTelemetry automatically injects the current trace ID and span ID into log records when you use a compatible logging library:

import { createLogger } from 'winston';
import { OpenTelemetryTransportV3 } from '@opentelemetry/winston-transport';

const logger = createLogger({
  transports: [new OpenTelemetryTransportV3()],
});

// Now every logger.info() call automatically includes trace_id and span_id
logger.info({ event: 'gemini_call_started', userId, model: 'gemini-pro' });
// Output: { event: "gemini_call_started", trace_id: "4bf92f35...", span_id: "00f067aa..." }

With trace IDs in logs, you navigate from a trace to its logs (search by trace ID) or from a log to its trace (click the trace ID link). The three pillars become one system.

Part 6: Alerting — Acting on Signals Automatically

Observability without alerting requires a human to watch dashboards. Alerting turns signals into action.

An alert fires when a metric crosses a threshold. The threshold design is where most alerting goes wrong in two opposite directions:

Too sensitive: Alert fires every time CPU briefly spikes above 60% or error count exceeds 5. On-call engineer gets paged 40 times a night. After two nights of false alarms, engineers start ignoring alerts. The real incident gets missed.

Too loose: Alert fires only when the system is completely broken. By the time it fires, users have been experiencing failures for 30 minutes.

The correct approach: alert on symptoms, not causes.

Wrong: CPU > 80%. CPU being high is a cause. Maybe it is fine, maybe not. Right: p99 latency > 1000ms for 5 minutes. Users are experiencing slow requests. This is a symptom. Always actionable.

Wrong: Postgres connections > 50. Maybe your pool is sized correctly at 50. Right: connection pool utilisation > 90% for 3 minutes. You are about to run out of connections. This is a symptom that requires action.

# Prometheus alerting rule (alerts.yml)
groups:
  - name: api_health
    rules:
      - alert: HighP99Latency
        expr: |
          histogram_quantile(0.99,
            rate(http_request_duration_seconds_bucket[5m])
          ) > 1.0
        for: 5m
        labels:
          severity: warning
        annotations:
          summary: "p99 latency above 1s for 5 minutes"
          description: "Endpoint {{ $labels.endpoint }} p99 latency is {{ $value }}s"

      - alert: HighErrorRate
        expr: |
          rate(http_requests_total{status_code=~"5.."}[5m]) /
          rate(http_requests_total[5m]) > 0.05
        for: 2m
        labels:
          severity: critical
        annotations:
          summary: "Error rate above 5%"

Alert messages must include the data needed to start diagnosis immediately: which service, which endpoint, what the current value is, what the threshold is. An alert that says "something is wrong" wastes the first 5 minutes of incident response reconstructing context.

Part 7: The Observability Stack for Your Architecture

For a Next.js + Node.js + Postgres + Redis + BullMQ stack on Hetzner:

Metrics: Prometheus (self-hosted on Hetzner) + Grafana. Prometheus scrapes your API servers, workers, Postgres (via postgres_exporter), and Redis (via redis_exporter). Grafana renders dashboards and fires alerts to PagerDuty or Slack.

Logs: Loki (Grafana's log aggregation system) + Promtail (log shipper). Promtail runs on each server, tails log files, and ships structured JSON logs to Loki. Grafana queries both Prometheus and Loki from the same interface, and correlates them via trace IDs.

Traces: Grafana Tempo (distributed trace backend) + OpenTelemetry SDK. Your Node.js services export traces via OTLP to Tempo. Grafana renders trace waterfall views.

This entire stack — Prometheus, Loki, Tempo, Grafana — is the PLT+G stack and runs on a single medium Hetzner VPS for a product at your current scale. Total cost: the server. No SaaS observability pricing that scales with data volume.

For zero operational overhead (no self-hosting): Grafana Cloud has a generous free tier that covers all three pillars. For production products, Datadog or New Relic provide equivalent capability with more polish and higher cost.

Vocabulary Map

Practice Problems

Problem 1 — Failure Analysis: Samiksha's on-call engineer gets paged at 2am: "Error rate spiked to 12%." They open Grafana. The error rate metric is elevated. That is all they know.

Design the set of metrics that would let this engineer narrow down the root cause within 2 minutes. Specifically: what dimensions (labels) should the error rate metric have? What other metrics should be on the same dashboard? Walk through the exact sequence of metric queries the engineer runs to identify whether the problem is: (a) one specific endpoint, (b) one specific downstream service, (c) database connection exhaustion, or (d) a worker queue backup.

Problem 2 — Design From Scratch: AttemptIQ processes test submissions via BullMQ workers. A job is: fetch the test, evaluate each answer with Gemini, compute the final score, write results to Postgres, send a result email. The job takes 3-8 seconds on average. Sometimes jobs fail silently — the score is never written, no email is sent, no error appears in logs.

Design the complete observability instrumentation for this job. What metrics do you emit at which points? What structured log events? What custom spans? How does an engineer discover a silently failing job within 5 minutes of it failing? Write the specific metric, log, and span names with their attributes.

Problem 3 — Cardinality: A junior engineer on your team adds the following metric to the API:

const requestDuration = new Histogram({
  name: 'api_request_duration_seconds',
  labelNames: ['endpoint', 'userId', 'userPlan', 'statusCode', 'region'],
});

The system has 80,000 users, 120 endpoints, 3 plans, 25 status codes, and 8 regions. Calculate the maximum cardinality. What happens to Prometheus under this load? Which labels should be kept? Which should be removed and why? How do you get per-user data if you cannot use userId as a label?

Problem 4 — Go Deeper: Distributed tracing requires every service in the call chain to propagate the traceparent header. If one service in the middle of the chain does not propagate the header, what happens to the trace?

Now consider sampling: if you sample 10% of traces (to reduce volume), and a bug affects 0.5% of requests, what is the probability that you capture at least one trace showing the bug in 10,000 requests? What sampling strategy would ensure you always capture traces for errors, even when sampling healthy requests at 1%?

Problem 5 — Connect to Previous Chapters: In Phase 2 Chapter 4 you learned about pg_stat_statements for identifying slow queries. In this chapter you learned about distributed tracing and metrics.

Design an observability system that connects all three: when a Grafana alert fires for high p99 API latency, describe the exact sequence of tools and queries an engineer uses to determine whether the cause is (a) a Postgres query regression identifiable via pg_stat_statements, (b) an external API slowdown visible in trace spans, or (c) a BullMQ queue backup visible in queue depth metrics. Name the specific dashboard panels, trace attributes, and SQL queries involved.

What's Next

You can now see inside a running distributed system — metrics tell you when something is wrong, logs tell you what happened, and traces tell you where. But there is one more layer of infrastructure that every request passes through before reaching your application: the load balancer. Chapter 6 opens the load balancer and shows you exactly how traffic is distributed across your application servers, what algorithms determine which server handles which request, how health checks work at the connection level, and what failure modes exist when a server goes down mid-request. The load balancer is the entry point to your system — understanding it is what lets you reason about availability, traffic shaping, and zero-downtime deployments.

End of Phase 4, Chapter 5.