Руководство по логированию¶Logging HOWTO

Когда использовать логирование¶When to use logging

Логирование предоставляет набор удобных функций для простого использования. Это debug(), info(), warning(), error() и critical(). Чтобы определить, когда использовать логирование, см. таблицу ниже, которая для каждой из общих задач указывает наилучший инструмент.

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

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

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

Простой пример ¶A simple example

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

import logging
logging.warning('Watch out!')  # выведет сообщение в консоль
logging.info('I told you so')  # ничего не выведет

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

WARNING:root:Watch out!

выводится на консоль. Сообщение INFO не появляется, потому что уровень по умолчанию – WARNING. Выводимое сообщение включает указание уровня и описание события, переданное в вызове логирования, т.е. 'Watch out!'. Не стоит беспокоиться о части 'root': она будет объяснена позже. Фактический вывод можно довольно гибко форматировать, если это необходимо; параметры форматирования также будут объяснены позже.

Запись логов в файл ¶Logging to a file

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

import logging
logging.basicConfig(filename='example.log',level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')

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

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too

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

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

--log=INFO

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

getattr(logging, loglevel.upper())

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

# предполагая, что loglevel привязан к строковому значению, полученному из
# аргумента командной строки. Преобразование в верхний регистр позволяет пользователю
# указать --log=DEBUG или --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() и т.д. Поскольку это одноразовое средство простой настройки, только первый вызов фактически что-то делает: последующие вызовы по сути являются пустышками (no-op).

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

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

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

Логирование из нескольких модулей¶Logging from multiple modules

Если ваша программа состоит из нескольких модулей, вот пример того, как можно организовать в ней логирование:

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(filename='myapp.log', level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

# mylib.py
import logging

def do_something():
    logging.info('Doing something')

Если вы запустите myapp.py, вы должны увидеть это в myapp.log:

INFO:root:Started
INFO:root:Doing something
INFO:root:Finished

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

Логирование переменных данных¶Logging variable data

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

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

выведет:

WARNING:root:Look before you leap!

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

Изменение формата отображаемых сообщений¶Changing the format of displayed messages

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

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

Отображение даты/времени в сообщениях¶Displaying the date/time in messages

Для отображения даты и времени события в строку формата помещается ‘%(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().

Следующие шаги¶Next Steps

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

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

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

Поток логирования¶Logging Flow

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

Логгеры¶Loggers

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

Обработчики¶Handlers

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

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

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

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

• setFormatter() выбирает объект Formatter для использования этим обработчиком.

• addFilter() и removeFilter() соответственно настраивают и удаляют объекты фильтров для обработчиков.

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

Форматировщики¶Formatters

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

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

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

1. Создание регистраторов, обработчиков и форматировщиков явно с помощью кода Python, вызывающего перечисленные выше методы настройки.

2. Создание файла конфигурации журналирования и его чтение с помощью функции fileConfig().

3. Создание словаря с информацией о конфигурации и передача его функции dictConfig().

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

import logging

# создать логгер
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# создать обработчик консоли и установить уровень DEBUG
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# создать форматтер
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# добавить форматтер в ch
ch.setFormatter(formatter)

# добавить ch в логгер
logger.addHandler(ch)

# код 'приложения'
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')

# создать логгер
logger = logging.getLogger('simpleExample')

# код 'приложения'
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
datefmt=

Результат почти идентичен примеру без файла конфигурации:

$ 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]

Для получения дополнительной информации о журналировании с использованием словаря см. функции конфигурации.

Что произойдет, если конфигурация не предоставлена¶What happens if no configuration is provided

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

Для версий Python до 3.2 поведение следующее:

• Если logging.raiseExceptions равно False (рабочий режим), событие молча отбрасывается.

• Если logging.raiseExceptions равно True (режим разработки), сообщение 'No handlers could be found for logger X.Y.Z' выводится один раз.

В Python 3.2 и новее поведение следующее:

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

Чтобы получить поведение как до версии 3.2, logging.lastResort можно установить в None.

Настройка журналирования для библиотеки¶Configuring Logging for a Library

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

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

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