Основы работы библиотеки Python Logging

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

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

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

Обратите внимание, что фрагменты кода в статье предполагают, что вы уже импортировали модуль logging:

import logging

Концепции Python Logging

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

Уровни Python Logging

Уровень лога соответствует его важности: лог ERROR важнее, чем WARNING. Тогда как лог DEBUG следует использовать только при отладке приложения.
Python предлагает шесть уровней лога; каждый уровень связан с числом, которое указывает на важность лога: NOTSET=0, DEBUG=10, INFO=20, WARNING=30, ERROR=40 и CRITICAL=50.
Иерархия уровней интуитивно понятна: DEBUG < INFO < WARNING. Кроме NOTSET, со спецификой которого, ознакомимся позднее.

Форматирование лога в Python

Форматирование лога дополняет сообщение, добавляя к нему контекстную информацию. Полезно знать, когда отправляется лог, где (файл Python, номер строки, метод и т. д.), а так же дополнительный контекст, такой как поток и процесс. Чрезвычайно полезные данные при отладке многопоточного приложения.

"%(time)s — %(log_name)s — %(level)s — %(func_name)s:%(line_no)d — %(message)s"

Он превращается в:

2019-01-16 10:35:12,468 - keyboards - ERROR - <module>:1 - привет мир

Обработчик ведения лога в Python

Обработчик лога — компонент, который записывает и отображает данные лога. Он отображает лог в консоли (через StreamHandler), в файле (через FileHandler), с помощью отправки электронного письма (через SMTPHandler) и других методов.
В каждом обработчике лога 2 важных поля:

  • Форматировщик, который добавляет контекстную информацию в лог.
  • Уровень важности лога, который отфильтровывает логи, уровни которых ниже. Поэтому обработчик лога с уровнем INFO не будет обрабатывать логи DEBUG.

Стандартная библиотека содержит несколько обработчиков, которых достаточно для большинства случаев: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Наиболее распространенные — StreamHandler и FileHandler:

console_handler = logging.StreamHandler()
file_handler = logging.FileHandler("MyLogFile.txt")

Python Logger

Логгер будет использоваться чаще всего в коде и будет самым сложным. Новый Logger получим следующим образом:

toto_logger = logging.getLogger("Privacy")

У логгера три основных поля:

  • Propagate: определяет, должен ли лог распространяться на родителя журнала. По умолчанию равен True.
  • Level: как и уровень обработчика лога, уровень логгера используется для фильтрации “менее важных” логов. Кроме того, в отличие от обработчика лога, уровень проверяется только на “детях” логгера; и после того, как лог распространился среди его родителей, уровень не будет проверятся. Это скорее не интуитивное поведение.
  • Handlers: список обработчиков, на которые отправит лог, когда поступит в логгер. Это делает обработку логов гибкой, например, вы создадите обработчик лога для записи в файл, который регистрирует логи DEBUG и обработчик лога для отправки электронной почты, который будет использоваться только для логов CRITICAL. Таким образом, отношение обработчика-логгера становится похожим на издатель-потребитель: где лог будет передаваться всем обработчикам после проверки уровня лога.

Logger определяется по имени, это означает, что если создан лог с именем foo, последующие вызовы logging.getLogger (" foo") будут возвращать один и тот же объект:

assert id(logging.getLogger("foo")) == id(logging.getLogger("foo"))

Как вы могли догадаться, у логгеров есть иерархия. В верхней части иерархии корневой лог, к которому можно получить доступ через logging.root. Этот лог вызывается, когда используются такие методы, как logging.debug(). По умолчанию, уровень корневого лога — WARNING, поэтому каждый лог с уровнем ниже игнорируется (например, через logging.info("info")).
Другая особенность корневого логгера заключается в том, что его обработчик, по умолчанию, создается при первом входе в лог с уровнем, выше WARNING.
Использование корневого логгера с помощью таких методов, как logging.debug(), не рекомендуется

lab = logging.getLogger("f.r")
assert lab.parent == logging.root # lab.parent действительно корневой логгер

