Estruturando logs de aplicação Python e de acesso do Gunicorn para o Google Stackdriver

Photo by Mr Cup / Fabien Barral on Unsplash.

O Google Stackdriver é um dos serviços de monitoramento oferecido pela Google que permite a captura de logs e eventos de aplicações hospedadas tanto no Google Cloud Platform (GCP) quanto na Amazon AWS. Além disso, este serviço permite a criação de métricas baseadas nos logs bem como a criação de dashboards para visualizações. Contudo, para utilizar este serviço, algumas configurações são necessárias e é exatamente isso que vamos aprender aqui!

O que você vai aprender neste post:

• Como habilitar o serviço Stackdriver para aplicações que rodam em clusters kubernetes no Google Cloud Platform;
• Como estruturar logs de aplicações Python segundo o formato esperado pelo Stackdriver;
• Como estruturar logs de acesso gerados pelo servidor de aplicação Gunicorn.

Habilitando o serviço Google Stackdriver

O uso recomendado do Google Stackdriver é através da instalação do agente de monitoramento que suporta VMs do Google (Compute Engine) e da Amazon (EC2), o qual permite a coleta de informações como uso disco, uso de CPU, uso de rede e permite o monitoramento de aplicações. O passo a passo para instalação do agente e configuração das autorizações para as VMs mencionadas podem ser encontradas no seguinte link https://cloud.google.com/monitoring/agent/install-agent.

Uma outra opção, e que é o foco deste post, é a utilização do Stackdriver para coleta de informações de aplicações rodando em clusters kubernetes do Google, isto é, para aplicações hospedadas através do Google Kubernetes Engine (GKE). A instalação é super simples, basta selecionar as opções de Stackdriver Logging e Stackdriver monitoring na hora da criação do cluster kubernetes.

Habilitando o serviço de log e monitoramento do Stackdriver para um cluster k8s do Google novo.

Para o caso de clusters k8s já existentes no GCP, basta ir na seção de Kubernetes Engine e clicar em editar no cluster desejado. Em seguida, basta selecionar as opções mencionadas acima.

Habilitando o serviço de log e monitoramento do Stackdriver para um cluster k8s do Google já existente.

Estruturando Logs de aplicações Python rodando no GKE

Após habilitar o Stackdriver, basta realizar o deploy de um serviço através do GKE e os logs já estarão sendo enviados para o Stackdriver "automagicamente"!

Todavia, as mensagens geradas pelos loggers do módulo logging presente na biblioteca padrão do Python não serão interpretados de forma correta pelo Stackdriver devido a falta de formatação requerida que é baseada em logs com formato estruturado do tipo JSON.

Assim, níveis de logging não serão interpretados corretamente como mostra a figura a seguir na qual uma mensagem com nível DEBUG é apresentada de forma incorreta com o símbolo laranja no Stackdriver (!!) que representa o nível WARNING. Além disso, a falta de estruturação torna a criação de queries e métricas baseadas nos logs complexas uma vez que será necessário uma busca em texto ao invés de uma busca simples através de uma chave em um objeto JSON.

Logs não estruturados de aplicações enviadas para o Stackdriver.

Para estruturar os logs de uma aplicação Flask em Python é bem fácil: basta utilizar a biblioteca pythonjsonlogger a qual irá converter as mensagens dos loggers para o formato de JSON.

Criação de uma função de configuração de log em formato de JSON.

Para tal, criamos uma função config_log para criar um handler de logs que possibilita a escrita de mensagens para uma stream de output e adicionamos um objeto de formatação no handler, utilizando a classe jsonlogger.JsonFormatter, para converter as strings de log em um JSON cujo campo message conterá tal string.

Por fim, obtemos uma referência do logger root da aplicação, limpamos outros handlers prévios (que poderiam ter uma formatação diferente) e adicionamos o handler mencionado acima. Agora, todo logger abaixo da hierarquia do root logger irá gerar mensagens em JSON.

Exemplo de um logger gerando uma mensagem tipo string.

