Основные концепции журналирования в Python

По мере того, как усложняется структура приложения, ведение логов (журналирование) становится всё полезнее для разработчика. Логи не только пригодятся в процессе отладки, но и помогут обнаружить скрытые проблемы проекта, а также отследить его производительность.

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

Данный материал — руководство для начинающих разработчиков.

Обратите внимание, что весь размещённый в статье код подразумевает, что вы уже импортировали модуль:

			import logging
		

Основные концепции журналирования на Python

В данном разделе рассмотрим уровни журналирования, форматирование журналов, обработчики и диспетчер журналирования.

Уровни журналирования

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

В Python существует шесть уровней лога. Каждому уровню присвоено целое число, указывающее на важность лога: NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 и CRITICAL=50.

Все уровни последовательно упорядочены (DEBUG < INFO < WARN), кроме NOTSET, который мы отдельно разберём далее.

Форматирование журналов

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

Например, при форматировании записи «hello world»:

			"%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"
		

в логе она отобразится таким образом:

			2018-02-07 19:47:41,864 - a.b.c - WARNING - :1 - hello world
		

Обработчик журналирования

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

В каждом обработчике есть два важных поля:

1. Форматер, добавляющий в лог контекстную информацию.
2. Уровень лога, который отфильтровывает журналы низшего уровня. Обработчик уровня INFO не будет работать с журналами уровня DEBUG.

Стандартная библиотека содержит обработчики, которых в большинстве случаев должно быть достаточно. Самые распространённые — StreamHandler и FileHandler.

			console_handler = logging.StreamHandler()
file_handler = logging.FileHandler("filename")
		

Диспетчер журналирования

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

			toto_logger = logging.getLogger("toto")
		

В диспетчере три основных поля.

1. Распространение. Определяет, должен ли лог обрабатываться родительским диспетчером (по умолчанию эта функция активна).
2. Уровень. Как и в обработчике, уровень отфильтровывает менее важные журналы. Отличие заключается в том, что уровень проверяется только в дочерних диспетчерах, при распространении вверх уровень не учитывается.
3. Список обработчиков, в которые направляется попавшая в диспетчер запись. Он позволяет гибко настраивать обработку записей. К примеру, можно создать обработчик, записывающий всё с уровнем DEBUG, и обработчик для электронной почты, работающий только с уровнем CRITICAL. Взаимоотношения диспетчера с обработчиками строятся по принципу издатель-потребитель. Запись передаётся всем обработчикам, как только пройдёт проверку уровня в диспетчере.

Имя диспетчера уникально, таким образом, если диспетчер с именем «toto» уже создан, последующие вызовы logging.getLogger("toto") будут возвращать один и тот же объект.

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

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

При создании нового диспетчера в качестве родительского будет установлен корневой.

			lab = logging.getLogger("a.b")
assert lab.parent == logging.root # lab's parent is indeed the root logger
		

Диспетчер использует «запись с точкой», то есть объект с именем «a.b» будет дочерним по отношению к «a». Однако это правило действительно только при существовании «a», иначе родительским всё равно будет корневой диспетчер.

			la = logging.getLogger("a")
assert lab.parent == la # lab's parent is now la instead of root
		

Когда диспетчер определяет, что запись проходит фильтр по уровню (если уровень лога ниже уровня диспетчера, запись игнорируется), применяется не действительный, а эффективный уровень. Эффективный уровень обычно равен уровню диспетчера, однако при этом уровень NOTSET является исключением. В таком случае эффективный уровень будет равен уровню первого диспетчера, расположенного выше в вертикали наследования, уровень которого не равен NOTSET.

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

			toto_logger = logging.getLogger("toto")
assert toto_logger.level == logging.NOTSET # новый диспетчер имеет уровень NOTSET
assert toto_logger.getEffectiveLevel() == logging.WARN # и его эффективный уровень равен уровню корневого диспетчера, то есть WARN

# прикрепляем консольный обработчик к диспетчеру «toto»
console_handler = logging.StreamHandler()
toto_logger.addHandler(console_handler)
toto_logger.debug("debug") # ничего не выводится, т. к. уровень логов, DEBUG, ниже, чем эффективный уровень «toto»
toto_logger.setLevel(logging.DEBUG)
toto_logger.debug("debug message") # теперь вы можете увидеть на экране «debug message»
		

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

Практические советы

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

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

			import logging
import sys
from logging.handlers import TimedRotatingFileHandler
FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)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) # better to have too much log than not enough
   logger.addHandler(get_console_handler())
   logger.addHandler(get_file_handler())
   # with this pattern, it's rarely necessary to propagate the error up to parent
   logger.propagate = False
   return logger
		

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

			my_logger = get_logger("my module name")
my_logger.debug("a debug message")
		

• Используйте классы RotatingFileHandler, например так, как применён TimedRotatingFileHandler в приведённом выше примере вместо FileHandler. Благодаря этому смена файла журнала будет происходить автоматически при достижении максимального размера или по расписанию.
• Для автоматического отслеживания сообщений об ошибках используйте такие инструменты, как Sentry, Airbrake, Raygun и тому подобные. Особенно это полезно при работе над веб-приложениями, где логи могут быть весьма многословными и ошибки легко теряются в общей массе. Ещё одно преимущество этих инструментов в том, что они отображают значения переменных при обнаружении ошибок. Таким образом можно определить, какой URL или пользователь спровоцировал проблему и тому подобное.