loom-logging-observability

Logging and Observability

Overview

Understand system behavior through the three pillars — logs, metrics, traces — correlated by shared IDs. This skill covers structured logging, OpenTelemetry tracing, Prometheus metrics, aggregation backends, and alerting, with emphasis on the cost/cardinality traps and sampling decisions that separate a working setup from an expensive broken one.

Three Pillars — what each answers, and its cost model

Pillar	Answers	Cost driver	Use for
Metrics	"Is it broken? how much?" (aggregate)	Label cardinality (# series)	Dashboards, SLOs, alerting — always-on, cheap
Traces	"Where in the request path?" (causal)	Span volume → sampling	Latency breakdown, cross-service dependency
Logs	"What exactly happened?" (event detail)	Volume + indexing strategy	Forensics, audit, the specifics of one request

Reach for metrics first (cheap, aggregate), traces to localize, logs for the detail. Link all three by trace_id/correlation_id so you can pivot: alert fires on a metric → jump to an exemplar trace → read that trace's logs.

Structured Logging

Emit JSON, one object per event — never string-interpolated prose. Structured fields are queryable in any backend; f"user {id} did {action}" is not.

import json, logging, sys
from datetime import datetime, timezone
from contextvars import ContextVar

correlation_id: ContextVar[str] = ContextVar("correlation_id", default="")
trace_id: ContextVar[str] = ContextVar("trace_id", default="")

class JsonFormatter(logging.Formatter):
    def format(self, r: logging.LogRecord) -> str:
        data = {
            "ts": datetime.now(timezone.utc).isoformat(),
            "level": r.levelname, "logger": r.name, "msg": r.getMessage(),
            "correlation_id": correlation_id.get(), "trace_id": trace_id.get(),
        }
        if r.exc_info:
            data["exception"] = self.formatException(r.exc_info)
        if hasattr(r, "fields"):
            data.update(r.fields)          # structured extras
        return json.dumps(data)

h = logging.StreamHandler(sys.stdout); h.setFormatter(JsonFormatter())
logging.getLogger().addHandler(h); logging.getLogger().setLevel(logging.INFO)

logging.getLogger(__name__).info("order processed",
    extra={"fields": {"order_id": order.id, "total": order.total}})

TypeScript: use a child-logger pattern so request context is bound once and inherited — pino/winston do this natively; prefer them over hand-rolling.

// pino: bound context + fast JSON. child() inherits parent fields.
const log = pino();
const reqLog = log.child({ correlationId, traceId });
reqLog.info({ orderId, total }, "order processed");  // object first, message second

Log levels

Level	When	Example
TRACE	Fine-grained, off in prod	Loop iterations, var values
DEBUG	Diagnostics, off in prod	Function entry/exit, intermediate state
INFO	Normal business events	Request done, job completed, user action
WARN	Recoverable / degraded	Retry attempted, deprecated API, slow query
ERROR	Failure needing attention	Exception caught, operation failed
FATAL	Cannot continue	Startup config missing, data corruption

Logging discipline (the expensive mistakes)

Never log secrets/PII — passwords, tokens, full card numbers, emails, request bodies. Redact at the formatter (allowlist fields), not by remembering at each call site. PII in logs is a compliance breach (GDPR/PCI) and log stores are rarely access-controlled like a DB.
Structured over interpolated — attach IDs as fields, not baked into the message string, or you can't filter/aggregate by them.
Don't log in hot paths synchronously. A blocking log write per iteration in a tight loop or per-row is a latency cliff. Use async/non-blocking appenders (QueueHandler in Python, pino's async transport) and log the summary, not each item.
Sample high-volume logs. For chatty success paths, emit 1-in-N (keep 100% of WARN/ERROR). Reduces cost without losing the signal.
Consistent field names across services — always correlation_id, never sometimes request_id. Cross-service queries depend on it.
Emit to stdout as JSON; let the platform collect it. Don't manage log files/rotation inside the app in a containerized environment — the agent/sidecar (Promtail, Fluent Bit, Datadog agent) tails stdout.

Distributed Tracing

Use OpenTelemetry — the vendor-neutral standard (CNCF). Don't hand-roll spans/tracers: the OTel SDK gives context propagation, batching, and OTLP export for free, and swaps backends (Jaeger, Tempo, Datadog, any OTLP endpoint) without code change. Maturity as of 2026: tracing is stable/GA; metrics stable; logs stable spec but SDK/collector logs support is newer than traces — verify your language SDK's status before relying on OTel logs vs a mature logging lib.

Architecture: SDK in-process (creates spans, propagates context) → OTel Collector (receive/process/export; the place to do batching, tail sampling, redaction, fan-out to backends). Run the Collector as a sidecar or gateway; keep exporters/sampling config there so apps stay backend-agnostic.

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor

