Краткое руководство по логированию

Когда использовать логирование

Чтобы получить доступ к функциям логирования, создайте регистратор с помощью logger = getLogger(__name__), а затем вызывайте методы регистратора debug(), info(), warning(), error() и critical(). Чтобы понять, когда использовать логирование и какие методы регистратора для этого подходят, см. таблицу ниже. В ней для каждого из распространённых заданий указан наиболее подходящий инструмент.

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

Уровень по умолчанию — WARNING, то есть будут отслеживаться только события этого уровня и выше, если пакет logging не настроен иначе.

Отслеживаемые события можно обрабатывать разными способами. Самый простой способ обработки отслеживаемых событий — выводить их в консоль. Ещё один распространённый способ — записывать их в файл на диске.

Простой пример

Вот очень простой пример:

import logging
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

Если ввести эти строки в скрипт и запустить его, вы увидите:

WARNING:root:Watch out!

в консоли. Сообщение INFO не отображается, поскольку уровень по умолчанию — WARNING. В выведенное сообщение входят указание уровня и описание события, переданное при вызове логирования, то есть «Watch out!». При необходимости фактический вывод можно гибко отформатировать; варианты форматирования также будут рассмотрены далее.

Обратите внимание: в этом примере мы используем функции непосредственно из модуля logging, например logging.debug, вместо того чтобы создавать регистратор и вызывать его функции. Эти функции работают с корневым регистратором, но могут быть полезны, поскольку вызовут для вас basicConfig(), если он ещё не был вызван, как в этом примере. Однако в крупных программах обычно требуется явно управлять конфигурацией логирования, поэтому, а также по другим причинам, лучше создавать регистраторы и вызывать их методы.

Логирование в файл

Очень часто события логирования записывают в файл, поэтому рассмотрим этот случай. Обязательно попробуйте выполнить следующие действия в новом интерпретаторе Python, а не продолжайте работу в сеансе, описанном выше:

import logging
logger = logging.getLogger(__name__)
logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
logger.debug('This message should go to the log file')
logger.info('So should this')
logger.warning('And this, too')
logger.error('And non-ASCII stuff, too, like Øresund and Malmö')

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

DEBUG:__main__:This message should go to the log file
INFO:__main__:So should this
WARNING:__main__:And this, too
ERROR:__main__:And non-ASCII stuff, too, like Øresund and Malmö

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

Если вы хотите задавать уровень логирования с помощью параметра командной строки, например:

--log=INFO

и значение параметра --log сохранено в переменной loglevel, можно использовать:

getattr(logging, loglevel.upper())

чтобы получить значение, которое будет передано в basicConfig() через аргумент level. Возможно, потребуется проверить корректность введённого пользователем значения, например, как в следующем примере:

# assuming loglevel is bound to the string value obtained from the
# command line argument. Convert to upper case to allow the user to
# specify --log=DEBUG or --log=debug
numeric_level = getattr(logging, loglevel.upper(), None)
if not isinstance(numeric_level, int):
    raise ValueError('Invalid log level: %s' % loglevel)
logging.basicConfig(level=numeric_level, ...)

Вызов basicConfig() должен выполняться до любых вызовов методов регистратора, таких как debug(), info() и т. д. Иначе событие логирования может быть обработано не так, как требуется.

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

logging.basicConfig(filename='example.log', filemode='w', level=logging.DEBUG)

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

Логирование переменных данных

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

import logging
logging.warning('%s before you %s', 'Look', 'leap!')

выведет:

WARNING:root:Look before you leap!

Как видите, для подстановки переменных данных в сообщение с описанием события используется старый стиль форматирования строк с помощью %. Это сделано для обратной совместимости: пакет logging появился до новых вариантов форматирования, таких как str.format() и string.Template. Эти новые варианты форматирования поддерживаются, но их рассмотрение выходит за рамки этого учебника: дополнительную информацию см. в разделе Использование определённых стилей форматирования во всём приложении.

Изменение формата отображаемых сообщений

Чтобы изменить формат отображения сообщений, укажите нужный формат:

import logging
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

В результате будет выведено:

DEBUG:This message should appear on the console
INFO:So should this
WARNING:And this, too

Обратите внимание, что «root», присутствовавшее в предыдущих примерах, исчезло. Полный список элементов, которые могут использоваться в строках формата, приведён в документации по атрибутам LogRecord, но для простого использования достаточно указать levelname (степень серьёзности), message (описание события, включая переменные данные) и, возможно, время возникновения события. Это описано в следующем разделе.

