compass_backoffice/docs_original_develop/logging.md

Logs de Aplicação

Este guia descreve como o logging está organizado, o que cada peça faz, e como adicionar logs em novas features de forma consistente com a política de monitoramento (doc interno 1330576 — Monitoramento de Aplicação - OCI Logging).

---

Visão geral

• Destino dos logs: stdout (logs < ERROR) e stderr (logs >= ERROR). A aplicação não envia logs diretamente para fora.
• Formato em produção: JSON (LOG_FORMAT=json).
• Enriquecimento automático: todo log recebe service, correlation, source_channel, conversation_start_time_ts, requesting_agent e user_id automaticamente via contextvars

Arquivo central: src/core/logging.py.

---

Estrutura do JSON emitido

{
  "timestamp": "2026-05-12T03:16:12.726Z",
  "level": "INFO",
  "logger": "src.agent.nodes.validation_node",
  "message": "process started",
  "source_channel": "ura",
  "conversation_start_time_ts": "2026-03-20T14:32:10Z",
  "requesting_agent": "agent_bo",
  "service": {
    "name": "Agent Microservice",
    "version": "0.4.0",
    "component": "validation_node",
    "agent_type": "backoffice"
  },
  "correlation": {
    "trace_id": "...",
    "request_id": "...",
    "span_id": "...",
    "session_id": "..."
  },
  "user_id": "...",
  "operation": {
    "name": "process",
    "status": "started",
    "execution_time": 0.001,
    "...": "campos custom adicionados via add_field"
  }
}

• service.component é derivado automaticamente do nome do logger (record.name.rsplit(".", 1)[-1]). Para sobrescrever, passe extra={"component": "outro_nome"} ou use o helper (log_operation).
• O bloco operation só aparece quando você está dentro de um log_operation(...) ou passa extra={"operation": {...}} manualmente.
• Em falhas, é adicionado o campo exception com o stacktrace.

---

Quem popula os contextvars

Contextvar	Quem seta	Onde
request_id	LoggingMiddleware (HTTP) ou set_ticket_log_context (consumer OCI)	middleware/logging.py, dependencies/logging_context.py
session_id	set_ticket_log_context	idem
user_id	set_ticket_log_context (Origin.submittedBy.userId)	idem
trace_id	set_ticket_log_context (hoje = transaction_id; Fase 2 trocará para trace OTEL)	idem
source_channel	set_ticket_log_context (Origin.sourceSystem)	idem
conversation_start_time_ts	set_ticket_log_context (Complaint.openedAt)	idem
requesting_agent	set_ticket_log_context (Origin.submittedBy.name)	idem
span_id	(reservado — não populado hoje)	—

Limpeza: clear_context() é chamado no finally do middleware HTTP e do consumer OCI para evitar vazamento entre requisições.

---

API pública

from src.core.logging import (
    get_logger,
    log_operation,           # context manager — preferido
    set_request_id,
    set_session_id,
    set_user_id,
    set_trace_id,
    set_span_id,
    set_source_channel,
    set_conversation_start_ts,
    set_requesting_agent,
    clear_context,
    MetricsLogger,           # legado — prefira log_operation
)

get_logger(name)

Wrapper sobre logging.getLogger(name). Garante que o root logger está configurado. Convenção: logger = get_logger(__name__) no topo do módulo.

log_operation(name, *, component=None, logger=None, **fields)

Context manager (funciona com with e async with) que emite:

• <name> started no entry.
• <name> completed no exit feliz, com execution_time em segundos.
• <name> failed: <exc> no exit por exceção, com exc_info e error_type — a exceção é re-raised normalmente.

component quando omitido é derivado do nome do logger.

Métodos do objeto retornado:

• op.add_field(key, value) — anexa um campo ao bloco operation que será emitido nos logs de success/failed (e em op.event(...)).
• op.event(message, level=INFO, **fields) — emite um log intermediário dentro da operação (status in_progress), sem fechá-la.

---

Guia de uso — quando e como logar

Regra mental

1. Operação clara com início e fim (rota, node, chamada externa, job) → use log_operation.
2. Evento pontual dentro de uma operação (cache hit/miss, retry, decisão tomada) → op.event(...) ou logger.info(...) direto.
3. Diagnóstico técnico fino → logger.debug(...).
4. Algo inesperado mas não fatal → logger.warning(...).
5. Falha em bloco except → logger.error(msg, exc_info=True) ou deixe log_operation propagar (já loga com exc_info).

NUNCA

• Não passe session_id/request_id/user_id em extra= — eles já são injetados pelo ContextFilter. Adicionar manualmente só duplica.
• Não use logger.error(str(e)) sem exc_info=True em bloco except — perde o stacktrace.
• Não use logger.error(..., exc_info=True) fora de bloco except — sem exceção ativa o campo exception vira NoneType: None.
• Não logue payloads com PII (CPF, telefone, token, senha). Mascarar / anonimizar antes (política §2 do doc).
• Não escreva em arquivo, não chame APIs externas para enviar logs — apenas stdout/stderr. Transporte é da infra.

