Tutorial de logging em Python

Se você está começando em Python e quer aprender mais, faça o curso Introduction to Data Science in Python da DataCamp.

De forma geral, logging é uma maneira de manter um registro gerado por um programa de computador. Um arquivo de log normalmente reúne eventos que ocorrem no seu código (por exemplo, um código Python) ou no sistema operacional. Esses eventos ou mensagens são escritos em um arquivo de log; uma mensagem ou evento também pode ser uma comunicação entre usuários diferentes.

Normalmente, cabe aos desenvolvedores decidir como querem gerar logs. Talvez queiram registrar cada operação de um aplicativo que desenvolveram, logar apenas quando ocorrer um erro ou monitorar operações essenciais feitas por um usuário e registrá-las. Um exemplo de operação essencial seria verificar qual usuário final ou endereço IP acessou o aplicativo ou o servidor e, caso tenha sido uma tentativa sem sucesso, o desenvolvedor pode consultar os logs e obter mais insights do que um simples stack trace.

Um bom exemplo é quando você tenta fazer uma instalação no Linux como usuário sudo quando não tem privilégios de sudo. Você vê a mensagem "Xyz is not in the sudoers file. This incident will be reported", que é escrita em um arquivo de log.

A boa notícia é que o Python já vem com um módulo de logging integrado, pronto para uso, sem precisar de instalação.

Como o logging é diferente da função print?

O logging é parecido, em essência, com a função print. Porém, a função print não traz várias informações que podem ser úteis para quem desenvolve. Já o logging pode registrar timestamps e o número da linha em que o erro ocorreu. Ele pode enviar erros ou qualquer informação para arquivos, sockets etc., e oferece cinco níveis de severidade para você diferenciar seus logs.

Os cinco níveis de logging, como mostrado aqui, são:

• Debug (10): útil para diagnosticar problemas no código.

• Info (20): pode atuar como confirmação de que não há bugs no código. Um bom caso de uso do nível Info é acompanhar o progresso do treinamento de um modelo de machine learning.

• Warning (30): indicativo de um problema que pode ocorrer no futuro. Por exemplo, um aviso de que um módulo será descontinuado ou um alerta de pouca memória RAM.

• Error (40): um bug sério no código, como erro de sintaxe, falta de memória ou exceções.

• Critical (50): um erro devido ao qual o programa pode parar de funcionar ou encerrar abruptamente.

Chega de teoria, certo?

Agora vamos entender como implementar logging em um código Python.

Mas antes, veja a tabela de atributos de logging; você vai usar alguns dos atributos abaixo neste tutorial.

import logging

Agora, chame o método basicConfig(), que ajuda a criar uma configuração básica para o sistema de logging funcionar sem problemas.

Ele permite definir os seguintes parâmetros:

• a severidade do logging: os cinco níveis de logging.
• registrar eventos em um arquivo.
• salvar apenas os logs atuais, sobrescrevendo os antigos usando o filemode.
• o formato do arquivo em que os logs serão armazenados.

Lembre-se: o método basicConfig() é opcional e você pode optar por não usá-lo.

logging.basicConfig()

Vamos agora acionar os cinco níveis de severidade.

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

logging.warning("A Warning Logging Message")

WARNING:root:A Warning Logging Message

logging.error("An Error Logging Message")

ERROR:root:An Error Logging Message

logging.critical("A Critical Logging Message")

CRITICAL:root:A Critical Logging Message

Como dá para ver pelos outputs acima, apenas mensagens com nível de severidade maior que 20 foram registradas, pois essa é a configuração padrão do logging em Python.

No entanto, como comentado, você pode alterar os níveis de severidade usando o método basicConfig(). Aqui, vamos mudar o nível de severidade para 20, o que significa que níveis com severidade maior que 10 serão registrados.

Observação: reinicie o kernel antes de executar as células abaixo para ver o output correto.

import logging

logging.basicConfig(level=logging.INFO)

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

INFO:root:A Info Logging Message

logging.warning("A Warning Logging Message")

WARNING:root:A Warning Logging Message

logging.error("An Error Logging Message")

ERROR:root:An Error Logging Message

logging.critical("A Critical Logging Message")

CRITICAL:root:A Critical Logging Message

Agora vamos registrar os outputs acima em um arquivo de log. Para isso, você vai usar o método basicConfig().

import logging

logging.basicConfig(level = logging.INFO, filename = 'datacamp.log')

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

logging.warning("A Warning Logging Message")

logging.error("An Error Logging Message")

logging.critical("A Critical Logging Message")

Como você pode ver, agora os logs estão sendo gerados no arquivo datacamp.log. Ao executar as células acima várias vezes, você notará que os logs serão adicionados ao arquivo todas essas vezes. Por padrão, o arquivo é aberto em modo de append.

Você pode usar a palavra-chave filemode para evitar que o arquivo de log receba várias cópias dos mesmos registros (modo append). O filemode pode ser alterado para o modo write, que sobrescreve os logs anteriores e salva apenas os atuais. Como o filemode está definido como w, isso significa que o arquivo de log será aberto em modo de escrita toda vez que basicConfig() for executado, o que acabará sobrescrevendo o arquivo.

