Logs em produção: o custo invisível do ruído

Mais um capítulo da série GenServer the “rabbit hole”. Dessa vez sem GenServer — só log mesmo. Mas o mesmo princípio: a abstração parece simples, e quase ninguém percebe que está usando errado até a conta chegar.

Imagina o cenário: 2h da manhã, um pod reiniciou e o alerta acordou alguém. A pessoa abre o Loki, filtra pela label do app, e a primeira tela do navegador é isso aqui:

12:45:33Z info  [InboundWebhook] - Income message: %{"path" => "proxy/977671907166781440/example.cdn.com/v3/openlive/CA2585112_5_2", ...}
12:45:33Z info  Sent 200 in 44ms
12:45:33Z warn  [ExternalProvider EventWorker] - Event already processed, skipping: "869247060431936_2026-05-21..."
12:45:33Z warn  [SetAuthToken] Resource ba8bf8f3-5ceb-4d7d-a318-f0a88e228f41 send token 010000000000003D and AuthToken is not found
12:45:33Z info  Sent 200 in 12ms
12:45:33Z warn  [ExternalProvider EventWorker] - Event already processed, skipping: "865478070223930_..."
12:45:33Z info  Sent 200 in 39ms
12:45:33Z error Erro ao criar recurso: "network exception"
12:45:33Z info  Sent 200 in 22ms
12:45:33Z warn  [SetAuthToken] Resource 38d916e1-1ee7-4f91-9f96-db6ff14c0bd7 send token 0100F68F9DD034FB and AuthToken is not found
... (mais 70 linhas por segundo)

A janela cobre 1 segundo. Pra entender o restart, é preciso do que aconteceu nos últimos 5 minutos. Boa sorte.

Esse é o estado de logs de uma aplicação Elixir hipotética em produção (qualquer semelhança com casos reais que você já viu… bom, é proposital =P). O caso fictício vai servir como fio condutor do artigo — a história é só pra dar concretude pras boas práticas que vêm a seguir.

16 linhas por segundo vêm do código do time

Suponha que a gente rode uma query simples no Loki cobrindo a última hora de produção da aplicação do exemplo, agregando por erl_level:

sum by (erl_level) (count_over_time({app="my-app"}[1h]))

Os números abaixo são ilustrativos — não saíram de um cluster específico, mas refletem a ordem de grandeza que aparece em apps Elixir maduras rodando Phoenix + Tesla + alguns workers. O ponto não são os valores absolutos: é a forma do problema.

Boa parte desse volume é baseline esperado de framework — coisas que o time não escreveu. O lib/phoenix/logger.ex (request summary "Sent 200 in 44ms") sozinho gera 200.015 linhas/h (84,5% do total). Some o lib/tesla/middleware/logger.ex (cliente HTTP, 5.244/h) e os crash reports do runtime (gen_server.erl, 1.508/h), e você tem ~207k linhas que não dá pra diminuir sem mexer em config de lib.

O que sobra — ~58.900 linhas/h, ~16,4 linhas/segundo — é o que o time escreveu. E é aí que mora a história.

Antes de seguir, um número que vale destacar: 5.406 erros por hora em estado estacionário. Sem incidente, sem rollout, só a app vivendo. Pra efeito de comparação: um post-mortem real registrou 1.931 erros Postgrex 22001 em 3 horas durante um incidente que derrubou pod. A taxa de erro “saudável” é 8 vezes mais alta do que a taxa de erro durante um incidente que escreveu um post-mortem.

E quando você filtra o ruído de framework e olha de onde vêm essas 16 linhas/s que o time gera, o quadro fica desconfortável:

topk(10, sum by (file) (count_over_time({app="my-app"} | json [1h])))

(filtrando arquivos sob lib/myapp/)

3 arquivos respondem por 75% do log produzido pelo time. Cinco arquivos respondem por ~85%. O resto da codebase — milhares de módulos — gera, somados, menos log do que o event_worker.ex do ExternalProvider sozinho.