Na figura ao lado, o logger, ao invés de gerar uma stream de dados para a stdout contendo a mensagem "this is a plain text msg", este irá gerar a seguinte representação dessa mensagem em formato JSON:

{"message": "this is a plain text msg..."}

O Stackdriver espera exatamente um JSON com um campo "message" uma vez que este deve conter o texto que será exibido na página de logs. Como exemplo, o a seguinte mensagem em formato JSON:

{"message": "GET /healthcheck HTTP/1.1"} 

Será exibido pelo Stackdriver da seguinte forma na página de logs:

Agora, basta configurarmos a biblioteca pythonjsonlogger para especificar os campos que desejamos que estejam presentes nos JSONs de log. Fazemos isso através da criação de uma subclasse da jsonlogger.JsonFormatter:

Subclasse JsonFormatter do pacote jsonlogger.JsonFormatter.

função config_log final utilizada para estruturar as mensagens segundo o modelo do Stackdriver.

Tal subclasse é instanciada na nossa nova função config_log com uma string que denota os campos que desejamos para os JSONs de log:

"%(message)s %(request_id)s %(name)s %(levelname)s %(lineno)s %(pathname)s %(asctime)s"

• message (que conterá a própria mensagem do log);
• request_id (adicionado pela biblioteca flask_log_request_id para gerar um id único para cada requisição);
• name (o nome do logger);
• levelname (o nível de severidade do log). Note que a subclasse que criamos faz um override do método process_log_record para trocar o campo levelname para o nome severity que é o formato esperado pelo Stackdriver para exibição do nível correto de log;
• lineno (linha de código onde o logger foi invocado);
• pathname (path do módulo python onde o logger foi invocado);
• asctime (datetime da mensagem logger).

Após executar tal função no início da aplicação, todas as mensagens de loggers abaixo da hierarquia do root logger já irão produzir mensagens em formato JSON com os campos mencionados anteriormente. A figura a seguir ilustra um logger e o formato final gerado pelo mesmo:

logger da aplicação já configurado para o Stackdriver.

Por fim, caso desejemos adicionar alguns campos a mais neste JSON de log (análogo a um mapped diagnostic context do Java), basta apenas incluir um dicionário que contenha os dados desejados no argumento nomeado extra na invocação do logger:

Uso de um Logger com um campo adicional de contexto.

Todo JSON estruturado que criamos será interpretado pelo Stackdriver e estará contido dentro do campo jsonPayload, conforme é apresentado na figura abaixo. Dentro deste payload, eventuais campos adicionais que inserimos como contexto também estarão presentes e são de fácil acesso para criamos queries e métricas baseadas nas mensagens de log:

Estruturando logs de acesso do Gunicorn

Para estruturar os logs de acesso que o servidor de aplicação Gunicorn gera, basta adicionar o seguinte formato no arquivo de configuração do mesmo:

access_log_format = ‘{“message”: “%(r)s”, “request_id”: “%({X-Request-ID}o)s”, “http_status”: %(s)s, “ip_address”: “%(h)s”, “response_length”: “%(b)s”, “referer”: “%(f)s”, “user_agent”: “%(a)s”, “request_time”: %(L)s, “date”: “%(t)s”}’

Nota-se que tal formato é similar a de um JSON e que é interpretado corretamente pelo Stackdriver. Assim, a figura a seguir mostra um log de acesso estruturado corretamente e com a interpretação adequada pelo Stackdriver:

Logs estruturados e interpretados corretamente pelo Stackdriver.

E é isso aí! Neste post aprendemos a deixar pra trás as velhas mensagens de log em strings não estruturadas e a utilizar mensagens de log em formato JSON para o Stackdriver!

Photo by Mr Cup / Fabien Barral on Unsplash.

Com logs em formato JSON, o Stackdriver pode interpretar com facilidade os campos que adicionamos e apresentar de forma correta as nossas mensagens! Além disso, conseguimos acessar os campos do JSON para criar métricas para dashboards!

Qual dúvida ou sugestão, basta adicionar comentário!

Até o próximo post!

logger.info("see ya!!")