provider = TracerProvider(resource=Resource.create({"service.name": "order-service"}))
provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter(endpoint="http://otel-collector:4317")))
trace.set_tracer_provider(provider)
tracer = trace.get_tracer(__name__)

FastAPIInstrumentor.instrument_app(app)   # auto-spans for incoming requests + context extraction

@app.get("/orders/{order_id}")
async def get_order(order_id: str):
    with tracer.start_as_current_span("fetch_order") as span:
        span.set_attribute("order.id", order_id)      # low-cardinality-ok on spans (unlike metrics labels)
        return await repo.get(order_id)

Context propagation — W3C traceparent

A trace spans services only if context crosses the wire. The standard is the W3C traceparent header: 00-<32-hex trace-id>-<16-hex span-id>-<2-hex flags> (flags bit 0 = sampled). OTel auto-instrumentation injects it on outgoing HTTP/gRPC and extracts it on incoming — so instrument BOTH the client and server side, or the trace breaks at the boundary and you get orphan traces. For non-HTTP hops (queues, Kafka), propagate traceparent as a message attribute manually. Legacy backends may use B3 (Zipkin) headers; configure the propagator to match, or run both.

Sampling — head vs tail

You cannot afford 100% of spans at volume. Two strategies:

Head sampling: decide at trace start (in the SDK), e.g. ParentBased(TraceIdRatioBased(0.1)) keeps 10%. Cheap, no buffering. Fatal limitation: the decision is made before the outcome is known, so you cannot "keep all errors" — a 1% error might be dropped.
Tail sampling: decide after the whole trace finishes, in the Collector's tailsamplingprocessor — keep 100% of error/slow traces + a sample of normal ones. Requires buffering every span of a trace until complete, so all spans of one trace must reach the same Collector instance: put a load-balancing exporter (routing by trace-id) in front of the tail-sampling collectors, or they'll each see partial traces and sample wrongly.

Rule of thumb: head-sample for cost control at the edge; add tail sampling in the Collector when you need "always keep errors/slow." Propagate the sampled flag so a downstream service doesn't independently drop spans of a kept trace.

Correlation & exemplars

Put trace_id into every log line's structured fields (bind it in a middleware/context var) so a trace pivots to its logs. Link metrics → traces with exemplars: a sampled trace-id attached to a histogram bucket observation, letting Grafana jump from a latency spike on a graph to the exact slow trace. Prometheus needs --enable-feature=exemplar-storage and OpenMetrics exposition; the client library attaches the exemplar at observe() time.

Metrics

Use a real client (prometheus_client, OTel metrics) — don't hand-roll registries. They handle concurrency, exposition format, and label management correctly.

from prometheus_client import Counter, Gauge, Histogram, start_http_server

REQS = Counter("http_requests_total", "Requests", ["method", "route", "status"])
INFLIGHT = Gauge("http_inflight_requests", "In-flight requests")
LAT = Histogram("http_request_duration_seconds", "Latency", ["method", "route"],
                buckets=(.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5))

start_http_server(9090)                        # exposes /metrics for scrape

@INFLIGHT.track_inprogress()
def handle(req):
    with LAT.labels(req.method, req.route).time():   # times the block
        resp = process(req)
    REQS.labels(req.method, req.route, resp.status).inc()