Esse é o efeito da poluição. Cada linha dessas, individualmente, parecia útil quando foi escrita. Somadas, elas afogam o que importa quando alguém precisa investigar — exatamente o oposto do que log existe pra fazer. Log poluído não ajuda a debugar; atrapalha. Cada linha “só por garantia” empurra a linha que realmente conta a história mais pra longe da tela.

E a concentração também é um ponto que vale guardar pro resto do artigo: cada um desses arquivos do topo tem, no fundo, uma única linha de Logger.x que dispara em loop. O ruído todo do Loki não é a aplicação inteira gritando — é meia dúzia de chamadas que, por estarem em caminho quente, dominam o volume. Vamos olhar o líder pra entender o padrão:

Logger.warning(
  "[ExternalProvider EventWorker] - Event already processed, skipping: #{inspect(cache_key)} - #{alert_type}"
)

Tradução: “esse evento já foi processado, então não vou processar de novo”. Isso é dedup funcionando. É o caminho feliz do código. É exatamente o que a função foi escrita pra fazer.

E é classificado como warning. Em produção. 4,5 vezes por segundo. 16 mil vezes por hora.

Esse é o tema do artigo.

Parte 1 — O custo do ruído

💎 Log não é gratuito. Cada linha tem três custos diferentes.

Toda vez que aparece um Logger.info("vou só logar uma coisinha aqui") no código, três orçamentos invisíveis estão sendo gastos:

1. Custo direto de infra. Em uma stack de observabilidade self-hosted, você não paga ingestion fee pra ninguém. Mas paga AWS pelos EC2 que rodam o Loki, pelos EBS/S3 que guardam os chunks indexados, pela rede que move log entre pod, ingester e storage. Esse custo cresce linearmente com volume e com retenção. Cada "#{inspect(big_map)}" num caminho quente infla a linha de 80 bytes pra 4 kB e isso vira EBS extra no mês seguinte — não é uma fatura assustadora de SaaS, é uma curva silenciosa de infra. (Loki — best practices for labels tem o resumo de por que o índice sofre tanto quanto o storage.)

2. Custo cognitivo do on-call. O ser humano que está lendo a tela às 2h da manhã tem largura de banda finita. Se ele precisa rolar 30 segundos de “skipping” antes de achar a stack trace, a velocidade de resolução do incidente cai. Esse custo não aparece em nenhuma fatura, mas aparece no MTTR (e nas DORA Metrics — falamos sobre).

3. Custo de cardinalidade. Esse é o mais sutil e o que mais machuca o Loki no médio prazo. Mensagem que muda a cada chamada explode o índice. Olha o pior ofensor do exemplo:

Logger.warning(
  "[#{@log_namespace}] Resource #{resource.id} send token #{token} and AuthToken is not found"
)

15.374 linhas/hora dessas, cada uma com uma mensagem única (resource_id e token diferentes). Pra você procurar todas as ocorrências desse caso no Loki, não dá pra filtrar por mensagem exata — você precisa de regex (|~), que é mais caro. E você nunca vai conseguir agrupar por essa “categoria de evento” porque do ponto de vista da indexação são 15 mil categorias diferentes por hora.

O padrão correto seria:

# Mensagem fixa + metadata
Logger.warning("AuthToken not found for incoming token",
  resource_id: resource.id,
  token: token
)

Mensagem virou uma categoria. resource_id virou label estruturado, indexável, agrupável. O custo de query no Loki cai. E a busca passa a ser:

{app="my-app"} | json | msg="AuthToken not found for incoming token"

em vez de:

{app="my-app"} |~ "AuthToken is not found"

E o melhor: o resource_id virou um label que você pode pivotar (sum by (resource_id)) pra descobrir se o problema é em um recurso específico ou todos. Antes era impossível.

🎯 Regra prática: mensagem é constante. Variável é metadata. Se o seu Logger.X("...") tem #{interpolation}, pare e pergunte: por que isso não é metadata?

