Como usar logging em Python 3

Introdução

O módulo logging faz parte da biblioteca padrão do Python e fornece rastreamento de eventos que ocorrem durante a execução do software. Você pode adicionar chamadas de logging ao seu código para indicar quais eventos ocorreram.

O módulo logging permite tanto o logging diagnóstico que registra eventos relacionados à operação de uma aplicação, quanto o logging de auditoria que registra os eventos das transações de um usuário para análise. É especialmente utilizado para registrar eventos em um arquivo.

Pré-requisitos

Você deve ter o Python 3 instalado e um ambiente de programação configurado em seu computador ou servidor. Se você não tiver um ambiente de programação configurado, pode consultar os guias de instalação e configuração para um ambiente de programação local ou para um ambiente de programação em seu servidor apropriado para seu sistema operacional (Ubuntu, CentOS, Debian, etc.).

Por que usar o módulo logging

O módulo logging mantém um registro dos eventos que ocorrem dentro de um programa, tornando possível ver a saída relacionada a qualquer um dos eventos que ocorrem durante a execução de um software.

Você pode estar mais familiarizado com a verificação de que eventos estão ocorrendo usando a instrução print() ao longo do seu código. A instrução print() fornece uma maneira básica de depurar seu código para resolver problemas. Embora a incorporação de instruções print() ao longo do seu código possa rastrear o fluxo de execução e o estado atual do seu programa, essa solução prova ser menos sustentável do que usar o módulo logging por algumas razões:

• Torna-se difícil distinguir entre a saída de depuração e a saída normal do programa porque as duas estão misturadas
• Ao usar instruções print() dispersas pelo código, não há uma maneira eficiente de desativar aquelas que fornecem saída de depuração
• Torna-se difícil remover todas as instruções print() quando você termina a depuração
• Não há registro de log que contenha informações de diagnóstico prontamente disponíveis

É uma boa ideia adotar o hábito de usar o módulo logging em seu código, pois isso é mais adequado para aplicativos que vão além de pequenos scripts Python e fornece uma abordagem sustentável para depuração.

Porque os registros podem mostrar seu comportamento e erros ao longo do tempo, eles também podem lhe dar uma imagem geral melhor do que está acontecendo no seu processo de desenvolvimento de aplicativos.

Imprimindo Mensagens de Depuração no Console

Se você está acostumado a usar a instrução print() para ver o que está ocorrendo em um programa, você pode estar acostumado a ver um programa que define uma classe e instanciar objetos que gera algo assim:

