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](../src/core/logging.py).

---

## Estrutura do JSON emitido

```json
{
  "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](../src/api/middleware/logging.py), [dependencies/logging_context.py](../src/api/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

```python
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](../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:

```python
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`**:

```python
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:

```python
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](../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:

```python
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](../src/core/logging.py).
- Decorators que aplicam `log_operation` automaticamente:
  [src/utils/observer.py](../src/utils/observer.py) (`@trace_node`,
  `@trace_api`, `@trace_tool`).
- Propagação do contexto da requisição:
  [src/api/dependencies/logging_context.py](../src/api/dependencies/logging_context.py).