"Vou logar tudo, ligar debug em produção" - quem nunca teve vontade de fazer isso? ou que já fez isso? Eu já fiz, me arrependi; me arrependi porque o sistema ficou muito mais lento, criando impacto nos usuários finais e o volume de logs foi tão grande que ficou impossível achar o que eu queria. Durante o desenvolvimento muitas vezes criamos diversas mensagens de log, elas ajudam muito a entender como o sistema está funcionando. Mas todos esses logs quando em produção fazem pouco sentido e só geram pressão no sistema de logs. Precisamos de mensagens de log que façam sentido numa investigação, por exemplo um stacktrace faz sentido ser logado, mas todos os If's que tomamos no meio do caminho não fazem.

Os logs tem que fazer sentido para o negócio também. Alguns logs podem ser em função de uma exigência legal. Outros para auditoria interna. Logue coisas que não façam sentido ter uma métrica, mas que são importantes para entender o que aconteceu na aplicação. Lembre-se: logs não substituem métricas, podem até auxiliar em alguns momentos quando estamos voando às cegas, mas adicione as métricas necessárias assim que possível.

Com leis em vigor como LGPD (Lei Geral de Proteção de Dados) no Brasil e GDPR (General Data Protection Regulation) na Europa, precisamos ter um cuidado extra com os dados que são logados. Um dos artigos da lei menciona o fato de um usuário poder pedir a remoção de seus dados pessoais dos sistemas que a empresa gerencia. Caso tenhamos logado esses dados, vamos ter que percorrer um enorme volume de logs para encontrar e remover os dados pessoais. Em geral, logs não devem ser alterados depois de escritos por requisitos jurídicos, portanto temos um grande problema do ponto de vista legal caso precisarmos alterar algum valor neles. Evite escrever qualquer dado pessoal em mensagens de log.

Dependendo da importância dos logs, eles podem (devem) inclusive ficar armazenados em infraestruturas diferentes, com acesso muito restrito, evitando ao máximo que eles sejam alterados.

Garanta que todos os sistemas adicionem e repassem um header de Request-Id. O seu sistema não trabalha sozinho, existem diversas peças de software envolvidas pare ele funcionar. Com um RequestId passando entre sistemas, fica fácil isolar na busca dos logs onde foi a falha. É um sistema de tracing bastante rudimentar, mas que dá muita informação para o caso de problemas. Se puderes, tente adicionar e instrumentar as aplicações para um sistema de tracing completo. Instrumentar é fundamental.

E o mais importante de tudo: SEMPRE leia os logs.

Mensagens de log

Outro aspecto importante é como escrever as mensagens de log. Quais informações são pertinentes e qual a ordem que devemos apresentá-las? Neste trabalho os autores exploram esses aspectos e propõe o seguinte modelo do que uma mensagem de log deve conter:

• Quando?
• Onde?
• Severidade
• O quê?
• Por quê?
• O quê irá acontecer?
• Outro detalhes

Os três primeiros são metadados sobre o log: data, servidor, arquivo e linha de código, severidade. Os outros trazem informações concretas do que aconteceu. Os autores ainda definem quais campos são necessários dependendo da severidade.

Não precisamos seguir à risca o que diz o artigo, mas precisamos ter uma noção de que estruturar as mensagens em volta de um padrão torna mais fácil o nosso trabalho. Queremos as informações necessárias para uma boa investigação.

Formato de logs

Dê preferência para logs estruturados, isto é não logue texto puro, mas algo que o sistema de logging consiga entender e simplificar a busca. Em um log estruturado fica fácil definir campos customizados, dados que são de interesse do time na hora de realizar uma pesquisa. Usando o exemplo abaixo, temos os campos referentes ao comportamento do upstream claramente definidos no log estruturado. Na versão somente texto não temos todas essas informações.

Exemplo de log em formato de texto

173.234.238.142 - - [04/Oct/2021:17:18:35 +0000] "GET /?param=a HTTP/2.0" 200 5316 "https://mysite.com/?param=a" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36" "2.75"

Exemplo de log estruturado:

{
    "@timestamp": "2021-10-04T17:18:35+0000",
    "host": "nginx01.mysite.com",
    "remote_addr": "173.234.238.142",
    "vhost": "mysite.com",
    "request_method": "GET",
    "request_uri": "/?param=a",
    "server_protocol": "HTTP/2.0",
    "http_referer": "",
    "status": "200",
    "body_bytes_sent": "5316",
    "request_time": "2.75",
    "upstream_addr": "internal.mysite.cloud",
    "upstream_status": "200",
    "upstream_response_length": "5316",
    "upstream_response_time": "2.73",
    "upstream_cache_status": "MISS",
    "uri": "https://mysite.com/?param=a",
    "http_user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.82 Safari/537.36",
    "http_x_forwarded_for": "mysite.com"
}

Sistemas de logs

Outro aspecto muito importante de logs é o sistema que faz o gerenciamento deles — faz a coleta, prepara os dados, armazena e disponibiliza para busca. Normalmente só olhamos para nossas aplicações e os logs que elas geram, mas entender o que está do outro lado nos ajuda a escrever logs melhores. Abaixo temos um desenho esquemático de como funcionam a maioria dos sistemas de logs. Vamos seguir o fluxo de um log, da aplicação até a busca que foi realizada.

As aplicações geram seus logs durante seu ciclo de vida. Estes logs podem ir diretamente para um sistema de ingestão ou podem ser escritos na saída padrão. Quando vão para a saída padrão tem mais uma peça no desenho que faz o envio para o sistema de ingestão. O sistema de ingestão vai fazer um pré-processamento dos logs, transformar texto em json e possivelmente ajustar a data de recebimento.

Para sistemas que geram uma quantidade massiva de logs, normalmente, temos uma fila, que serve de armazenamento temporário e não deixa saturar o sistema de indexação, evitando perdas de logs. Aqui podemos ver qual o impacto que uma aplicação gerando uma quantidade excessiva de logs pode ter em outras aplicações. Se tivermos uma aplicação com muitos logs e outra com poucos logs, a fila irá encher e ambas demorarão para chegar na indexação. Por isso o conselho de gerar uma quantidade menor de logs quando em produção.

Do outro lado da fila, temos um sistema de indexação que fará o processamento necessário no log para adicioná-lo a um índice. É nesse momento que um campo de data é reconhecido como tal e que todos os outros campos ganham significado¹ para que possamos realizar buscas. O log agora está dentro de um conjunto enorme de outros logs, todos devidamente identificados e preparados para pesquisas.

A pessoa desenvolvedora normalmente utiliza uma interface gráfica para fazer as buscas, limitando os logs para serem de uma só aplicação, no espaço de tempo de interesse, etc. A maioria dos sistemas têm uma linguagem de busca extremamente poderosa, permitindo acharmos a agulha no meio do palheiro. Esse sistema de query busca os dados que foram previamente indexados e retorna todas as linhas de log relacionadas. A sugestão de repassar um Request-Id entre as aplicações vem justamente para facilitar no momento de busca.

O principal sistema de logs open-source é a combinação de ElasticSearch, Logstash e Kibana, conhecido comumente por ELK. Seu funcionamento é bastante similar ao que acabei de descrever.

1. Liberdade poética, não estou falando de semântica. ↩