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

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

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

Обратите внимание, что в этом примере мы используем функции непосредственно из модуля 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 служит базовым классом, который определяет интерфейс для всех обработчиков и задает поведение по умолчанию, которое могут использовать (или переопределять) дочерние классы.

Форматтеры

Объекты Formatter задают окончательный порядок, структуру и содержимое сообщения журнала. В отличие от базового класса 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. Это считается наилучшим поведением по умолчанию.

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

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

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

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

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

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