A funcionalidade de modo de arquivo no logging é semelhante ao tratamento de arquivos padrão oferecido pelo Python.

import logging

logging.basicConfig(level = logging.INFO, filename = 'datacamp.log', filemode = 'w')

logging.debug("A Debug Logging Message")
logging.info("A Info Logging Message")
logging.warning("A Warning Logging Message")
logging.error("An Error Logging Message")
logging.critical("A Critical Logging Message")

Vamos executar as linhas acima várias vezes. Você vai notar que, desta vez, apenas as entradas de log atuais serão salvas e as anteriores serão sobrescritas, como mostrado abaixo.

Vamos ver mais alguns atributos de logging, como data, hora e número da linha em que o aviso ou erro foi gerado. Como você já deve concordar, tudo isso é vantagem em relação a um simples print e é muito mais poderoso do que uma saída com print.

Para fazer isso, você vai passar os atributos de logging asctime e lineno. Também vai passar o atributo message, que será um placeholder para a mensagem que você quer exibir nos logs. Todos esses atributos serão passados para o parâmetro format.

import logging

logging.basicConfig(format='Date-Time : %(asctime)s : Line No. : %(lineno)d - %(message)s', \
                    level = logging.DEBUG)

logging.debug("A Debug Logging Message")
logging.info("A Info Logging Message")
logging.warning("A Warning Logging Message")
logging.error("An Error Logging Message")
logging.critical("A Critical Logging Message")

Date-Time : 2020-03-18 23:58:12,429 : Line No. : 1 - A Debug Logging Message
Date-Time : 2020-03-18 23:58:12,436 : Line No. : 2 - A Info Logging Message
Date-Time : 2020-03-18 23:58:12,437 : Line No. : 3 - A Warning Logging Message
Date-Time : 2020-03-18 23:58:12,440 : Line No. : 4 - An Error Logging Message
Date-Time : 2020-03-18 23:58:12,441 : Line No. : 5 - A Critical Logging Message

Vamos às definições de cada atributo diretamente desta tabela.

• asctime: horário legível por humanos quando o LogRecord foi gerado. Por padrão, tem o formato 2020-03-18 22:24:42,670 (os números após a vírgula são os milissegundos). Como esse atributo é uma string, você usa o especificador s depois dele.

• lineno: número da linha de origem onde a chamada de logging ocorreu. Como esse atributo é um inteiro, você usa o especificador d depois dele.

• message: a mensagem registrada, computada como msg % args. Isso é definido quando Formatter.format() é chamada. Se você não especificar esse atributo ao usar o parâmetro format(), as mensagens que deseja registrar não serão geradas. Da mesma forma, para o atributo message, você usa s por ser uma string.

• funcName: exibe o nome do módulo ou da função em que o log foi gerado. É útil quando você tem muitas funções no código e quer separar os logs com base na função ou no método a que pertencem.

Vamos a um exemplo simples para ver como substituir o print por logging no nível debug.

import logging

logging.basicConfig(format='%(asctime)s :: %(levelname)s :: %(funcName)s :: %(lineno)d \
:: %(message)s', level = logging.INFO)

def addition(x, y):
    add = x + y
    return add


def subtract(x, y):
    sub = x - y
    return sub


def multiply(x, y):
    mul = x * y
    return mul


def divide(x, y):
    div = x / y
    return div

def exponent(x, y):
    exp = x ** y
    return exp


num1 = 20
num2 = 2

def main():
    add_result = addition(num1, num2)
    logging.info('Add: {} + {} = {}'.format(num1, num2, add_result))

    sub_result = subtract(num1, num2)
    logging.info('Sub: {} - {} = {}'.format(num1, num2, sub_result))

    mul_result = multiply(num1, num2)
    logging.info('Mul: {} * {} = {}'.format(num1, num2, mul_result))

    div_result = divide(num1, num2)
    logging.info('Div: {} / {} = {}'.format(num1, num2, div_result))

    exp_result = exponent(num1, num2)
    logging.info('Exp: {} ** {} = {}'.format(num1, num2, exp_result))


main()

2020-03-19 00:01:27,372 :: INFO :: main :: 35 :: Add: 20 + 2 = 22
2020-03-19 00:01:27,376 :: INFO :: main :: 38 :: Sub: 20 - 2 = 18
2020-03-19 00:01:27,377 :: INFO :: main :: 41 :: Mul: 20 * 2 = 40
2020-03-19 00:01:27,378 :: INFO :: main :: 44 :: Div: 20 / 2 = 10.0
2020-03-19 00:01:27,379 :: INFO :: main :: 47 :: Exp: 20 ** 2 = 400

Conclusão

Parabéns por concluir o tutorial.

Vale a pena testar outros atributos de logging e entender como aproveitá-los no seu código.

Fique à vontade para deixar suas dúvidas sobre este tutorial nos comentários abaixo.

Se você está começando em Python e quer aprender mais, faça o curso Introduction to Data Science in Python da DataCamp.