РУКОВОДСТВО ПО ВЕДЕНИЮ ЖУРНАЛА

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

Получить доступ к функциям ведения журнала можно, создав регистратор с помощью logger = 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() выбирает объект-форматтер, который будет использовать этот обработчик.
• 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(). Чтобы изменить поведение для всех форматтеров (например, если требуется отображать время всех записей в GMT), задайте атрибут converter класса Formatter (для отображения времени по GMT укажите 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())

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

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

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