Использование модуля logging в Python 3

Модуль logging является частью стандартной библиотеки Python. Он отслеживает события, которые происходят во время запуска программ. Вы можете добавить вызов модуля logging в код программы, чтоб узнать, что происходит на том или ином этапе.

Модуль logging поддерживает логи диагностики, которые регистрируют события, связанные с работой приложения, и логи аудита, в которых для дальнейшего анализа хранятся события транзакций пользователя. Он также используется для записи событий в файл.

Краткий обзор модуля logging

Модуль logging регистрирует происходящие в программе события, что позволяет увидеть результат любого события.

Очень часто с этой же целью в программах используется оператор print() – это, по сути, базовый способ обнаружения и устранения неполадок. Хотя оператор print() может отслеживать поток выполнения кода и текущее состояние программы, это решение оказывается менее удобным, чем использование модуля logging по нескольким причинам:

• Сложно отличить вывод для отладки от обычного вывода программы, потому что они не отделяются друг от друга.
• Используя print() по всему коду программы, вы не можете просто отключить те операторы, которые предназначены для отладки.
• Завершив отладку программы, удалить операторы print() довольно сложно.
• Оператор print() не предоставляет логов, в которых можно было бы найти полезные для диагностики данные.

Модуль logging больше подходит для отладки сложных приложений, которые выходят за рамки простых сценариев Python.

В логах регистрируется поведение и ошибки программы, потому они предоставляют более полную картину того, что происходит в процессе разработки приложения.

Вывод отладочных сообщений в консоль

Если вы привыкли использовать print() для отслеживания работы программы, скорее всего, вы часто работаете с кодом, который определяет класс и создает объекты. Для примера рассмотрим программу pizza.py:

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()

В коде используется метод __init__, который определяет параметры name и price объекта, созданного из класса Pizza. Далее следуют методы make() и eat(), которые используют параметр quantity с исходным значением 1.

Запустите программу pizza.py.

python pizza.py
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)

Оператор print() позволяет понять, что код работает. Теперь попробуйте заменить его модулем logging.

Удалите или закомментируйте все операторы print() и импортируйте модуль в начало файла с помощью строки import logging:

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

Модуль logging позволяет выбрать уровень важности (подробнее этот вопрос будет описан далее). По умолчанию используется уровень WARNING, который выше чем DEBUG. Чтобы использовать модуль logging для отладки, нужно изменить стандартный уровень важности на logging.DEBUG, и тогда модуль будет выводить информацию в консоль. Для этого просто добавьте следующую строку после оператора import:

import logging
logging.basicConfig(level=logging.DEBUG)
class Pizza():
...

Уровень logging.DEBUG позволяет задать пороговое значение (в данном случае это 10).

Теперь замените все операторы print() операторами logging.debug(). Разница между logging.DEBUG и logging.debug() в том, что первый является константой, а второй – методом модуля logging. С помощью этого метода можно использовать ту же строку, что и с оператором print(), например:

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()

Снова запустите программу с помощью python pizza.py. Вы получите такой вывод:

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, которое ссылается на уровень модуля Python. Модуль logging позволяет создавать иерархии логеров с разными именами, благодаря чему можно использовать разные логеры с разными модулями.

К примеру, вы можете создать несколько логеров одного прядка с разными именами и разным выводом:

logger1 = logging.getLogger("module_1")
logger2 = logging.getLogger("module_2")
logger1.debug("Module 1 debugger")
logger2.debug("Module 2 debugger")
DEBUG:module_1:Module 1 debugger
DEBUG:module_2:Module 2 debugger

Теперь вы знаете, как использовать модуль logging для вывода сообщений в консоль. Попробуйте вывести сообщение в файл.

Вывод отладочных сообщений в файл

Основная цель модуля logging – записывать сообщения в файл, а не в консоль. Такой файл может хранить данные некоторое время, в дальнейшем он может помочь вам определить, какие изменения необходимо внести в код программы.

Чтобы модуль выводил сообщения в файл, откорректируйте метод logging.basicConfig() и добавьте в него параметр filename (в этом примере файл будет называться 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()

Вышеприведенный код ничем, кроме параметра filename, от предыдущего примера не отличается. Однако теперь модуль знает, в каком файле следует хранить сообщения. Запустите программу, после чего в каталоге должен появиться файл test.log.

Откройте этот файл:

nano test.log

Он будет содержать следующее:

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)

Этот же вывод в предыдущем разделе вы видели в консоли.

Закройте файл (CTRL + x), а затем откройте файл pizza.py.

Откорректируйте параметры объектов pizza_01 и 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))
# Параметры объекта pizza_01
pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)
# Параметры объекта pizza_02
pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

Запустите программу. Затем откройте файл test.log.

nano test.log

В файле появились новые строки.

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)

Данные, хранящиеся в логе, очень полезны, но вы можете сделать лог более информативным, добавив атрибуты LogRecord. В первую очередь нужно добавить удобочитаемую метку времени создания записи.

Добавьте атрибут в параметр format (строка %(asctime)s). Также нужно указать уровень DEBUG (строка %(levelname)s) и настроить хранение сообщений (%(message)s). Параметры разделяются двоеточием.

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)

Запустите программу с новыми атрибутами. Проверьте файл test.log. В нём появится метка времени и сообщения.

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)
2017-05-01 16:28:54,593:DEBUG:Pizza created: Sicilian ($18)
2017-05-01 16:28:54,593:DEBUG:Made 5 Sicilian pizza(s)
2017-05-01 16:28:54,593:DEBUG:Ate 4 pizza(s)
2017-05-01 16:28:54,593:DEBUG:Pizza created: quattro formaggi ($16)
2017-05-01 16:28:54,593:DEBUG:Made 2 quattro formaggi pizza(s)
2017-05-01 16:28:54,593:DEBUG:Ate 2 pizza(s)

По мере необходимости можно добавить в код другие атрибуты LogRecord.

Собирая сообщения отладки в специальный файл, вы сможете получить целостное понимание работы программы, своевременно устранять ошибки и вносить поправки.

Уровни важности

Вы можете присваивать событиям уровни важности.

Технически уровни важности выражаются целыми числами (константами) с шагом в 10. Отсчёт начинается с уровня NOTSET, который имеет значение 0.

Также вы можете определять свои собственные уровни. Если вы присвоите новому уровню числовое значение, которое уже занято другим уровнем, вы переопределите название этого уровня.

В этой таблице вы найдёте названия уровней, их числовые значения и функции.

Уровень	Числовое значение	Функция	Действие
CRITICAL	50	logging.critical()	Критическая ошибка; программа не может продолжать работу
ERROR	40	logging.error()	Серьёзная ошибка или сбой.
WARNING	30	logging.warning()	Произошло (или может произойти) что-то непредвиденное.
INFO	20	logging.info()	Программа работает должным образом
DEBUG	10	logging.debug()	Диагностика ошибок (сбор подробных данных).

Модуль logging использует WARNING в качестве уровня по умолчанию, потому WARNING, ERROR и CRITICAL будут по умолчанию регистрироваться логами. Ранее вы уже настраивали уровень важности DEBUG с помощью кода:

logging.basicConfig(level=logging.DEBUG)

Читайте также: Документация модуля logging

Заключение

Отладка – очень важный этап разработки программы. Модуль logging позволяет обнаружить слабые места программы и усовершенствовать код.