Введение в logging на Python
В стандартной библиотеке Python есть замечательный пакет для логирования — logging. В сети бытует мнение, что он сложный и настраивать его сплошная боль. В этой статье я попробую убедить вас в обратном. Мы разберём что из себя представляет этот пакет, изучим основные компоненты и закрепим материал практическим примером.
Зачем нужны логи?
Логи это рентген снимок выполнения вашей программы. Чем детальнее лог, тем проще разобраться в нестандартных ситуациях, которые могут приключиться с вашим скриптом. Наиболее популярным примером логов служат access логи веб-сервера, например, Apache httpd или nginx. Пример куска access лога моего блога:
92.63.107.227 - - [04/Nov/2020:06:30:48 +0000] "GET /ru/hosted-open-vpn-server/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-"
92.63.107.227 - - [04/Nov/2020:06:30:49 +0000] "GET /ru/data-engineering-course/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-"
213.180.203.50 - - [04/Nov/2020:06:36:07 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; YandexMetrika/2.0; +http://yandex.com/bots yabs01)" "-"
114.119.160.75 - - [04/Nov/2020:06:36:41 +0000] "GET /robots.txt HTTP/1.1" 301 169 "-" "(compatible;PetalBot;+https://aspiegel.com/petalbot)" "10.179.80.67"
90.180.35.207 - - [04/Nov/2020:06:47:11 +0000] "GET / HTTP/1.0" 301 169 "-" "-" "-"
46.246.122.77 - - [04/Nov/2020:06:53:22 +0000] "GET / HTTP/1.1" 301 169 "<http://khashtamov.com>" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36" "-"
66.249.76.16 - - [04/Nov/2020:06:53:30 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-"
66.102.9.118 - - [04/Nov/2020:07:11:19 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 Google Favicon" "46.159.204.234"
71.6.167.142 - - [04/Nov/2020:07:11:55 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36" "-"Помимо access логов веб-сервер также пишет error лог, там хранится информация обо всех ошибках при обработке HTTP запросов. Также и в ваших скриптах, логи могут делиться на информационные — вывод текущего состояния выполнения, отладочной информации, и на логи с ошибками — вывод исключений, ошибок с дополнительной информацией для отладки, содержащей контекст).
logging и Python
Точкой входа в работу с логированием в Python является библиотека logging. На первый взгляд может показаться, что библиотека сложная и запутанная, но потратив некоторое время на её изучение, можно убедиться в обратном. Для меня logging это классический пример дизайна ООП, где композиция преобладает над наследованием, поэтому в исходном коде библиотеки можно встретить множество функциональных классов. Цель этого туториала разобрать по косточкам каждый класс и воссоединить их в единый механизм логирования в Python. Начнём-с.
Logger
Чтобы начать работу с logging необходимо в импортировать библиотеку logging и вызвать функцию getLogger, передав ей имя будущего логера. Функция вернёт инстанс объекта Logger. Логер это рычаг за который мы дёргаем каждый раз, когда нам нужно записать информацию в лог.
import logging
logger = logging.getLogger('logger')
Заметьте, что функция getLogger принимает на вход параметр — имя логера. Можно назначать любое имя или __name__. Вызов getLogger с одинаковым названием вернёт один и тот же инстанс логера.
Я рекомендую использовать в качестве аргумента __name__, в этом случае не нужно беспокоиться, что разные модули могут ссылаться на один и тот же логер.
Класс Logger предоставляет наружу несколько методов для записи сообщений разного уровня. Уровни необходимы для понимания контекста сообщения/лога, который мы пишем. В logging существует несколько уровней:
- DEBUG — уровень отладочной информации, зачастую помогает при разработке приложения на машине программиста.
- INFO — уровень вспомогательной информации о ходе работы приложения/скрипта.
- WARNING — уровень предупреждения. Например, мы можем предупреждать о том, что та или иная функция будет удалена в будущих версиях вашего приложения.
- ERROR — с таким уровнем разработчики пишут логи с ошибками, например, о том, что внешний сервис недоступен.
- CRITICAL — уровень сообщений после которых работа приложения продолжаться не может.
По умолчанию в logging задан уровень WARNING, это означает, что сообщения уровня DEBUG и INFOбудут игнорироваться при записи в лог. Разработчик может самостоятельно задать необходимый ему уровень логирования через метод setLevel у инстанса Logger:
logger.setLevel(logging.DEBUG)
Методы для записи сообщений с разными уровнями именуются по тому же принципу:
logger.debug('debug info')
logger.info('info')
logger.warning('warning')
logger.error('debug info')
logger.critical('debug info')
Также есть ещё один метод — exception. Его желательно вызывать в блоке except при обработке исключения. В это случае он сможет уловить контекст исключения и записать его в лог:
try:
1/0
except :
logger.exception('exception')Handler
Задача класса Handler и его потомков обрабатывать запись сообщений/логов. Т.е. Handler отвечает за то куда будут записаны сообщения. В базовом наборе logging предоставляет ряд готовых классов-обработчиков:
- SteamHandler — запись в поток, например, stdout или stderr.
- FileHandler — запись в файл, класс имеет множество производных классов с различной функциональностью (ротация файлов логов по размеру, времени и т.д.)
- SocketHandler — запись сообщений в сокет по TCP
- DatagramHandler — запись сообщений в сокет по UDP
- SysLogHandler — запись в syslog
- HTTPHandler — запись по HTTP
Это далеко не полный список. Чтобы посмотреть все, перейдите по ссылке выше. Для указания Handler, необходимо у инстанса Logger вызвать метод addHandler и передать туда инстанс класса Handler. У одного Logger инстанса может быть множество обработчиков.
Пример записи лога в stdout:
import sys
import logging
from logging import StreamHandler
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
logger.addHandler(handler)
logger.debug('debug information')
Если запустить этот скрипт, то можно увидеть сообщение:
debug information
Мы видим сообщение уровня DEBUG потому что задачи этот уровень в настройках. Если поменять его на INFO, то сообщение пропадёт:
logger.setLevel(logging.INFO)
Наверняка вы обратили внимание, что лог содержит всего лишь переданную строку. Как сделать так, чтобы в логе была информация об уровне лога, времени записи?
Formatter
Formatter это ёщё один класс в семействе logging, отвечающий за отображение лога. Если класс Handler ответственный за то куда будет происходить запись, то класс Formatter отвечает на вопрос как будет записано сообщение. По умолчанию в лог пишется голая строка, которую мы передаём через методы debug, info и т.д. Давайте обогатим наш лог дополнительной метаинформация, например, о времени записи и уровне сообщения. Formatter передаётся инстансу Handler через метод .setFormatter
import sys
import logging
from logging import StreamHandler, Formatter
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
logger.addHandler(handler)
logger.debug('debug information')
Запуск скрипта выведет на экран следующее сообщение:
[2020-11-22 13:00:08,751: DEBUG] debug information
Обратите внимание на строку, которую я передал при инициализации инстанса Formatter:
[%(asctime)s: %(levelname)s] %(message)s
Это шаблон, который будет заполнен при записи сообщения в лог. Набор таких готовых шаблонов можно посмотреть в разделе LogRecord attributes.
Filter
Задача класса фильтровать сообщения по заданной разработчиком логике. Предположим, что я хочу записывать в лог сообщения, содержащие слово python. Чтобы задать фильтр необходимо вызвать метод addFilter у инстанса Logger. Передать можно либо инстанс класса, реализующий метод filter либо callable объект (например, функцию). На вход прилетит инстанс класса LogRecord, это и есть 1 сообщение лога:
import sys
import logging
from logging import StreamHandler, Formatter, LogRecord
def filter_python(record: LogRecord) -> bool:
return record.getMessage().find('python') != -1
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
logger.addHandler(handler)
logger.addFilter(filter_python)
logger.debug('python debug information')
Наглядно и понятно, разве logging может быть сложным? 😎
LoggerAdapter
Адаптер нужен для передачи дополнительной контекстной информации при каждой записи лога через Logger. Например, вы написали веб-приложение и вам необходимо в логи дополнительно передавать username пользователя:
class CustomLoggerAdapter(LoggerAdapter):
def process(self, msg, kwargs):
return f'{msg} from {self.extra["username"]}', kwargs
logger2 = logging.getLogger('adapter')
logger2.setLevel(logging.DEBUG)
handler = StreamHandler(stream=sys.stdout)
handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s'))
adapter = CustomLoggerAdapter(logger2, {'username': 'adilkhash'})
logger2.addHandler(handler)
adapter.error('failed to save')
extra и не только
Строки в логах это хорошо, а что если я хочу помимо строки дополнительно передавать ответ от веб-сервера? Для этого можно использовать аргумент extra при вызове методов debug, info и т.д. Давайте напишем пример вывода
logger.debug('debug info', extra={"response": response.text})Теперь вывод значения ключа response можно указать через Formatter (при условии, что response передаётся всегда):
Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s, response: %(response)s')
Аргумент extra удобен при написании своих кастомных обработчиков логов (например, отсылка логов в телеграм). Далее я покажу пример кастомного Handler класса для отправки логов в Telegram через бота.
Конфигурация logging
Официальная документация рекомендует конфигурировать logging через python-словарь. Для этого необходимо вызвать функцию logging.config.dictConfig и передать ей специальный словарь. Схема словаря описана здесь. Я лишь вкратце пробегусь по основным ключам:
- version — ключ указывает версию конфига, рекомендуется наличие этого ключа со значением 1, нужно для обратной совместимости в случае, если в будущем появятся новые версии конфигов.
- disable_existing_loggers — запрещает или разрешает настройки для существующих логеров (на момент запуска), по умолчанию равен True
- formatters — настройки форматов логов
- handlers — настройки для обработчиков логов
- loggers — настройки существующих логеров
Ранее все настройки я задавал кодом через вызов методов. Это может быть удобно, если у вас 1 модуль, но когда таких модулей становится множество, то в каждом из них задавать общие настройки кажется излишним занятием. Давайте попробуем все настройки задать в одном месте:
import logging.config
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'default_formatter': {
'format': '[%(levelname)s:%(asctime)s] %(message)s'
},
},
'handlers': {
'stream_handler': {
'class': 'logging.StreamHandler',
'formatter': 'default_formatter',
},
},
'loggers': {
'my_logger': {
'handlers': ['stream_handler'],
'level': 'DEBUG',
'propagate': True
}
}
}
logging.config.dictConfig(LOGGING_CONFIG)
logger = logging.getLogger('my_logger')
logger.debug('debug log')
Неправда ли удобно? В реальных приложениях настройки выносят в отдельный модуль, который обязательно импортируется на старте, например, модуль в settings.py как в Django. Именно в нём задаются глобальные настройки для всех логеров приложения.
Наследование в logging
Ещё одним удобным механизмом в logging является "наследование" настроек корневого логера его потомками. Наследование задаётся через символ . в названии логера. То есть логер с названием my_package.logger1 унаследует все настройки, заданные для my_package. Давайте обновим пример выше, добавив в LOGGING_CONFIG настройку для my_package
LOGGING_CONFIG['loggers'].update({
'my_package': {
'handlers': ['stream_handler'],
'level': 'DEBUG',
'propagate': False
}
})
Если у вас есть настройка для конкретного логера и вы не хотите, чтобы он был дополнительно обработан родительскими Handler классами, то ключу propagate нужно присвоить значение False. В этом случае передача управления "вверх" до родителя будет запрещена.
Отправляем логи в Telegram
А теперь давайте напишем свой кастомный Handler для отправки логов через бота в телеграм. Если вы никогда не работали с телеграм-ботами, то почитайте мою статью про создание телеграм-ботов. Я предполагаю, что вы уже создали бота, получили его токен и знаете свой user-id/chat-id, чтобы бот смог посылать сообщения лично вам. Для работы с телеграмом я использую библиотеку pyTelegramBotAPI.
Чтобы создать свой обработчик, необходимо наследоваться от класса Handler и перезаписать метод emit:
import telebot
from logging import Handler, LogRecord
class TelegramBotHandler(Handler):
def __init__(self, token: str, chat_id: str):
super().__init__()
self.token = token
self.chat_id = chat_id
def emit(self, record: LogRecord):
bot = telebot.TeleBot(self.token)
bot.send_message(
self.chat_id,
self.format(record)
)
При инициализации инстанса класса TelegramBotHandler ему необходимо будет передать токен бота и chat_id. Замечу, что эти настройки можно задать через конфигурирование:
'handlers': {
'telegram_handler': {
'class': 'handlers.TelegramBotHandler',
'chat_id': '<CHAT_ID>',
'token': '<BOT_TOKEN>',
'formatter': 'default_formatter',
}
},
Чтобы обработчик начал свою работу, достаточно в настройках вашего логера прописать новый обработчик:
LOGGING_CONFIG['loggers'].update({
'my_package': {
'handlers': ['stream_handler', 'telegram_handler'],
'level': 'DEBUG',
'propagate': False
}
})Всё готово! 😎
Заключение
В этой статье я постарался вкратце рассказать и показать основные сущности библиотеки logging, а также продемонстрировать гибкий механизм логирования в python. Надеюсь мне это удалось, и статья оказалась для вас полезной.