Aiologger - Logger assíncrono para Python e asyncio

Acho que todo desenvolvedor e equipe passam por etapas de amadurecimento bem parecidas ao longo da geração de logs de sistemas:

1. Aplicações geram nenhum ou quase nenhum log;
2. Escrevemos aplicações verbosas demais, com logs provavelmente muito extensos e voltados para outros humanos;
3. Passamos a gerar logs estruturados, serializados para algum formato de fácil consumo e indexação em algum sistema de gerenciamento de logs, como JSON, msgpack, etc;
4. Começamos a extrair valor através de métricas geradas a partir de dados logados.

Nesse ponto, logs se tornam essenciais em qualquer aplicação. Bons logs podem nos ajudar no processo de debugging, a medir a saúde e performance, a detectar anomalias e, em geral, nos ajudam a operar sistemas.

Na Sieve, meu time na B2W Digital, começamos a usar Python assíncrono com asyncio na massiva maioria das aplicações a mais ou menos 2 anos. Ao mesmo tempo que aplicações eram desenvolvidas, novas métricas de operação se mostravam necessárias e cada vez mais logs precisavam ser gerados.

Se quiser saber sobre asyncio, recomendo começar por esse post aqui.

Como qualquer outra coisa na nossa aplicação, logar não é uma operação gratuita. Logar tem um custo de performance, e esse custo pode ser bem caro se você gerar grandes volumes de logs com o módulo builtin logging em uma aplicação assíncrona.

Para demonstrar isso, vamos começar com um exemplo de código simples:

Tudo o que esse código faz é criar 10000 corotinas que vão imprimir no stdout , de forma concorrente, a string "Hello world !" utilizando o logger padrão do python.

exemplo_sem_aiologger.py — Diagrama de concorrência do pycharm

Usando o diagrama de concorrência do pycharm, percebemos que o código passa uma boa parte do tempo lidando com operações de lock. Locks são mecanismos de sincronização de programação multithread. Se você está usando asyncio, muito provavelmente você não tem logs sendo gerados em mais de um thread e esse tipo de mecanismo não precisa estar presente na sua aplicação.

Além disso, como estamos escrevendo para um file descriptor (stdout), essa é uma operação de I/O e, como tal, com asyncio, devemos tratá-la de forma não bloqueante.

Em unix, para que isso seja possível, significa que devemos fazer a chamada de open com a flag O_NONBLOCK

Vamos ver como o próprio logger usado pelo asyncio se comporta?

>>> True

A função os.get_blocking verifica se o file descriptor foi aberto em modo bloqueante, ou seja, verifica pela flag O_NONBLOCK. Isso significa que, por padrão, o log gerado pelo próprio asyncio é bloqueante.

Apesar dos avanços que Python tem feito nos últimos anos com relação a programação assíncrona, ainda estamos bem longe de ter um ecossistema completo. Ao contrário de Go e Javascript, que já nasceram assíncronas por natureza, ainda temos um bom caminho a percorrer. Asyncio foi lançado sem alternativas oficiais para funções básicas como por exemplo open e print, dando margem para implementações não oficiais da comunidade.

Aiologger

Como o Logger padrão opera de forma bloqueante e ineficiente para aplicações asyncio, aiologger nasceu com o objetivo de substituí-lo de forma eficiente e não bloqueante. Se você já está acostumado com o `logging.Logger` e asyncio, não vai estranhar em nada a interface. Basta adicionar await nas chamadas a debug, info, warn…

Voltando ao nosso exemplo inicial, o mesmo código com aiologger seria:

Como o aiologger remove o uso de locks, não existe mais tempo de espera.

>>> Hello stderr !
>>> Hello stdout !
>>> False
>>> False

E agora escrevemos no stdout/stderr de forma não bloqueante.

Se você se interessou pelas vantagens, recomendo muito que confira a documentação. Já utilizamos o aiologger em diversas aplicações em produção e é comprovadamente estável. Sabemos que diversas coisas podem melhorar e estamos sempre abertos a sugestões e pull requests!