Отображение даты и времени в сообщениях

Чтобы отображать дату и время события, добавьте «%(asctime)s» в строку формата:

import logging
logging.basicConfig(format='%(asctime)s %(message)s')
logging.warning('is when this event was logged.')

В результате должно быть выведено нечто подобное:

2010-12-12 11:41:42,612 is when this event was logged.

Формат даты и времени по умолчанию (показанный выше) соответствует ISO8601 или RFC 3339. Если требуется точнее настроить форматирование даты и времени, передайте аргумент datefmt в basicConfig, как в этом примере:

import logging
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')

В результате будет выведено примерно следующее:

12/12/2010 11:46:36 AM is when this event was logged.

Формат аргумента datefmt такой же, как в функции time.strftime().

Дальнейшие шаги

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

Если ваши потребности в логировании невелики, используйте приведённые выше примеры в своих скриптах. Если возникнут проблемы или что-то будет непонятно, задайте вопрос в группе Usenet comp.lang.python (доступна по адресу https://groups.google.com/g/comp.lang.python), и вскоре вам должны помочь.

Всё ещё здесь? Можете продолжить чтение следующих разделов, в которых материал изложен несколько подробнее и на более продвинутом уровне, чем в базовом учебнике выше. После этого можно ознакомиться со сборником рецептов по логированию.

Порядок обработки записей журнала

Поток информации о событиях журнала между регистраторами и обработчиками показан на следующей диаграмме.

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

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

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

Ниже перечислены наиболее распространённые методы настройки:

• Logger.setLevel() задаёт наименьший уровень важности сообщения журнала, которое будет обрабатывать регистратор: debug — самый низкий из встроенных уровней, а critical — самый высокий. Например, если установлен уровень INFO, регистратор будет обрабатывать только сообщения INFO, WARNING, ERROR и CRITICAL, игнорируя сообщения DEBUG.
• Logger.addHandler() и Logger.removeHandler() добавляют объекты-обработчики к объекту-регистратору и удаляют их из него. Обработчики подробнее рассматриваются в разделе Обработчики.
• Logger.addFilter() и Logger.removeFilter() добавляют объекты-фильтры к объекту-регистратору и удаляют их из него. Фильтры подробнее рассматриваются в разделе Объекты-фильтры.

Необязательно всегда вызывать эти методы для каждого создаваемого регистратора. См. два последних абзаца этого раздела.

После настройки объекта-регистратора для создания сообщений журнала используются следующие методы:

• Logger.debug(), Logger.info(), Logger.warning(), Logger.error() и Logger.critical() создают записи журнала с сообщением и уровнем, соответствующими именам этих методов. Сообщение фактически является строкой формата, в которой может использоваться стандартный синтаксис подстановки строк %s, %d, %f и т. д. Остальные аргументы представляют собой список объектов, соответствующих полям подстановки в сообщении. Что касается **kwargs, методы ведения журнала учитывают только ключевое слово exc_info и используют его, чтобы определить, следует ли записывать информацию об исключении.
• Logger.exception() создаёт сообщение журнала, аналогичное сообщению метода Logger.error(). Отличие в том, что Logger.exception() выводит вместе с ним трассировку стека. Вызывайте этот метод только из обработчика исключений.
• Logger.log() принимает уровень журнала в качестве явного аргумента. Это немного более многословный способ записи сообщений, чем использование перечисленных выше методов для удобного выбора уровня, но именно так можно вести журнал с пользовательскими уровнями.

getLogger() возвращает ссылку на экземпляр регистратора с указанным именем, если оно задано, или root, если нет. Имена образуют иерархические структуры, разделённые точками. Несколько вызовов getLogger() с одним и тем же именем возвращают ссылку на один и тот же объект-регистратор. Регистраторы, расположенные ниже в иерархическом списке, являются потомками регистраторов, расположенных выше. Например, если задан регистратор с именем foo, регистраторы с именами foo.bar, foo.bar.baz и foo.bam являются потомками foo.

Для регистраторов существует понятие эффективного уровня. Если уровень явно не задан для регистратора, в качестве эффективного уровня используется уровень его родителя. Если для родителя явный уровень не задан, проверяется его родитель и так далее — поиск продолжается по всем предкам, пока не будет найден явно заданный уровень. Для корневого регистратора уровень всегда задан явно (по умолчанию — WARNING). При принятии решения об обработке события эффективный уровень регистратора используется для определения того, будет ли событие передано обработчикам регистратора.

Дочерние регистраторы передают сообщения обработчикам, связанным с родительскими регистраторами. Поэтому нет необходимости определять и настраивать обработчики для всех регистраторов, используемых приложением. Достаточно настроить обработчики для регистратора верхнего уровня и создавать дочерние регистраторы по мере необходимости. (Однако распространение можно отключить, задав для атрибута propagate регистратора значение False.)

Обработчики

Объекты Handler отвечают за отправку соответствующих сообщений журнала (с учётом уровня важности сообщений) в указанное для обработчика место назначения. Объекты Logger могут добавлять к себе ноль или более объектов-обработчиков с помощью метода addHandler(). Например, приложению может потребоваться отправлять все сообщения журнала в файл, все сообщения уровня error и выше — в stdout, а все сообщения уровня critical — на адрес электронной почты. Для этого нужны три отдельных обработчика, каждый из которых отвечает за отправку сообщений определённого уровня важности в определённое место.

Стандартная библиотека включает немало типов обработчиков (см. раздел Полезные обработчики); в примерах руководств в основном используются StreamHandler и FileHandler.

Разработчикам приложений нужно учитывать очень мало методов обработчика. Для разработчиков, использующих встроенные объекты-обработчики (то есть не создающих собственные обработчики), имеют значение только следующие методы настройки:

• Метод setLevel(), как и у объектов-регистраторов, задаёт наименьший уровень важности, сообщения которого будут отправляться в соответствующее место назначения. Зачем нужны два метода setLevel()? Уровень, заданный для регистратора, определяет, сообщения какого уровня важности он передаёт своим обработчикам. Уровень, заданный для каждого обработчика, определяет, какие сообщения этот обработчик будет отправлять дальше.
• setFormatter() выбирает объект Formatter, который будет использоваться этим обработчиком.
• addFilter() и removeFilter() соответственно добавляют фильтры к обработчикам и удаляют их.

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

Форматтеры

Объекты форматтеров задают итоговый порядок, структуру и содержимое сообщения журнала. В отличие от базового класса logging.Handler, классы форматтеров можно создавать в коде приложения, хотя при необходимости особого поведения приложения, вероятно, потребуется унаследовать класс форматтера. Конструктор принимает три необязательных аргумента: строку формата сообщения, строку формата даты и индикатор стиля.

logging.Formatter.__init__(fmt=None, datefmt=None, style='%')

Если строка формата сообщения не указана, по умолчанию используется исходное сообщение. Если строка формата даты не указана, используется следующий формат даты по умолчанию:

%Y-%m-%d %H:%M:%S

в конце добавляются миллисекунды. Значением style должно быть одно из '%', '{' или '$'. Если не указано ни одно из этих значений, будет использоваться '%'.

Если style равен '%', в строке формата сообщения используется подстановка строк в стиле %(<dictionary key>)s; возможные ключи описаны в разделе Атрибуты LogRecord. Если стиль равен '{', предполагается, что строка формата сообщения совместима с str.format() (с использованием ключевых аргументов). Если же стиль равен '$', строка формата сообщения должна соответствовать требованиям string.Template.substitute().

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

'%(asctime)s - %(levelname)s - %(message)s'

Форматтеры используют настраиваемую пользователем функцию для преобразования времени создания записи в кортеж. По умолчанию используется time.localtime(); чтобы изменить это для отдельного экземпляра форматтера, задайте атрибут converter экземпляра равным функции с такой же сигнатурой, как у time.localtime() или time.gmtime(). Чтобы изменить настройку для всех форматтеров, например если вы хотите отображать время всех записей журнала по Гринвичу, задайте атрибут converter класса Formatter (значение time.gmtime включает отображение по Гринвичу).

Настройка журналирования

Программисты могут настроить журналирование тремя способами:

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

Справочную документацию по двум последним вариантам см. в разделе Функции настройки. В следующем примере с помощью кода Python настраиваются очень простой регистратор, обработчик консоли и простой форматтер:

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

При запуске этого модуля из командной строки выводится следующее:

$ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

Следующий модуль Python создает регистратор, обработчик и форматтер, почти идентичные приведенным выше в примере; единственное отличие — имена объектов:

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Вот файл logging.conf:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

Вывод почти идентичен выводу примера, в котором не использовался файл конфигурации:

$ python simple_logging_config.py
2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message
2005-03-19 15:38:55,979 - simpleExample - INFO - info message
2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message
2005-03-19 15:38:56,055 - simpleExample - ERROR - error message
2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message

Как видите, у подхода с файлом конфигурации есть несколько преимуществ по сравнению с подходом на основе кода Python: прежде всего, конфигурация отделена от кода, а пользователи, не занимающиеся программированием, могут легко изменять свойства журналирования.

Обратите внимание: имена классов, указанные в файлах конфигурации, должны быть либо относительными относительно модуля logging, либо абсолютными значениями, которые можно разрешить с помощью обычных механизмов импорта. Таким образом, можно использовать как WatchedFileHandler (относительно модуля logging), так и mypackage.mymodule.MyHandler (для класса, определенного в пакете mypackage и модуле mymodule, где mypackage доступен в пути импорта Python).

В Python 3.2 был представлен новый способ настройки журналирования с помощью словарей, содержащих информацию о конфигурации. Он предоставляет возможности, охватывающие все функции описанного выше подхода с файлом конфигурации, и является рекомендуемым способом настройки для новых приложений и развертываний. Поскольку для хранения информации о конфигурации используется словарь Python, который можно заполнить разными способами, у вас появляется больше вариантов настройки. Например, для заполнения словаря конфигурации можно использовать файл конфигурации в формате JSON или, если у вас есть средства обработки YAML, файл в формате YAML. Разумеется, можно также создать словарь в коде Python, получить его в сериализованном виде через сокет или выбрать любой другой подход, подходящий для вашего приложения.

Вот пример той же конфигурации, что и выше, в формате YAML для нового подхода на основе словарей:

version: 1
formatters:
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout
loggers:
  simpleExample:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

Дополнительные сведения о журналировании с помощью словаря см. в разделе Функции настройки.

Что происходит, если конфигурация не задана

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

Событие выводится с помощью «резервного обработчика», хранящегося в lastResort. Этот внутренний обработчик не связан ни с одним регистратором и работает как StreamHandler, записывая описание события в текущее значение sys.stderr (поэтому учитываются все перенаправления, которые могут быть настроены). Форматирование сообщения не выполняется — выводится только исходное описание события. Уровень обработчика установлен в WARNING, поэтому выводятся все события этого уровня и выше.

Настройка журналирования для библиотеки

При разработке библиотеки, использующей журналирование, следует позаботиться о документировании того, как именно библиотека его использует, например указать имена используемых регистраторов. Также необходимо продумать настройку журналирования. Если приложение, использующее библиотеку, не использует журналирование, а код библиотеки вызывает функции журналирования, то (как описано в предыдущем разделе) события уровня WARNING и выше будут выводиться в sys.stderr. Такое поведение считается наилучшим вариантом по умолчанию.

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

В пакете logging есть пустой обработчик: NullHandler (начиная с Python 3.1). Экземпляр этого обработчика можно добавить к регистратору верхнего уровня пространства имен logging, используемого библиотекой (если вы хотите предотвратить вывод зарегистрированных событий библиотеки в sys.stderr при отсутствии настроек журналирования). Если все вызовы журналирования библиотеки foo выполняются с помощью регистраторов с именами, соответствующими шаблонам «foo.x», «foo.x.y» и т. д., следующий код:

import logging
logging.getLogger('foo').addHandler(logging.NullHandler())

должен дать желаемый результат. Если организация выпускает несколько библиотек, вместо простого «foo» можно указать имя регистратора «orgname.foo».

Пользовательские уровни

Определять собственные уровни можно, но в этом не должно быть необходимости, поскольку существующие уровни выбраны на основе практического опыта. Однако, если вы уверены, что вам нужны пользовательские уровни, следует действовать с большой осторожностью; возможно, определять пользовательские уровни при разработке библиотеки — очень плохая идея. Если несколько авторов библиотек определят собственные пользовательские уровни, вывод журналов из таких библиотек, используемых вместе, может оказаться трудным для настройки и/или интерпретации разработчиком приложения, поскольку одно и то же числовое значение может иметь разный смысл в разных библиотеках.