Capítulo 61, Backend
Observabilidade
Em produção você não pode abrir o programa e olhar dentro. Observabilidade é a capacidade de entender o que o sistema está fazendo a partir do que ele emite: logs, métricas e traces.
Código deste capítulo: backend/cap61_observabilidade.py
Os três sinais
| Sinal | Responde | Exemplo |
|---|---|---|
| Logs | O que aconteceu, em detalhe | "pedido 7 recusado: cartão sem saldo" |
| Métricas | Quanto, com que frequência, quão rápido | Requisições por segundo, p99 de latência |
| Traces | Por onde uma requisição passou e quanto cada etapa demorou | checkout chamou cobrar e gravar |
As métricas dizem que há um problema (a latência subiu). Os traces dizem onde (a chamada ao gateway). Os logs dizem por quê (a mensagem de erro dele). Os três se complementam e se ligam por um identificador comum.
Logs estruturados com identificador de correlação
Um log em texto livre é para humanos lerem. Um log em JSON é para máquinas pesquisarem: nivel = "ERROR" e id_requisicao = "abc". Um middleware atribui um identificador a cada requisição, o guarda em uma ContextVar (que funciona em threads e em asyncio) e o devolve no cabeçalho, para o cliente poder citá-lo em um chamado:
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"])
{"nivel": "INFO", "mensagem": "buscando pedido 7", "id_requisicao": "abc123"}
abc123
A primeira linha impressa é o log da rota, com o identificador que veio no cabeçalho, e a segunda é o cabeçalho devolvido. É o mesmo mecanismo da API de pedidos, que registra uma linha por requisição:
{"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}
O que nunca vai para um log
Senhas, tokens, números de cartão e dados pessoais (CPF, e-mail completo). Um log é copiado para vários sistemas e guardado por meses. O
SecretStrdo capítulo 58 existe para isso. E registre a rota com o padrão (/pedidos/{id}), e não com a URL já preenchida, para não vazar identificadores.
Métricas com Prometheus
Uma métrica é um número que o sistema expõe e uma ferramenta coleta periodicamente. Há dois tipos que cobrem quase tudo: o Counter, que só cresce (pedidos criados), e o Histogram, que distribui valores em faixas (duração do checkout). O Prometheus lê o texto de uma rota /metricas:
uv add prometheus-client
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)))
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
Os bucket são cumulativos: a faixa le="0.5" conta tudo que levou até 0,5 segundo. É daí que se calcula o percentil (p95, p99) de latência, que diz muito mais do que a média.
Cuidado com a cardinalidade dos rótulos
Cada combinação de valores de rótulo cria uma série nova na memória do Prometheus. Um rótulo com valores ilimitados (id do usuário, URL completa, e-mail) cria milhões de séries e derruba o sistema de métricas. Rotule só com valores de conjunto pequeno e fixo: método, rota padrão, status, resultado.
Traces com OpenTelemetry
Um trace é a árvore de uma requisição. Cada etapa é um span, com início, duração, atributos e um pai. O OpenTelemetry é o padrão aberto para isso. Para ver a estrutura sem precisar de um servidor de traces, o exemplo guarda os spans em memória:
uv add opentelemetry-sdk
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)}")
cobrar_cartao pai=checkout atributos={}
gravar_pedido pai=checkout atributos={'itens': 3}
checkout pai=None atributos={'cliente': 'Ana'}
Repare na ordem: um span só é "finalizado" quando termina, então os filhos aparecem antes da raiz. Em produção, em vez do exportador de memória, você configura um exportador OTLP que envia os spans a um coletor (Jaeger, Tempo, Datadog), e as bibliotecas de instrumentação automática (para FastAPI, SQLAlchemy e httpx) criam os spans de entrada e de saída sem você escrever nada.
O que medir: RED e saúde
Para um serviço que atende requisições, eu começo pelo método RED:
| Letra | Métrica | Pergunta |
|---|---|---|
| Rate | Requisições por segundo | Quanto tráfego existe? |
| Errors | Proporção de respostas 5xx | Está falhando? |
| Duration | Percentis de latência (p95, p99) | Está lento? |
E dois endpoints de saúde com papéis diferentes: liveness ("o processo está vivo?", se falhar o orquestrador reinicia) e readiness ("posso receber tráfego?", se falhar ele para de enviar requisições). Um banco fora do ar deve derrubar a readiness, e não a liveness: reiniciar a API não conserta o banco.
Alerte sobre sintomas
Um alerta bom acorda alguém por algo que o usuário sente: taxa de erro alta, latência acima do objetivo. Alertar para "CPU em 80%" gera ruído. Eu defino um objetivo (por exemplo, 99% das requisições abaixo de 500 ms) e alerto quando o orçamento de erro está sendo gasto rápido demais.
Exercício 1
Contar requisições por rota
Crie um middleware que incremente um Counter com o rótulo rota a cada requisição e mostre, com get_sample_value, que duas chamadas a /ping resultam em 2.0.