Como Usar Log no 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 de diagnóstico que registra eventos relacionados à operação de uma aplicação, quanto o logging de auditoria que registra os eventos de 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 no 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 no seu servidor apropriado para o 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() em todo o 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() em todo o seu código possa rastrear o fluxo de execução e o estado atual do seu programa, essa solução se mostra menos sustentável do que usar o módulo logging por alguns motivos:

• 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ê terminar de depurar
• Não há registro de log que contenha informações de diagnóstico prontamente disponíveis

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

Porque os registros podem mostrar o comportamento e os erros ao longo do tempo, eles também podem fornecer uma imagem geral melhor do que está acontecendo no processo de desenvolvimento da sua aplicação.

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 instancia objetos que geram 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. Em seguida, 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 quantity, 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() em todo o 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 possui um nível padrão de WARNING, que é um nível acima de DEBUG. Como vamos usar o módulo logging para depuração neste exemplo, precisamos modificar a configuração para que o nível logging.DEBUG retorne informações para o console. Podemos fazer isso adicionando a seguinte linha abaixo da declaração de importação:

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
...

Este nível de logging.DEBUG refere-se 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, bem 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 de 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.

Registrando Mensagens em um Arquivo

O objetivo 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 alterações 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 log ser impresso. Depois de executar o código com o comando python pizza.py, deveríamos 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 mudanças, vamos executar o programa novamente com o comando python pizza.py.

Depois que o programa terminar de rodar, 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 essas informações sejam úteis, podemos tornar o log mais informativo adicionando atributos adicionais do LogRecord. Principalmente, gostaríamos de adicionar um carimbo de data e hora legível por humanos que nos diga quando o LogRecord foi criado.

Podemos adicionar esse atributo a um parâmetro chamado format, fazendo referência a ele 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 que pedimos ao registrador 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 e hora legível pelo humano, além do nome do nível de DEBUG e as mensagens associadas que são passadas para o registrador 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 de registro de log adicionais em seu código para tornar os logs de seus arquivos de programa relevantes para você.

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

Tabela de Níveis de Registro

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

Os níveis de registro são tecnicamente inteiros (uma constante) e todos 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, irá sobrescrever o nome associado a esse valor.

A tabela a seguir mostra os vários nomes de níveis, seu valor numérico, qual função você pode usar para chamar o nível e para que esse nível é usado.

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 trabalhar com o depurador na documentação oficial do logging.

Conclusão

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 durante a execução do software 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 lhe dá a oportunidade de depurar seu código com base no entendimento dos vários eventos que ocorrem ao executar seu programa ao longo do tempo.