Chapter 61, Backend

Observability

In production, you cannot open the program and look inside. Observability is the ability to understand what the system is doing based on what it emits: logs, metrics, and traces.

Code for this chapter: backend/cap61_observabilidade.py

The three signals

Signal	Responds	Example
Logs	What happened, in detail	"request 7 denied: card with no balance"
Metrics	How much, how often, how fast	Requests per second, p99 latency
Traces	Where a request went and how long each step took	`checkout` called `cobrar` and `gravar`

Metrics say that there is a problem (latency increased). Traces say where (the call to the gateway). Logs say why (its error message). The three complement each other and are linked by a common identifier.

Structured logs with correlation ID

A free-text log is for humans to read. A JSON log is for machines to search: nivel = "ERROR" e id_requisicao = "abc". A middleware assigns an identifier to each request, stores it in a ContextVar (which works in threads and in asyncio) and returns it in the header, so the client can reference it in a call:

backend/cap61_observabilidade.pylinhas 10 a 64

import contextvars
import json
import logging
import sys
from uuid import uuid4

from fastapi import FastAPI, Request
from fastapi.testclient import TestClient

id_requisicao = contextvars.ContextVar("id_requisicao", default="-")


class FormatoJson(logging.Formatter):
    def format(self, record):
        return json.dumps(
            {
                "nivel": record.levelname,
                "mensagem": record.getMessage(),
                "id_requisicao": id_requisicao.get(),
            },
            ensure_ascii=False,
        )


manipulador = logging.StreamHandler(sys.stdout)
manipulador.setFormatter(FormatoJson())
log = logging.getLogger("loja")
log.handlers = [manipulador]
log.setLevel(logging.INFO)
log.propagate = False

app = FastAPI()


@app.middleware("http")
async def correlacionar(request: Request, call_next):
    identificador = request.headers.get("X-Request-ID") or uuid4().hex[:8]
    token = id_requisicao.set(identificador)
    try:
        resposta = await call_next(request)
    finally:
        id_requisicao.reset(token)
    resposta.headers["X-Request-ID"] = identificador
    return resposta


@app.get("/pedido/{numero}")
def pedido(numero: int):
    log.info("buscando pedido %d", numero)
    return {"numero": numero}


cliente = TestClient(app)
resposta = cliente.get("/pedido/7", headers={"X-Request-ID": "abc123"})
print(resposta.headers["x-request-id"])

Output

{"nivel": "INFO", "mensagem": "buscando pedido 7", "id_requisicao": "abc123"}
abc123

The first printed line is the route log, with the identifier that came in the header, and the second is the returned header. It’s the same mechanism as the orders API, which logs one line per request:

Logs da API de pedidos (execução real, com PostgreSQL)

{"nivel": "INFO", "mensagem": "requisição concluída", "id_requisicao": "req-demo", "metodo": "POST", "rota": "/pedidos", "status": 201, "duracao_ms": 24.08}
{"nivel": "INFO", "mensagem": "requisição concluída", "id_requisicao": "1e6049ebb0f048509d7bce3a280f1972", "metodo": "POST", "rota": "/pedidos", "status": 200, "duracao_ms": 4.29}

What never goes into a log
Passwords, tokens, card numbers, and personal data (CPF, full email). A log is copied to several systems and stored for months. The SecretStr of chapter 58 exists for this. And register the route with the standard (/pedidos/{id}), and not with the already filled URL, to avoid leaking identifiers.

Metrics with Prometheus

A metric is a number that the system exposes and a tool collects periodically. There are two types that cover almost everything: the Counter, which only grows (created requests), and the Histogram, which distributes values into ranges (checkout duration). Prometheus reads the text of a route /metricas:

Terminal

uv add prometheus-client

backend/cap61_observabilidade.pylinhas 69 a 83

from prometheus_client import CollectorRegistry, Counter, Histogram, generate_latest

registro = CollectorRegistry()
PEDIDOS = Counter("pedidos_total", "Pedidos criados", ["status"], registry=registro)
LATENCIA = Histogram("checkout_segundos", "Duração do checkout", buckets=(0.1, 0.5, 1.0), registry=registro)

