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. ```python 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. ```typescript // 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** — adopt OpenTelemetry semantic conventions for resource and signal attributes; keep any application correlation field stable across services. 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. ```python 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"})) # OTLP/gRPC accepts an endpoint URL. `insecure=True` is appropriate only for a # trusted in-cluster plaintext collector; configure TLS explicitly for remote use. provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter(endpoint="http://otel-collector:4317", insecure=True))) 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. ```python 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): **R**ate (req/s), **E**rrors (failed req/s or ratio), **D**uration (latency distribution, alert on p95/p99). One RED panel set per service tells you if users are hurting. - **USE** (resources: CPU, disk, pool, queue): **U**tilization (% busy), **S**aturation (queued/waiting work — the leading indicator), **E**rrors. 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. ```yaml # 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 ``` ```yaml # Datadog agent: exclude noise at ingest to control cost logs_config: processing_rules: - type: exclude_at_match name: drop_healthchecks pattern: "GET /health" ``` ## Alerting ```yaml 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) ```python class ObservabilityMiddleware(BaseHTTPMiddleware): async def dispatch(self, request, call_next):