Log do Python: um tutorial aprofundado

À medida que os aplicativos se tornam mais complexos, ter bons logs pode ser muito útil, não apenas durante a depuração, mas também para fornecer informações sobre problemas/desempenho do aplicativo.

A biblioteca padrão do Python vem com um módulo de registro que fornece a maioria dos recursos básicos de registro. Ao configurá-lo corretamente, uma mensagem de log pode trazer muitas informações úteis sobre quando e onde o log é acionado, bem como o contexto do log, como o processo/thread em execução.

Apesar das vantagens, o módulo de registro é muitas vezes esquecido, pois leva algum tempo para configurar corretamente e, embora completo, na minha opinião, o documento oficial de registro em https://docs.python.org/3/library/logging.html realmente não fornece as melhores práticas de registro nem destaca algumas surpresas de registro.

Este tutorial de log do Python não pretende ser um documento completo sobre o módulo de log, mas sim um guia de “introdução” que apresenta alguns conceitos de log, bem como algumas “pegadinhas” a serem observadas. A postagem terminará com as práticas recomendadas e conterá algumas dicas para tópicos de registro mais avançados.

Observe que todos os trechos de código na postagem supõem que você já importou o módulo de log:

 import logging

Conceitos para Python Logging

Esta seção fornece uma visão geral de alguns conceitos que são frequentemente encontrados no módulo de registro.

Níveis de Log do Python

O nível de log corresponde à “importância” que um log recebe: um log de “erro” deve ser mais urgente que o log de “aviso”, enquanto um log de “depuração” deve ser útil apenas para depurar a aplicação.

Existem seis níveis de log em Python; cada nível está associado a um número inteiro que indica a gravidade do log: NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 e CRITICAL=50.

Todos os níveis são bastante diretos (DEBUG < INFO < WARN ) exceto NOTSET, cuja particularidade será abordada a seguir.

Formatação de Log do Python

O formatador de log basicamente enriquece uma mensagem de log adicionando informações de contexto a ela. Pode ser útil saber quando o log é enviado, onde (arquivo Python, número da linha, método, etc.) e contexto adicional, como thread e processo (pode ser extremamente útil ao depurar um aplicativo multithread).

Por exemplo, quando um log “hello world” é enviado por meio de um formatador de log:

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

se tornará

 2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world 

Manipulador de Log do Python

O manipulador de log é o componente que efetivamente grava/exibe um log: exiba-o no console (via StreamHandler), em um arquivo (via FileHandler) ou até mesmo enviando um e-mail via SMTPHandler, etc.

Cada manipulador de log tem 2 campos importantes:

• Um formatador que adiciona informações de contexto a um log.
• Um nível de log que filtra os logs cujos níveis são inferiores. Portanto, um manipulador de log com o nível INFO não manipulará logs DEBUG.

A biblioteca padrão fornece um punhado de manipuladores que devem ser suficientes para casos de uso comuns: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Os mais comuns são StreamHandler e FileHandler:

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Python Logger

O Logger é provavelmente aquele que será usado diretamente com mais frequência no código e que também é o mais complicado. Um novo registrador pode ser obtido por:

 toto_logger = logging.getLogger("toto")

Um registrador tem três campos principais:

• Propagar: Decide se um log deve ser propagado para o pai do registrador. Por padrão, seu valor é True.
• Um nível: Assim como o nível do manipulador de logs, o nível do logger é usado para filtrar os logs “menos importantes”. Exceto que, ao contrário do manipulador de log, o nível é verificado apenas no registrador “filho”; uma vez que o log é propagado para seus pais, o nível não será verificado. Este é um comportamento pouco intuitivo.
• Manipuladores: A lista de manipuladores para os quais um log será enviado quando chegar a um registrador. Isso permite um tratamento de log flexível—por exemplo, você pode ter um manipulador de log de arquivo que registra todos os logs DEBUG e um manipulador de log de e-mail que será usado apenas para logs CRITICAL. A esse respeito, o relacionamento registrador-manipulador é semelhante ao de um editor-consumidor: um log será transmitido para todos os manipuladores assim que passar na verificação de nível do registrador.