Types: Counter (monotonic totals — _total), Gauge (up/down current value — memory, queue depth), Histogram (bucketed distribution — latency; enables histogram_quantile percentiles server-side). Prefer Histogram over Summary for latency (Summary quantiles can't be aggregated across instances).
Naming (Prometheus): base unit suffix — _seconds, _bytes, _total. http_request_duration_seconds, not _ms.
⚠ Label cardinality is the #1 killer. Each unique label-value combination is a separate time series stored in memory. Never use unbounded values as labels — user_id, request_id, email, full URL with IDs, raw error message. One high-card label can create millions of series and OOM Prometheus. Keep labels to bounded sets (method, route template, status class). Put the high-card identifier in a trace or log, not a metric label.

Dashboards & SLOs — RED and USE

RED (request-driven services): Rate (req/s), Errors (failed req/s or ratio), Duration (latency distribution, alert on p95/p99). One RED panel set per service tells you if users are hurting.
USE (resources: CPU, disk, pool, queue): Utilization (% busy), Saturation (queued/waiting work — the leading indicator), Errors. Saturation usually predicts trouble before utilization saturates.
Golden Signals (Google SRE) = latency, traffic, errors, saturation — RED + saturation. Alert on symptom signals (RED), use USE to diagnose the cause.

Log Aggregation — and the indexing cost trap

The single biggest cost/architecture decision: index everything vs index labels only.

ELK / Elasticsearch / OpenSearch: indexes every field → fast arbitrary full-text and field queries, but storage and compute scale with total log volume (expensive at scale; index bloat, hot-node pressure).
Grafana Loki: indexes only labels (stream metadata), stores log content compressed and unindexed → cheap ingest/storage; content queries are brute-force scans over the time-and-label-narrowed set ({app="api"} |= "timeout"). Great when you filter by labels then grep; slow if you need ad-hoc full-text over everything.
Loki cardinality trap (same killer as metrics): every unique label-value set is a separate stream. Putting trace_id/user_id/pod_ip as a Loki label explodes stream count and destroys performance. Keep labels low-cardinality (app, env, level, namespace); filter high-card values as content in the query, not as labels.
Datadog / hosted: priced per ingested/indexed GB — use ingestion filters/exclusion rules (e.g. drop health-check logs) and index only what you'll query.

# Promtail → Loki: LOW-cardinality labels only; do NOT add trace_id/user_id as labels
scrape_configs:
  - job_name: app
    static_configs: [{ targets: [localhost], labels: { job: app, __path__: /var/log/app/*.log } }]
    pipeline_stages:
      - json: { expressions: { level: level, service: service } }
      - labels: { level:, service: }        # bounded sets only

# Datadog agent: exclude noise at ingest to control cost
logs_config:
  processing_rules:
    - type: exclude_at_match
      name: drop_healthchecks
      pattern: "GET /health"

Alerting

groups:
  - name: service
    rules:
      - alert: HighErrorRate                # symptom, not cause
        expr: sum(rate(http_requests_total{status=~"5.."}[5m])) / sum(rate(http_requests_total[5m])) > 0.05
        for: 5m
        labels: { severity: critical }
        annotations:
          summary: "Error rate {{ $value | humanizePercentage }}"
          runbook_url: "https://wiki/runbooks/high-error-rate"     # every alert links a runbook
      - alert: HighLatencyP95
        expr: histogram_quantile(0.95, sum(rate(http_request_duration_seconds_bucket[5m])) by (le)) > 1
        for: 10m
        labels: { severity: warning }
      - alert: ServiceDown
        expr: up == 0
        for: 1m
        labels: { severity: critical }

Severity	Response	Examples
Critical	Page now	Service down, error-rate SLO breach, data loss
Warning	Business hrs	Rising latency, approaching limits, retry spikes
Info	Log only	Deploy started, config changed

Principles:

Alert on symptoms (user impact), not causes. Page on error rate/latency (RED); CPU high with healthy latency is not an incident. Symptoms say what's broken; use USE/traces to find why.
Every alert is actionable and has a runbook. Non-actionable alerts cause fatigue → ignored pages. Delete or downgrade alerts nobody acts on.
Thresholds from SLOs, not vibes. Prefer SLO burn-rate alerts (fast burn = page, slow burn = ticket) over static thresholds — they alert proportional to error-budget consumption and cut false pages during low traffic.
for: avoids flapping — require the condition to hold before firing.

Request middleware (correlation + span + metrics in one place)

class ObservabilityMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        corr = request.headers.get("X-Correlation-ID", str(uuid.uuid4()))
        correlation_id.set(corr)
        span = trace.get_current_span()               # created by FastAPIInstrumentor
        span.set_attribute("correlation_id", corr)
        trace_id.set(format(span.get_span_context().trace_id, "032x"))  # into logs
        start = time.perf_counter()
        try:
            resp = await call_next(request)
            LAT.labels(request.method, request.url.path).observe(time.perf_counter() - start)
            REQS.labels(request.method, request.url.path, str(resp.status_code)).inc()
            resp.headers["X-Correlation-ID"] = corr
            return resp
        except Exception as e:
            span.record_exception(e); span.set_attribute("error", True)
            raise

Note: use url.path template (route pattern), not the raw path with IDs, as the metric label — else cardinality explodes.

Verification Checklist

Logs are JSON to stdout with consistent field names; correlation_id + trace_id on every line
No secrets/PII in logs; redaction is enforced at the formatter, not per-call-site
Hot-path logging is async/sampled; success paths sampled, 100% of WARN/ERROR kept
Tracing uses the OTel SDK; both client and server sides instrumented so traceparent propagates (no orphan traces)
Sampling chosen deliberately: head for cost, tail (in Collector, with trace-id load balancing) if "always keep errors"
Metric labels are bounded — no user_id/request_id/raw-path/error-string as labels
Latency uses Histogram with sensible buckets; percentiles computed via histogram_quantile
Dashboards follow RED (services) / USE (resources); metric names carry base-unit suffixes
Loki labels are low-cardinality (no trace_id/user_id as labels); backend indexing cost understood (Loki labels-only vs ELK index-all)
Alerts fire on symptoms, have for:, link a runbook, and derive thresholds from SLOs (prefer burn-rate)
Logs, metrics, and traces are cross-linkable by shared IDs; exemplars wired if metric→trace pivot is needed