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

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

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

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

Следующие шаги

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

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

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

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

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

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».

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

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