Um logger é único por nome, o que significa que se um logger com o nome “toto” foi criado, as chamadas consequentes de logging.getLogger("toto") retornarão o mesmo objeto:

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

Como você deve ter adivinhado, os madeireiros têm uma hierarquia. No topo da hierarquia está o root logger, que pode ser acessado via logging.root. Este registrador é chamado quando métodos como logging.debug() são usados. Por padrão, o nível de log raiz é WARN, portanto, todos os logs com nível inferior (por exemplo, via logging.info("info") ) serão ignorados. Outra particularidade do root logger é que seu handler padrão será criado na primeira vez que um log com um nível maior que WARN for registrado. Usar o root logger direta ou indiretamente por meio de métodos como logging.debug() geralmente não é recomendado.

Por padrão, quando um novo registrador é criado, seu pai será definido como o registrador raiz:

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

No entanto, o registrador usa a “notação de ponto”, o que significa que um registrador com o nome “ab” será filho do registrador “a”. No entanto, isso só é verdade se o registrador “a” tiver sido criado, caso contrário, o pai “ab” ainda é a raiz.

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

Quando um logger decide se um log deve passar de acordo com a verificação de nível (por exemplo, se o nível do log for inferior ao nível do logger, o log será ignorado), ele usa seu “nível efetivo” em vez do nível real. O nível efetivo é igual ao nível do registrador se o nível não for NOTSET, ou seja, todos os valores de DEBUG até CRITICAL; no entanto, se o nível do registrador for NOTSET, o nível efetivo será o primeiro nível ancestral que possui um nível não-NOTSET.

Por padrão, um novo registrador possui o nível NOTSET e, como o registrador raiz possui um nível WARN, o nível efetivo do registrador será WARN. Portanto, mesmo que um novo registrador tenha alguns manipuladores anexados, esses manipuladores não serão chamados, a menos que o nível de log exceda WARN:

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

Por padrão, o nível do logger será usado para decidir os passos de um log: Se o nível do log for inferior ao nível do logger, o log será ignorado.

Práticas recomendadas de log do Python

O módulo de registro é realmente muito útil, mas contém algumas peculiaridades que podem causar longas horas de dor de cabeça até mesmo para os melhores desenvolvedores de Python. Aqui estão as melhores práticas para usar este módulo na minha opinião:

• Configure o root logger mas nunca o use em seu código—por exemplo, nunca chame uma função como logging.info() , que na verdade chama o root logger nos bastidores. Se você deseja capturar mensagens de erro das bibliotecas que usa, certifique-se de configurar o logger raiz para gravar em um arquivo, por exemplo, para facilitar a depuração. Por padrão, o logger raiz só gera saída para stderr , então o log pode se perder facilmente.
• Para usar o log, certifique-se de criar um novo logger usando logging.getLogger(logger name) . Eu costumo usar __name__ como o nome do registrador, mas qualquer coisa pode ser usada, desde que seja consistente. Para adicionar mais manipuladores, geralmente tenho um método que retorna um logger (você pode encontrar a essência em https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0).

 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

Depois de criar um novo registrador e usá-lo:

 my_logger = get_logger("my module name") my_logger.debug("a debug message")

• Use as classes RotatingFileHandler, como o TimedRotatingFileHandler usado no exemplo em vez de FileHandler, pois ele rotacionará o arquivo automaticamente quando o arquivo atingir um limite de tamanho ou fará isso todos os dias.
• Use ferramentas como Sentry, Airbrake, Raygun, etc., para capturar logs de erros automaticamente para você. Isso é especialmente útil no contexto de um aplicativo da Web, onde o log pode ser muito detalhado e os logs de erros podem ser perdidos facilmente. Outra vantagem de usar essas ferramentas é que você pode obter detalhes sobre os valores das variáveis ​​no erro para saber qual URL aciona o erro, qual usuário está preocupado etc.

Se você estiver interessado em mais práticas recomendadas, leia Os 10 erros mais comuns que os desenvolvedores de Python cometem, do colega Toptaler Martin Chikilian.