NÃO crie wrappers próprios

Se aparecer a tentação de criar um decorator/helper local para "padronizar log de início e fim", pare. Use log_operation. Múltiplos padrões na base é exatamente o que essa refatoração eliminou.

---

Receitas

1. Rota HTTP / handler

O LoggingMiddleware já envolve toda requisição em log_operation("http_request"). Dentro da rota, não precisa logar "recebi requisição" / "finalizei requisição". Logue apenas eventos de negócio relevantes.

2. Node do agente

Não precisa fazer nada. O decorator @trace_node em src/utils/observer.py já envolve cada node com log_operation(func_name, component=<node_name>) e injeta message_count e iteration_count automaticamente.

Se quiser enriquecer com campos próprios do node, use logger.info dentro do node — o bloco service e a contextualização vêm de graça:

logger = get_logger(__name__)

@trace_node
async def process(state: AgentState) -> AgentState:
    # start/end são logados automaticamente pelo decorator
    logger.info(
        "Customer enriched from IMDB",
        extra={"payload": {"msisdn_masked": mask(msisdn), "cached": False}},
    )
    return state

3. Cliente HTTP externo

Métodos decorados com @trace_api ou @trace_tool já estão envolvidos em log_operation. Para logar retries dentro do loop, emita um log estruturado com o bloco operation em status in_progress:

for attempt in range(max_retries + 1):
    try:
        return await call_api(...)
    except TransientError as exc:
        if attempt == max_retries:
            raise
        wait = backoff(attempt)
        logger.warning(
            "Cliente: tentativa falhou, repetindo",
            extra={
                "operation": {
                    "name": "get_invoice_buffer",
                    "status": "in_progress",
                    "attempt": attempt + 1,
                    "max_retries": max_retries,
                    "backoff_seconds": round(wait, 3),
                    "last_error": str(exc),
                },
                "component": "pdf_invoice_recover",
            },
        )
        await asyncio.sleep(wait)

Para uma operação de API que não use @trace_api/@trace_tool (caso raro), envolva manualmente:

with log_operation(
    "get_invoice_buffer",
    component="pdf_invoice_recover",
    logger=logger,
    end_point_name="get_pdf",
    operacao_realizada="consulta",
    id_consulta=invoice_id,
) as op:
    op.add_field("attempt", attempt)
    response = http_call(...)
    op.add_field("status_code", response.status_code)

4. Job de background / consumer

Igual à rota: envolva o trabalho da unidade (uma mensagem consumida, um job rodado) em log_operation. Veja src/api/main.py process_incoming_ticket como referência.

5. Cache / acesso a memória

Toda operação de I/O que possa falhar merece log_operation. Padrão usado no projeto:

try:
    async with log_operation("save_state_to_memory", component="memory", logger=logger):
        await save_state_to_memory(state)
except Exception:
    # log_operation já emitiu failed com exc_info — silencie aqui
    # se o caminho feliz não depende do cache.
    pass

---

Níveis de log — política

Nível	Quando usar
DEBUG	Diagnóstico fino. Em produção fica desligado (LOG_LEVEL=INFO).
INFO	Eventos de negócio e fluxo normal — início/fim de operação, decisão tomada, recurso criado.
WARNING	Algo inesperado mas recuperável — fallback acionado, retry transitório, dado opcional ausente.
ERROR	Falha de operação. Sempre dentro de except com exc_info=True.
CRITICAL	Falha total / risco alto / corrupção de estado.

Configuração por ambiente:

• Produção: LOG_LEVEL=INFO, LOG_FORMAT=json.
• Homologação/Dev: LOG_LEVEL=DEBUG, LOG_FORMAT=text (mais legível localmente; o split stdout/stderr funciona em ambos os formatos).
• Loggers ruidosos (httpx, urllib3, pymongo, etc.) são silenciados para WARNING por padrão — ajuste via LOG_NOISY_LEVEL.

---

Checklist para PR adicionando novos logs

• Usou log_operation para operações com início/fim claros?
• Em bloco except, logger.error(..., exc_info=True)?
• Não passou session_id/request_id/user_id redundantes em extra?
• Não logou PII (CPF, telefone, token, payload bruto do cliente)?
• Quando adicionou campos custom, encaixou no bloco operation ou em payload (não criou um nível superior novo)?
• Se for um cliente HTTP com retry, registrou attempt e max_retries nos logs de retentativa?
• Verificou localmente com LOG_FORMAT=json que o JSON contém os blocos esperados?

---

Referências

• Política interna: doc 1330576 — Monitoramento de Aplicação - OCI Logging.
• Implementação base: src/core/logging.py.
• Decorators que aplicam log_operation automaticamente: src/utils/observer.py (@trace_node, @trace_api, @trace_tool).
• Propagação do contexto da requisição: src/api/dependencies/logging_context.py.