Configurando o formatter e o handler

A boa notícia é que a infra pra isso costuma já estar disponível — só precisa ser configurada. Em uma app Elixir tipica, o setup mínimo tem duas camadas:

a) Formatter de texto pra dev/teste — config :logger, :default_formatter controla como cada linha aparece no console local. Aqui você lista os campos de metadata que quer ver no terminal:

# config/config.exs
config :logger, :default_formatter,
  format: "$time $metadata[$level] $message\n",
  metadata: [
    :request_id,
    :graphql_operation_name,
    :graphql_operation_type,
    :organization_id,
    :resource_id,
    :log_name,
    :span_id,
    :trace_id,
    :module
  ]

Isso é só pra leitura humana no console. Em produção a saída precisa ser estruturada — texto colado não é indexável.

b) Handler JSON pra produção — plugando uma lib como LoggerJSON, cada chamada de Logger.x vira uma linha JSON com msg, level, time, e toda a metadata como campo de primeira classe:

# config/runtime.exs
if config_env() == :prod do
  config :logger, :default_handler,
    formatter: {LoggerJSON.Formatters.Basic, metadata: :all}
end

A lib já vem com formatters prontos pra alguns destinos comuns (Basic, GoogleCloud, Datadog) — escolha o que casa com o backend de logs que você usa. O importante é que, com handler JSON ligado, resource_id, request_id, trace_id deixam de ser texto solto na mensagem e viram colunas que o Loki (ou equivalente) indexa.

A linha do set_auth_token do exemplo já poderia ter resource_id indexável e não tem. Não é falta de infra, é falta de hábito.

Logger.metadata em camadas: configure uma vez, herde sempre

Você não precisa repetir resource_id: em toda chamada de log dentro da árvore de processamento de um recurso. O Logger.metadata/1 é por-processo e propaga pra todos os logs subsequentes naquele mesmo processo Elixir. O caso bom vive em middlewares de entrada como esse:

# lib/my_app_web/middlewares/operation_name_logger.ex
defmodule MyAppWeb.Middleware.OperationNameLogger do
  @behaviour Absinthe.Middleware
  alias Absinthe.Blueprint.Document.Operation

  @impl true
  def call(resolution, _opts) do
    case Enum.find(resolution.path, &match?(%Operation{}, &1)) do
      %Operation{name: name, type: type} when not is_nil(name) ->
        Logger.metadata(graphql_operation_name: name, graphql_operation_type: type)

      _ ->
        Logger.metadata(graphql_operation_name: "#NULL", graphql_operation_type: "#UNKNOWN")
    end

    resolution
  end
end

E o pulo do gato é plugar esse middleware no middleware/3 do schema, pra que ele rode antes de qualquer resolver:

# lib/my_app_web/schema.ex
defmodule MyAppWeb.Schema do
  use Absinthe.Schema
  # ...

  def middleware(middleware, _field, _object) do
    [MyAppWeb.Middleware.OperationNameLogger | middleware]
  end
end

A partir daí, toda chamada de Logger.x dentro daquele request — seja no resolver, no contexto, no Ecto, em qualquer lib — herda esses campos. Custo zero por linha.

A mesma técnica casa bem com outros entry-points — processamento de recurso, de organização, de Oban worker:

# Em um Oban worker, antes de fazer qualquer outra coisa:
def perform(%Job{args: %{"resource_id" => resource_id, "organization_id" => org_id}}) do
  Logger.metadata(resource_id: resource_id, organization_id: org_id)
  do_the_work()
end

Daí pra frente, ninguém precisa interpolar IDs em mensagem. O do_the_work() chama mais 5 funções, cada uma faz 3 logs — todos saem com resource_id e organization_id no JSON. Sem trabalho extra.

Se não quiser repetir esse setup em cada worker, dá pra centralizar via handler de telemetry do Oban. Tem um evento [:oban, :job, :start] que você pode escutar e injetar a metadata antes do perform/1 rodar:

# lib/my_app/application.ex
def start(_type, _args) do
  :telemetry.attach(
    "oban-logger-metadata",
    [:oban, :job, :start],
    &MyApp.ObanLogger.handle_event/4,
    nil
  )
  # ...
end

# lib/my_app/oban_logger.ex
defmodule MyApp.ObanLogger do
  def handle_event([:oban, :job, :start], _measure, %{job: job}, _config) do
    Logger.metadata(
      oban_worker: job.worker,
      oban_job_id: job.id,
      resource_id: job.args["resource_id"],
      organization_id: job.args["organization_id"]
    )
  end
end

Vantagem: workers ficam limpos. Desvantagem: a metadata depende da convenção de keys no args — se um worker usa "device_id" em vez de "resource_id", fica fora. Escolha o que casa com o time.

O inspect que nunca dorme

Pior do que interpolar ID é interpolar payload inteiro. Caso típico no nosso exemplo:

Logger.info(
  "[InboundWebhook] - Income message: #{inspect(params, printable_limit: :infinity, limit: :infinity)}"
)

Repare nos parâmetros do inspect: printable_limit: :infinity, limit: :infinity. A chamada está opt-in explicitamente em não truncar. Na prática, esse Logger.info virou uma promessa contratual de imprimir o payload inteiro, por maior que ele seja, em produção, em todo request — provavelmente uma decisão tomada num momento em que isso fazia sentido, mas que envelheceu junto com o volume do endpoint.

Aproveita e olha um vizinho:

Logger.debug("Complete resource data: #{inspect(resource_data)}")

Logger.debug em produção fica silenciado pelo config :logger, level: :info, então essa linha não chega no Loki — mas chega no log local de dev/staging, e na primeira vez que alguém ativar debug num pod pra investigar algo, ela vai imprimir a struct inteira de cada recurso a cada interação do usuário no mapa.

⚠️ Regra prática: inspect/1 em log é cheiro forte. Se você precisa ver o payload pra debugar, salve o ID e busque o payload depois (no banco, no S3, num replay). Se o payload é pequeno e estável, vira metadata estruturada. Se é grande e dinâmico, não é log, é dump — e dump tem outro lugar.

Parte 2 — Severidade não é decoração

💎 error é o nível “alguém precisa olhar”. Se você usa pra fluxo normal, ninguém olha mais.

Tem uma versão do ditado da fada do dente que diz: se tudo é importante, nada é importante. O nível do log é exatamente isso — uma promessa de relevância. Quando você usa error pra um cenário que não é erro, você quebra o contrato com quem está lendo.

A semântica que eu defendo (e que é mais ou menos consenso no Elixir e fora):

Com esse critério na mão, vamos olhar dois casos típicos.

Caso 1: auth-deny não é erro

if authorized?(token) do
  conn
else
  Logger.error("Unauthorized request with token: #{inspect(token)}")
  abort_request(conn)
end

Em produção, isso aparece com erl_level=error:

{
  "msg": "Unauthorized request with token: nil",
  "function": "call/2",
  "module": "Elixir.MyAppWeb.Plugs.RequireApiToken",
  "request_id": "GLGTwuoyCvEsYq0AtM1E"
}

Tem dois aprendizados nessa linha:

1. Cliente sem token (ou com token errado) é fluxo normal de uma API pública. Não é falha do sistema. Ninguém vai ser acordado às 2h da manhã pra investigar isso. Encaixaria melhor como info ou — se vale a pena ser observável — entrando como métrica (:telemetry.execute([:myapp, :auth, :denied], …)) em vez de log.
2. #{inspect(token)} acaba colocando o valor do token na linha de log. No exemplo, o token era nil (faltou o header no request). Mas no dia em que vier um token inválido mas real, ele vai parar no Loki self-hosted, indexado, retido pelo período que o cluster guarda. É um risco de exposição de credencial que vale evitar.