class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        print("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        print("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        print("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

O código acima tem um método __init__ para definir o nome e o preço de um objeto da classe Pizza. Ele então tem dois métodos, um chamado make() para fazer pizzas, e outro chamado eat() para comer pizzas. Esses dois métodos recebem o parâmetro de quantidade, que é inicializado em 1.

Agora vamos executar o programa:

python pizza.py

Receberemos a seguinte saída:

Output
Pizza created: artichoke ($15)
Made 1 artichoke pizza(s)
Ate 1 pizza(s)
Pizza created: margherita ($12)
Made 2 margherita pizza(s)
Ate 1 pizza(s)

Enquanto a instrução print() nos permite ver que o código está funcionando, podemos usar o módulo logging para fazer isso em vez disso.

Vamos remover ou comentar as instruções print() ao longo do código e adicionar import logging no topo do arquivo:

import logging


class Pizza():
    def __init__(self, name, value):
        self.name = name
        self.value = value
...

O módulo logging tem um nível padrão de WARNING, que é um nível acima de DEBUG. Como vamos usar o módulo logging para depurar neste exemplo, precisamos modificar a configuração para que o nível de logging.DEBUG retorne informações para o console. Podemos fazer isso adicionando a seguinte linha abaixo da instrução de importação:

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
...

Esse nível de logging.DEBUG se refere a um valor inteiro constante que referenciamos no código acima para definir um limite. O nível de DEBUG é 10.

Agora, vamos substituir todas as instruções print() por instruções logging.debug() em vez disso. Ao contrário de logging.DEBUG, que é uma constante, logging.debug() é um método do módulo logging. Ao trabalhar com este método, podemos usar a mesma string passada para print(), como mostrado a seguir:

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

Neste ponto, quando executamos o programa com o comando python pizza.py, receberemos esta saída:

Output
DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

As mensagens de log têm o nível de gravidade DEBUG assim como a palavra root incorporada nelas, que se refere ao nível do seu módulo Python. O módulo logging pode ser usado com uma hierarquia de registradores que têm nomes diferentes, para que você possa usar um registrador diferente para cada um dos seus módulos.

Por exemplo, você pode definir registradores iguais a diferentes registradores que têm nomes e saídas diferentes:

logger1 = logging.getLogger("module_1")
logger2 = logging.getLogger("module_2")

logger1.debug("Module 1 debugger")
logger2.debug("Module 2 debugger")

Output
DEBUG:module_1:Module 1 debugger
DEBUG:module_2:Module 2 debugger

Agora que entendemos como usar o módulo logging para imprimir mensagens no console, vamos passar a usar o módulo logging para imprimir mensagens em um arquivo.

Registro de Mensagens em um Arquivo

O propósito principal do módulo logging é registrar mensagens em um arquivo em vez de no console. Manter um arquivo de mensagens fornece dados ao longo do tempo que você pode consultar e quantificar para ver quais mudanças precisam ser feitas no seu código.

Para começar a registrar em um arquivo, podemos modificar o método logging.basicConfig() para incluir um parâmetro filename. Neste caso, vamos chamar o arquivo de test.log:

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

O código acima é o mesmo que estava na seção anterior, exceto que agora adicionamos o nome do arquivo para o registro imprimir. Depois de executar o código com o comando python pizza.py, devemos ter um novo arquivo em nosso diretório chamado test.log.

Vamos abrir o arquivo test.log com o nano (ou o editor de texto de sua escolha):

nano test.log

Ao abrir o arquivo, vamos receber o seguinte:

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

Isso é semelhante à saída do console que encontramos na seção anterior, exceto que agora está no arquivo test.log.

Vamos fechar o arquivo com CTRL + x e voltar para o arquivo pizza.py para que possamos modificar o código.

Vamos manter grande parte do código o mesmo, mas modificar os parâmetros nas duas instâncias de pizza, pizza_01 e pizza_02:

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

# Modificar os parâmetros do objeto pizza_01
pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

# Modificar os parâmetros do objeto pizza_02
pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

Com essas alterações, vamos executar o programa novamente com o comando python pizza.py.

Depois que o programa for executado, podemos abrir nosso arquivo test.log novamente com o nano:

nano test.log

Ao revisar o arquivo, veremos que várias novas linhas foram adicionadas e que as linhas anteriores da última vez que o programa foi executado foram mantidas:

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)

Embora estas informações sejam certamente úteis, podemos tornar o registro mais informativo adicionando atributos adicionais do registro de log. Principalmente, gostaríamos de adicionar um carimbo de data e hora legível que nos diga quando o registro de log foi criado.

Podemos adicionar esse atributo a um parâmetro chamado format, referenciando-o conforme mostrado na tabela com a string %(asctime)s. Além disso, para manter o nome do nível DEBUG, precisaremos incluir a string %(levelname)s e para manter a mensagem de string que pedimos ao logger para imprimir, incluiremos %(message)s. Cada um desses atributos será separado por dois pontos, conforme mostrado no código adicionado:

import logging

logging.basicConfig(
    filename="test.log",
    level=logging.DEBUG,
    format="%(asctime)s:%(levelname)s:%(message)s"
    )


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

Ao executarmos o código acima com os atributos adicionados com o comando python pizza.py, obteremos novas linhas adicionadas ao nosso arquivo test.log que incluem o carimbo de data/hora legível pelo ser humano além do nome do nível de DEBUG e as mensagens associadas que são passadas para o logger como strings.

DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: Sicilian ($18)
2021-08-19 23:31:34,484:DEBUG:Made 5 Sicilian pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 4 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: quattro formaggi ($16)
2021-08-19 23:31:34,484:DEBUG:Made 2 quattro formaggi pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 2 pizza(s)

Dependendo de suas necessidades, você pode querer fazer uso de atributos adicionais de LogRecord em seu código para tornar os logs dos arquivos do seu programa relevantes para você.

Registrar mensagens de depuração e outras mensagens em arquivos separados fornece uma compreensão holística do seu programa Python ao longo do tempo, dando a você a oportunidade de solucionar problemas e modificar seu código de uma maneira informada pelo trabalho histórico realizado no programa, bem como pelos eventos e transações que ocorrem.

Tabela de Níveis de Logging

Como desenvolvedor, você pode atribuir um nível de importância ao evento que é capturado no registro definindo um nível de severidade. Os níveis de severidade são mostrados na tabela abaixo.

Os níveis de registro são tecnicamente inteiros (uma constante), e todos eles estão em incrementos de 10, começando com NOTSET, que inicializa o registro com o valor numérico 0.

Você também pode definir seus próprios níveis relativos aos níveis predefinidos. Se você definir um nível com o mesmo valor numérico, você irá sobrescrever o nome associado a esse valor.

A tabela a seguir mostra os vários nomes de níveis, seus valores numéricos, qual função você pode usar para chamar o nível, e para que o nível é utilizado.

O módulo logging define o nível padrão como WARNING, então WARNING, ERROR e CRITICAL serão todos registrados por padrão. No exemplo acima, modificamos a configuração para incluir o nível DEBUG com o seguinte código:

logging.basicConfig(level=logging.DEBUG)

Você pode ler mais sobre os comandos e como trabalhar com o depurador na documentação oficial do logging.

Conclusão

A depuração é uma etapa importante de qualquer projeto de desenvolvimento de software. O módulo logging faz parte da biblioteca padrão do Python, fornece rastreamento de eventos que ocorrem enquanto o software é executado e pode enviar esses eventos para um arquivo de log separado para permitir que você acompanhe o que acontece enquanto seu código é executado. Isso oferece a oportunidade de depurar seu código com base na compreensão dos vários eventos que ocorrem ao executar seu programa ao longo do tempo.