mirror of https://github.com/hoshikawa2/compass_backoffice.git synced 2026-07-09 22:04:20 +00:00

Files

Cristiano Hoshikawa 89c23fb0ed first commit

2026-06-13 08:23:21 -03:00

10 KiB

Raw Blame History

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

Operação clara com início e fim (rota, node, chamada externa, job) → use log_operation.
Evento pontual dentro de uma operação (cache hit/miss, retry, decisão tomada) → op.event(...) ou logger.info(...) direto.
Diagnóstico técnico fino → logger.debug(...).
Algo inesperado mas não fatal → logger.warning(...).
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.

10 KiB Raw Blame History