E a alternativa via telemetry não fica solta — o caminho concreto é declarar a métrica e plugar num Reporter:

# lib/my_app/telemetry.ex
defmodule MyApp.Telemetry do
  import Telemetry.Metrics

  def metrics do
    [
      counter("myapp.auth.denied.count",
        event_name: [:myapp, :auth, :denied],
        tags: [:reason]
      )
    ]
  end
end

Daí no application.ex:

# lib/my_app/application.ex
children = [
  {TelemetryMetricsPrometheus, [metrics: MyApp.Telemetry.metrics()]},
  # ...
]

E no plug, no lugar do Logger.error:

:telemetry.execute([:myapp, :auth, :denied], %{count: 1}, %{reason: :missing_token})

Agora “quantos auth-deny tivemos hoje” é um gráfico, com tag por razão. Nada vai pro Loki — e ninguém é acordado.

Caso 2: o retry esperado virou alerta

Logger.error("Erro ao criar recurso: #{inspect(response)}")

Esse log aparece em produção como:

{
  "msg": "Erro ao criar recurso: \"network exception\"",
  "module": "Elixir.MyApp.Gateways.DeviceCloud.Device.ConfigResource",
  "function": "configure_resource/3"
}

Aqui o que acontece é: chamada HTTP pra um gateway externo deu network exception. O código trata isso logo na linha seguinte: get_resource(device_channel, area_id, external_id) — vai consultar a API pra ver se o recurso já existe, faz retry, segue a vida. A operação se recupera sozinha.

Isso não é error. Isso é warning (talvez), ou nem isso. E o top 1 de volume de erros nesse mesmo serviço é exatamente esse módulo: 1.628 “erros” por hora vindos de process_event.ex do mesmo gateway, no mesmo padrão de “API externa lenta/instável, tô tentando de novo”.

Quem vê o painel de erros vê 5.406 errors/h e mete o pé do freio. Quem investiga descobre que ~30-50% disso é retry esperado de gateway. A métrica mente — e quando ela mente, ninguém olha mais.

O caso bom (também tem)

Pra fechar, um exemplo correto:

Logger.warning(
  "[CrmWebhookWorker] webhook_id=#{webhook.id} rate-limited — snoozing #{seconds}s"
)

Rate limit do destino: algo degradou (não vamos entregar agora), mas se recupera (vamos tentar de novo em seconds). Level warning, mensagem ação-orientada, ID estruturado (mesmo que dentro da string — o webhook_id= ajuda quem busca, mas a forma ideal seria Logger.warning("rate-limited; snoozing", webhook_id: webhook.id, snooze_seconds: seconds)).

Esse log diz uma coisa útil pra um humano: estou fazendo o snooze, fica de olho se virar epidemia. É exatamente isso que warning deve dizer.

Sobre o idioma do log

Você vai notar que parte dos exemplos acima está em português (Erro ao criar recurso, Recurso não encontrado) e parte em inglês. Não é incomum encontrar codebases bilíngues — coisa que acontece naturalmente em time bilíngue ao longo do tempo, e que individualmente cada escolha fez sentido.

Não tem nada de errado em logar em português. O custo é específico de misturar na mesma codebase: alerta por substring precisa cobrir as duas variantes ({app="my-app"} |~ "not found|não encontrado"), busca no Loki força lembrar de duas versões da palavra, e quem ainda está se ambientando no domínio gasta atenção extra na tradução mental.

A reflexão é simples: escolher um idioma só — inglês ou português, qualquer dos dois — entrega mais consistência do que o estado misto. É uma conversa que vale o time fazer com calma, escolher um e seguir daí em diante.

Parte 3 — Telemetry e Logger não são a mesma coisa

💎 Se você consegue contar e agrupar, é métrica. Se você precisa contar a história, é log.

