Руководство по ведению журнала

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

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

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

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

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

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

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

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. В выведенном сообщении указаны уровень и описание события, переданное при вызове ведения журнала, то есть «Осторожно!». При необходимости формат вывода можно гибко настроить; параметры форматирования также будут рассмотрены далее.

Обратите внимание, что в этом примере мы используем функции непосредственно из модуля 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!

Как видите, для подстановки переменных данных в сообщение с описанием события используется старый стиль форматирования строк с помощью %. Это сделано для обратной совместимости: пакет ведения журнала появился до более новых вариантов форматирования, таких как 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().

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

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

Если ваши потребности в ведении журнала невелики, используйте приведённые выше примеры в своих скриптах. Если возникнут проблемы или что-то будет непонятно, задайте вопрос в категории Help на форуме обсуждения 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). Экземпляр этого обработчика можно добавить к регистратору верхнего уровня пространства имен журнала, используемого библиотекой (если вы хотите предотвратить вывод зарегистрированных библиотекой событий в sys.stderr при отсутствии конфигурации журналирования). Если все операции журналирования в библиотеке foo выполняются с помощью регистраторов, имена которых соответствуют шаблонам «foo.x», «foo.x.y» и т. д., то следующий код:

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

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

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

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