Тем не менее логгер использует “точечную запись”, значит логгер с именем f.r будет потомком логгерра f. Однако это справедливо только в том случае, когда создан лог f, иначе родитель fr по прежнему будет корнем.

la = logging.getLogger("f")
assert lab.parent == la # родитель lab теперь la вместо корня

Эффективный уровень логгера

Когда логгер решает, должен ли лог выводится в соответствии с уровнем важности (например, если уровень лога ниже уровня логгера, сообщение будет проигнорировано), он использует свой “эффективный уровень” вместо фактического уровня.
Эффективный уровень совпадает с уровнем логгера, если уровень не равен NOTSET. Однако, если уровень логгера равен NOTSET, эффективным уровнем будет первый уровень родителя, у которого уровень не NOTSET.
По умолчанию, новый логгер имеет уровень NOTSET. Поскольку корневой логгер с уровнем WARNING, эффективный уровень логгера будет WARNING.
Поэтому, даже если новый логгер подключен к некоторым обработчикам, эти обработчики не будут вызываться, если уровень лога не превысит WARNING:

foo_logger = logging.getLogger("foo")
assert foo_logger.level == logging.NOTSET # у нового логгера уровень NOTSET
assert foo_logger.getEffectiveLevel() == logging.WARNING # и его эффективный уровень не является уровнем корневого логгера
# прикрепите консольный обработчик к foo_logger
console_handler = logging.StreamHandler()
foo_logger.addHandler(console_handler)
foo_logger.debug("debug level") # ничего не отображается, так как уровень лога DEBUG меньше чем эффективный уровень foo 
foo_logger.setLevel(logging.DEBUG)
foo_logger.debug("debug message") # теперь вы увидите на экране "debug message"

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

Рекомендации по работе с Python Logging

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

  • Настройте корневой логгер, но никогда не используйте его в своем коде, никогда не вызывайте функцию типа logging.info(), которая оставляет корневой логгер без дела. Если хотите убрать сообщения об ошибках из используемых библиотек, обязательно настройте корневой лог для записи в файл, например, чтобы облегчить отладку. По умолчанию корневой логгер выводит только на stderr, поэтому журнал может легко потеряться.
  • Чтобы использовать логгирование, создайте новый логгер с помощью logging.getLogger(имя логгера). Я использую __name__ в качестве имени логгера, но вы можете подобрать и другие варианты. Чтобы добавить больше одного обработчика, есть метод, который возвращает логгер.
import logging
import sys
from logging.handlers import TimedRotatingFileHandler


FORMATTER = logging.Formatter("%(time)s — %(name)s — %(level)s — %(message)s")
LOG_FILE = "my_app.log"


def get_console_handler():
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(FORMATTER)
    return console_handler


def get_file_handler():
    file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight')
    file_handler.setFormatter(FORMATTER)
    return file_handler


def get_logger(logger_name):
    logger = logging.getLogger(logger_name)
    logger.setLevel(logging.DEBUG) # лучше иметь больше логов, чем их нехватку
    logger.addHandler(get_console_handler())
    logger.addHandler(get_file_handler())
    logger.propagate = False
    return logger

После этого, вы можете создать новый логгер и пользоваться им:

my_logger = get_logger("Имя модуля например")
my_logger.debug("debug сообщение")
  • Используйте классы RotatingFileHandler, такие, как TimedRotatingFileHandler, из примера вместо FileHandler, так как он автоматически меняет файл для, когда тот достигает максимального размера или делает это каждый день.
  • Используйте такие инструменты, как Sentry, Airbrake, Raygun и т.д., чтобы автоматически ловить сообщения об ошибке. Это полезно при работе с приложениями. Там лог бывает очень многословным, а логи ошибок могут легко потеряться. Другое преимуществом использования этих инструментов это возможность получить подробную информацию о значениях переменных которые связанны с ошибкой: какой URL-адрес вызывает ошибку, какой пользователь и т. д.

Статьи по теме