Uma stack Elixir moderna costuma ter :telemetry configurado, e o OpenTelemetry plugado no formatter de log via trace_id e span_id. Os dois canais são complementares, não substitutos. A convenção que eu uso:

• Telemetry responde “quantos / com que frequência / quão rápido”. Métrica, agregação, dashboard. Ex.: [:myapp, :crm, :webhook, :received], com :duration, :batch_size, provider.
• Logger responde “o que aconteceu nesse caso específico que eu preciso reconstruir”. Evento singular, com IDs pra cross-reference. Ex.: Logger.warning("webhook rate-limited", webhook_id: id, retry_in_seconds: s).

O caso bom é esse:

:telemetry.execute(
  [:myapp, :crm, :webhook, :received],
  Map.put(summary, :batch_size, length(events)),
  %{provider: :hubspot}
)

Métrica pura. Nenhum log redundante. Quem quiser saber “quantos webhooks o HubSpot mandou hoje” não vai ler logs — vai abrir o dashboard.

Plugando isso na sua app

Pra :telemetry.execute/3 virar gráfico de fato, falta o outro lado da equação — alguém escutando o evento e exportando como métrica. O caminho mais direto numa app Elixir moderna é a combinação :telemetry_metrics + um Reporter:

# lib/my_app/telemetry.ex
defmodule MyApp.Telemetry do
  import Telemetry.Metrics

  def metrics do
    [
      counter("myapp.crm.webhook.received.count",
        event_name: [:myapp, :crm, :webhook, :received],
        tags: [:provider]
      ),
      distribution("myapp.crm.webhook.received.duration",
        event_name: [:myapp, :crm, :webhook, :received],
        measurement: :duration,
        tags: [:provider],
        unit: {:native, :millisecond}
      )
    ]
  end
end

# lib/my_app/application.ex
children = [
  {TelemetryMetricsPrometheus, [metrics: MyApp.Telemetry.metrics()]},
  # ...
]

Pronto: o Reporter expõe um endpoint /metrics no formato Prometheus, e o evento [:myapp, :crm, :webhook, :received] vira myapp_crm_webhook_received_count_total{provider="hubspot"} no painel.

Pra casos mais específicos onde Reporter pronto não dá conta, dá pra anexar um handler customizado:

:telemetry.attach(
  "myapp-crm-webhook-logger",
  [:myapp, :crm, :webhook, :received],
  fn _event, measure, meta, _config ->
    # lógica customizada aqui
    MyApp.Metrics.record(measure, meta)
  end,
  nil
)

Cuidado com isso em hot path — attach/4 roda síncrono no processo que emitiu o evento. Pra evento de alta frequência, prefira o Reporter pronto.

O caso ruim

Quase toda codebase tem: o mesmo evento gera log E métrica. O log fica desalinhado da métrica (texto antigo, formato antigo, sem o campo novo que entrou na métrica) e o on-call lê o log porque é o que aparece no Loki. Pior dos dois mundos.

🎯 Regra prática: antes de adicionar um Logger.info num caminho de alta frequência, pergunte: isso vai virar gráfico um dia? Se vai, é telemetria. Não log.

Parte 4 — Debuggabilidade: a hora em que o log salva

Tudo que conversamos até aqui foi sobre podar. Mas o log tem um trabalho que nenhuma outra ferramenta faz tão bem: contar a história de um caso específico, pra um humano, depois do fato.

Pensa num incidente de cascata via process links (o tipo de coisa que a Parte 2 da série descreve). O que permite reconstruir esse tipo de incidente em algumas horas é exatamente o que costuma estar bem feito nos logs:

• trace_id estável atravessando processos. A Task que crashou tinha o mesmo trace_id do request original; o GenServer que recebeu o {:EXIT, _, :shutdown} tinha o trace_id herdado por causa do Logger.metadata.
• Mensagens distinguíveis das exceções: Postgrex.Error 22001 string_data_right_truncation é uma string única e googlável. function_clause em Highlander.handle_info/2 aponta direto pro código.
• Contagem agregada funciona porque a mensagem é estável: count_over_time({...} |= "22001" [3h]) dá 1.931 sem precisar de regex caro.

