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

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

Модуль 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() и т.д. Поскольку это однократное простое средство настройки, только первый вызов что-то делает; последующие вызовы фактически ничего не делают.

Если запускать этот скрипт несколько раз, сообщения от последовательных запусков добавляются в файл 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. Если требуется более гибкое управление форматированием даты/времени, передайте аргумент 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 (доступна по адресу http://groups.google.com/group/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() возвращает ссылку на экземпляр логгера с указанным именем, если оно задано, или на корневой логгер, если нет. Имена представляют собой иерархические структуры, разделенные точками. Многократные вызовы getLogger() с одним и тем же именем возвращают ссылку на один и тот же объект логгера. Логгеры, находящиеся ниже в иерархическом списке, являются дочерними по отношению к логгерам, находящимся выше в списке. Например, для логгера с именем foo логгеры с именами foo.bar, foo.bar.baz и foo.bam являются потомками foo.

Loggers have a concept of effective level. If a level is not explicitly set on a logger, the level of its parent is used instead as its effective level. If the parent has no explicit level set, its parent is examined, and so on - all ancestors are searched until an explicitly set level is found. The root logger always has an explicit level set (WARNING by default). When deciding whether to process an event, the effective level of the logger is used to determine whether the event is passed to the logger’s handlers.

Дочерние логгеры передают сообщения обработчикам, связанным с их родительскими логгерами. По этой причине нет необходимости определять и настраивать обработчики для всех логгеров, которые использует приложение. Достаточно настроить обработчики для логгера верхнего уровня и создавать дочерние логгеры по мере необходимости. (Однако можно отключить передачу, установив атрибут propagate логгера в False.)

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

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

Стандартная библиотека включает довольно много типов обработчиков (см. Полезные обработчики); в примерах учебных пособий в основном используются 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.warn('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.warn('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

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