Введение в 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 существует несколько уровней:

  1. DEBUG — уровень отладочной информации, зачастую помогает при разработке приложения на машине программиста.
  2. INFO — уровень вспомогательной информации о ходе работы приложения/скрипта.
  3. WARNING — уровень предупреждения. Например, мы можем предупреждать о том, что та или иная функция будет удалена в будущих версиях вашего приложения.
  4. ERROR — с таким уровнем разработчики пишут логи с ошибками, например, о том, что внешний сервис недоступен.
  5. 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. Надеюсь мне это удалось, и статья оказалась для вас полезной.

Также я веду телеграм-канал @devbrain. Подписывайтесь, чтобы не пропустить всё самое интересное 😎