É esse trio que permite sair da hipótese errada (“é OOM”) pra hipótese certa (“é cascade de link via Task”) em poucas iterações.

Agora olha o anti-padrão exato disso:

exception ->
  Logger.error("Unexpected error: #{inspect(exception)}",
    error: exception,
    stacktrace: __STACKTRACE__
  )

  Resolution.put_result(resolution, @default_error)

A intenção é exatamente a certa: middleware do Absinthe que captura exceções inesperadas pra não derrubar a resposta GraphQL. A forma, porém, tem três pontos que vale repensar do ponto de vista de investigabilidade:

1. A mensagem é constante ("Unexpected error: ...") mas o conteúdo do inspect(exception) muda a cada caso. Você vai cair na mesma armadilha de cardinalidade da Parte 1 — não dá pra agrupar por “tipo de exceção”.
2. O resolver que estourou não está no log (não tem graphql_operation_name na mensagem — vai pegar do metadata se o OperationNameLogger rodou antes; bom em teoria, frágil em prática).
3. O caller recebe {:error, :unknown} (o @default_error) — não tem como o frontend distinguir “validação falhou” de “BEAM pegou fogo”.

O conserto idiomático seria algo como:

exception ->
  Logger.error("absinthe resolver raised",
    exception_module: exception.__struct__,
    exception_message: Exception.message(exception),
    stacktrace: Exception.format_stacktrace(__STACKTRACE__)
  )

  Resolution.put_result(resolution, @default_error)

Mensagem estável ("absinthe resolver raised"), módulo da exceção como metadata indexável (exception_module=Postgrex.Error, exception_module=ArgumentError), mensagem humana separada. Agora dá pra fazer:

sum by (exception_module) (count_over_time({app="my-app"} | json | msg="absinthe resolver raised" [1h]))

e ver, em um gráfico, quais exceções são as mais frequentes. Mesma intenção do código original, com debuggabilidade ligada.

Bônus: PII em log

Os mesmos caminhos que comem o pulmão do Loki também são onde a PII costuma vazar. Caso típico:

Logger.debug("[Forms] form: create with params #{inspect(params)}")

params aqui é o body inteiro do request — em checklist pode incluir CPF, telefone, foto. Mesmo sendo debug (silenciado em prod), basta alguém ativar debug num pod por 5 minutos pra essa linha derramar dados pessoais no Loki. E uma vez no Loki, fica retido pelo período de retenção. É um caso onde vale repensar a estratégia: logar só o ID do form recém-criado, e deixar o payload completo fora.

Pra payload de request, o padrão correto começa na entrada — Absinthe, por exemplo, tem filtro explícito de variáveis:

config :absinthe, Absinthe.Logger,
  pipeline: true,
  filter_variables: ["access_token", "password", "secret"]

Lista explícita de chaves a filtrar. Não é à prova de balas (precisa lembrar de incluir cada campo novo), mas é melhor que inspect/1 puro.

Pra uma rede de segurança adicional — que pega o que escapa do filtro de entrada — o LoggerJSON aceita redactors aplicados a toda saída de log:

# config/runtime.exs (prod)
config :logger, :default_handler,
  formatter:
    {LoggerJSON.Formatters.Basic,
     metadata: :all,
     redactors: [
       {LoggerJSON.Redactors.RedactKeys, ["password", "token", "cpf", "access_token"]}
     ]}

Toda chave dessa lista, encontrada em qualquer profundidade da metadata serializada, sai como "[REDACTED]". Não substitui o filtro na entrada (que evita inclusive o objeto sequer ser construído), mas funciona como linha de defesa final pra quando alguém esquece.

Checklist: como avaliar uma linha de log antes de mergear

Toda vez que você adicionar (ou tocar) um Logger.x num PR, passe por essa checklist:

