Ведение журнала Python: подробное руководство

Опубликовано: 2022-03-11

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

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

Несмотря на преимущества, модуль ведения журнала часто упускается из виду, так как для его правильной настройки требуется некоторое время, и, хотя, на мой взгляд, полный официальный документ по ведению журнала на https://docs.python.org/3/library/logging.html на самом деле не дает рекомендации по ведению журнала и не выделяет некоторые сюрпризы ведения журнала.

Это руководство по ведению журнала Python не предназначено для того, чтобы быть полным документом по модулю ведения журнала, а скорее является руководством для начала работы, в котором представлены некоторые концепции ведения журнала, а также некоторые «подводные камни», на которые следует обратить внимание. Пост будет заканчиваться рекомендациями и содержать некоторые указатели на более сложные темы ведения журналов.

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

 import logging

Концепции ведения журнала Python

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

Уровни ведения журнала Python

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

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

Уровни журнала Python Logging

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

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

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

Например, когда журнал «hello world» отправляется через средство форматирования журнала:

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

это станет

 2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world

Форматирование сообщения журнала Python

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

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

Каждый обработчик журнала имеет 2 важных поля:

  • Средство форматирования, добавляющее контекстную информацию в журнал.
  • Уровень журнала, который отфильтровывает журналы с более низкими уровнями. Таким образом, обработчик журнала с уровнем INFO не будет обрабатывать журналы DEBUG.

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

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

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

Регистратор Python

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

 toto_logger = logging.getLogger("toto")

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

  • Распространение: решает, следует ли распространять журнал на родительский блок ведения журнала. По умолчанию его значение равно True.
  • Уровень A: Как и уровень обработчика журнала, уровень регистратора используется для фильтрации «менее важных» журналов. Только, в отличие от обработчика логов, уровень проверяется только у «дочернего» логгера; как только журнал будет передан своим родителям, уровень не будет проверяться. Это скорее неинтуитивное поведение.
  • Обработчики: список обработчиков, которым будет отправлен журнал, когда он поступит в регистратор. Это обеспечивает гибкую обработку журналов — например, у вас может быть обработчик журнала файлов, который регистрирует все журналы DEBUG, и обработчик журнала электронной почты, который будет использоваться только для КРИТИЧЕСКИХ журналов. В этом отношении отношения между регистратором и обработчиком аналогичны отношениям между издателем и потребителем: журнал будет транслироваться всем обработчикам после прохождения проверки на уровне регистратора.

Процесс регистрации Python

Регистратор уникален по имени, а это означает, что если был создан регистратор с именем «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("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

Однако регистратор использует «точечную нотацию», что означает, что регистратор с именем «ab» будет дочерним по отношению к регистратору «a». Однако это верно только в том случае, если был создан регистратор «a», в противном случае родителем «ab» по-прежнему является корень.

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

Когда регистратор решает, должен ли журнал пройти проверку уровня (например, если уровень журнала ниже уровня регистратора, журнал будет проигнорирован), он использует свой «действующий уровень» вместо фактического уровня. Эффективный уровень такой же, как уровень регистратора, если уровень не установлен, т. е. все значения от DEBUG до CRITICAL; однако, если уровень регистратора НЕУСТАНОВЛЕН, то эффективным уровнем будет первый уровень предка, который имеет уровень, отличный от НЕУСТАНОВЛЕННЫЙ.

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

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

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

Лучшие практики ведения журналов Python

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

  • Настройте корневой регистратор, но никогда не используйте его в своем коде — например, никогда не вызывайте такую ​​функцию, как logging.info() , которая на самом деле вызывает корневой регистратор за кулисами. Если вы хотите перехватывать сообщения об ошибках из используемых вами библиотек, обязательно настройте корневой регистратор на запись в файл, например, чтобы упростить отладку. По умолчанию корневой регистратор выводит только на stderr , поэтому журнал может легко потеряться.
  • Чтобы использовать ведение журнала, обязательно создайте новый регистратор с помощью logging.getLogger(logger name) . Обычно я использую __name__ в качестве имени логгера, но можно использовать что угодно, если оно непротиворечиво. Чтобы добавить больше обработчиков, у меня обычно есть метод, который возвращает регистратор (вы можете найти суть на https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0).
 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-адрес вызывает ошибку, какой пользователь заинтересован и т. д.

Если вас интересуют другие передовые практики, прочитайте «10 наиболее распространенных ошибок, которые совершают разработчики Python» коллеги по Toptaler Мартина Чикиляна.