PEDIDOS.labels("aprovado").inc()
PEDIDOS.labels("aprovado").inc()
PEDIDOS.labels("recusado").inc()
LATENCIA.observe(0.3)
LATENCIA.observe(0.05)

texto = generate_latest(registro).decode()
interessantes = ("pedidos_total{", "checkout_segundos_bucket", "checkout_segundos_count")
print("\n".join(linha for linha in texto.splitlines() if linha.startswith(interessantes)))

Output

pedidos_total{status="aprovado"} 2.0
pedidos_total{status="recusado"} 1.0
checkout_segundos_bucket{le="0.1"} 1.0
checkout_segundos_bucket{le="0.5"} 2.0
checkout_segundos_bucket{le="1.0"} 2.0
checkout_segundos_bucket{le="+Inf"} 2.0
checkout_segundos_count 2.0

The bucket are cumulative: the range le="0.5" counts everything that took up to 0.5 seconds. This is where the percentile (p95, p99) of latency is calculated, which says much more than the average.

Be careful with label cardinality
Each combination of label values creates a new series in Prometheus's memory. A label with unlimited values (user ID, full URL, email) creates millions of series and crashes the metrics system. Label only with a small and fixedset of values: method, standard route, status, result.

Traces with OpenTelemetry

An trace is the tree of a request. Each step is a span, with start, duration, attributes, and a parent. OpenTelemetry is the open standard for this. To see the structure without needing a trace server, the example stores the spans in memory:

Terminal

uv add opentelemetry-sdk

backend/cap61_observabilidade.pylinhas 88 a 108

from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter

exportador = InMemorySpanExporter()
provedor = TracerProvider()
provedor.add_span_processor(SimpleSpanProcessor(exportador))
rastreador = provedor.get_tracer("loja")

with rastreador.start_as_current_span("checkout") as raiz:
    raiz.set_attribute("cliente", "Ana")
    with rastreador.start_as_current_span("cobrar_cartao"):
        pass
    with rastreador.start_as_current_span("gravar_pedido") as etapa:
        etapa.set_attribute("itens", 3)

spans = exportador.get_finished_spans()
nomes = {s.context.span_id: s.name for s in spans}
for s in spans:
    pai = nomes.get(s.parent.span_id) if s.parent else None
    print(f"{s.name:<14} pai={pai} atributos={dict(s.attributes)}")

Output

cobrar_cartao  pai=checkout atributos={}
gravar_pedido  pai=checkout atributos={'itens': 3}
checkout       pai=None atributos={'cliente': 'Ana'}

Notice the order: a span is only "finalized" when it ends, so the children appear before the root. In production, instead of the memory exporter, you configure an OTLP exporter that sends the spans to a collector (Jaeger, Tempo, Datadog), and the automatic instrumentation libraries (for FastAPI, SQLAlchemy, and httpx) create the incoming and outgoing spans without you writing anything.

What to measure: RED and health

For a service that handles requests, I start with the method RED:

Letter	Metric	Question
Rate	Requests per second	How much traffic is there?
Errors	Proportion of responses `5xx`	Is it failing?
Duration	Latency percentiles (p95, p99)	Is it slow?

And two health endpoints with different roles: liveness ("is the process alive?", if the orchestrator fails, restarts) and readiness ("can I receive traffic?", if it fails, it stops sending requests). A database that is down should take down the readiness, and not the liveness: restarting the API does not fix the database.

Alert about symptoms
A good alert wakes someone up for something that the user feels: high error rate, latency above the target. Alerting for "CPU at 80%" generates noise. I set a target (for example, 99% of requests below 500 ms) and alert when the error budget is being spent too quickly.

Exercise 1

Count requests by route

Create a middleware that increments a Counter with the label rota for each request and shows, with get_sample_value, that two calls to /ping result in 2.0.

The three signals

Structured logs with correlation ID

Metrics with Prometheus

Traces with OpenTelemetry

What to measure: RED and health

View solution