Camada 1 — A linha

• Level certo? error é “acorde alguém”, warning é “degradou mas se recuperou”, info é “evento de negócio”, debug é “investigação ativa”. Sob dúvida, desça um nível.
• Mensagem fixa? Se a string muda a cada chamada (#{...}), você está fabricando cardinalidade. Mova o que muda pra metadata.
• Sem inspect/1 de struct grande? Especialmente sem printable_limit: :infinity. Se precisa ver o objeto inteiro, não é log, é dump.

Camada 2 — Contexto

• Tem ID que liga essa linha ao resto da execução? request_id, resource_id, organization_id, trace_id. O formatter do app já declara esses campos — basta usar.
• Você precisa repetir o ID em toda chamada? Quase nunca. Configure uma vez no entry-point com Logger.metadata/1 (hexdocs) e toda a árvore herda.

Camada 3 — Conteúdo

• PII fora? Token, CPF, e-mail, telefone, foto, payload inteiro de request não entram em log. Lista explícita de campos a filtrar, no estilo do Absinthe filter_variables, e redactor de defesa final no LoggerJSON.
• Não duplica o que telemetry já mede? Se a pergunta que essa linha responde é “quantos / em quanto tempo”, a resposta é métrica, não log.

Camada 4 — Volume

• Está num hot path? LiveView event handler, Broadway processor, Oban worker em loop, GenServer com mailbox cheia. Se sim: o level natural é debug. Se a intuição é que precisa ser info, vale articular o motivo antes — geralmente um deles aparece.
• A linha é repetida muitas vezes com a mesma mensagem? Considere se é “evento individual” (log) ou “métrica de frequência” (telemetry).

Camada 5 — Investigabilidade

• Se um humano precisar achar essa linha no Loki às 3 da manhã, ele consegue? A mensagem é distinguível? Tem labels que permitem narrar (| json | msg="...")? Tem trace_id pra cruzar com OTel?
• Se essa linha aparecer 10.000 vezes/h, alguém vai notar? Se não vai, o nível tá errado pra cima. Se vai, o nível tá certo — mas é melhor virar telemetry.

Em uma frase

Log é o canal mais barato de comunicar com o seu eu de daqui a três meses. Não desperdice.

Os números que abriram o artigo — 16 linhas/segundo escritas pelo time do exemplo, 5.406 erros/hora, 75% disso vindo de 3 arquivos — não são “muito log”. São log mal calibrado. A diferença entre o estado atual e um estado saudável não é cortar pela metade: é cada linha ter um leitor previsto e um trabalho específico.

Esse artigo não pede pra ninguém abrir PR amanhã. O objetivo dele é só pôr cada um dos pontos acima na cabeça do time. Da próxima vez que você abrir um arquivo e tiver que adicionar (ou tocar) um Logger.x, que a pergunta “esse log responde a alguma das 5 camadas do checklist?” venha junto, e que a resposta seja consciente.

E da próxima vez que você for escrever Logger.error("Erro ao …"), lembra: 1.628 outras linhas idênticas já estão na fila, e nenhuma delas é erro.

Referências

• Logger (hexdocs) — toda a API, com a parte de metadata
• Logger.metadata/1 — propagação por processo
• logger_json (hexdocs) — formatter JSON e redactors
• :telemetry (hexdocs) — métrica vs log
• Telemetry.Metrics (hexdocs) — definição declarativa de métricas
• TelemetryMetricsPrometheus (hexdocs) — Reporter pra expor /metrics
• Loki — best practices for labels — por que cardinalidade na mensagem dói
• 12-Factor App — XI. Logs — a opinião clássica sobre log como stream de eventos
• GenServer the “rabbit hole” (parte 1) — parte 1 da série
• GenServer the “rabbit hole” — Parte 2: A cascata silenciosa — parte 2
• DORA Metrics — onde MTTR vira número, e onde log de qualidade vira diferença mensurável