Логирование

Теория

Сервер работает без экрана: когда что-то пошло не так в три часа ночи, единственный способ понять, что случилось, — журнал событий. print для этого не годится: у него нет уровней важности (не отличить «заказ оформлен» от «платёжка упала»), его нельзя отключить для части кода или направить в файл, не переписав весь код, в нём нет времени и источника. Модуль logging решает это: код пишет сообщения с уровнем, а куда и что из них попадёт, настраивается в одном месте.

Уровни по возрастанию важности: DEBUG — подробности для отладки, INFO — обычные события («заказ 1042 оформлен»), WARNING — что-то подозрительное, но работаем дальше, ERROR — операция не удалась, CRITICAL — всё плохо. По умолчанию показываются только WARNING и выше — поэтому info «молчит», пока его не включили. Настраивают логирование один раз при старте программы (logging.basicConfig), а в каждом модуле берут свой именованный логгер — logging.getLogger(__name__): по имени в журнале видно, откуда сообщение, и уровни можно настраивать для отдельных частей приложения. В Django то же самое настраивается словарём LOGGING в settings.py.

Наглядно

Таблица 1. Уровни логирования.

Таблица 2. print и logging.

На практике

Задача: вести журнал оформления заказов и импорта товаров — с уровнями, источником и traceback при ошибках.

Шаг 1. Видим уровень по умолчанию

Без настройки показываются только предупреждения и ошибки, а info молчит:

import logging

logging.warning("остаток мыши: %s шт.", 2)
logging.info("заказ 1042 оформлен")

Результат:

WARNING:root:остаток мыши: 2 шт.

root — имя корневого логгера. Значения подставляются через %s и аргументы, а не f-строкой: строка собирается, только если сообщение действительно попадёт в журнал.

Шаг 2. Настраиваем журнал один раз — в начале

basicConfig задаёт уровень и формат. Но первый вызов logging.warning в шаге 1 уже настроил журнал «по умолчанию», и обычный повторный вызов ничего не меняет:

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s")
logging.info("заказ 1043 оформлен")

Ничего не вывелось. Поэтому basicConfig вызывают первой строкой программы, до любых сообщений. Здесь программа уже «запущена», и мы перенастраиваем журнал принудительно — force=True:

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s", force=True)
logging.info("заказ 1043 оформлен")

Результат:

INFO root: заказ 1043 оформлен

Шаг 3. Берём логгер модуля

В каждом модуле — свой логгер. Его имя попадает в журнал, и сразу видно, откуда сообщение. В модуле обычно пишут logging.getLogger(__name__), здесь имя задано явно:

orders_log = logging.getLogger("shop.orders")
payments_log = logging.getLogger("shop.payments")

orders_log.info("заказ %s оформлен на %s ₽", 1044, 1989)
payments_log.warning("оплата заказа %s: повторная попытка", 1044)

Результат:

INFO shop.orders: заказ 1044 оформлен на 1989 ₽
WARNING shop.payments: оплата заказа 1044: повторная попытка

Шаг 4. Настраиваем уровень части приложения

Платёжный модуль слишком подробен — для него оставляем только ошибки, остальные модули не трогаем:

payments_log.setLevel(logging.ERROR)
payments_log.info("запрос к платёжке отправлен")
payments_log.error("оплата заказа %s отклонена", 1045)
orders_log.info("заказ %s оформлен", 1046)

Результат:

ERROR shop.payments: оплата заказа 1045 отклонена
INFO shop.orders: заказ 1046 оформлен

Шаг 5. Записываем ошибку с traceback

В except вместо error пишут exception: он добавляет в журнал traceback пойманной ошибки, а программа продолжает работу:

import_log = logging.getLogger("shop.import")
try:
    qty = int("три")
except ValueError:
    import_log.exception("не удалось разобрать количество")
import_log.info("импорт продолжается")

Результат:

ERROR shop.import: не удалось разобрать количество
Traceback (most recent call last):
  File "main.py", line 3, in <module>
    qty = int("три")
          ^^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'три'
INFO shop.import: импорт продолжается

С import_log.error(...) в журнале было бы только «не удалось разобрать количество» — без указания, где и почему.

Частые ошибки

• info не виден. Уровень по умолчанию — WARNING. Включите нужный уровень: basicConfig(level=logging.INFO).
• basicConfig не в начале. Если до него уже было любое сообщение logging.warning(...), журнал настроился сам, и basicConfig без force=True ничего не делает. Настройку — первой строкой программы.
• error вместо exception в except. Теряется traceback — в журнале видно «что-то не удалось», но не где и почему.
• f-строка в сообщении. logger.debug(f"... {big_object}") собирает строку, даже если DEBUG выключен. Передавайте значения аргументами: logger.debug("... %s", big_object).
• print в серверном коде. Нет уровней и источника, нельзя настроить — для журнала только logging.

Итог

Уровни

• DEBUG < INFO < WARNING < ERROR < CRITICAL; по умолчанию видно WARNING и выше.

Настройка

• logging.basicConfig(level=..., format=...) — один раз, первой строкой программы.
• В формате: %(levelname)s, %(name)s, %(message)s, %(asctime)s (время).
• В Django — словарь LOGGING в настройках.

Использование

• В модуле: logger = logging.getLogger(__name__); уровень можно задать отдельно: logger.setLevel(...).
• Значения — аргументами: logger.info("заказ %s", order_id).
• В except — logger.exception(...): сообщение + traceback.

Вопросы на собеседовании