Продвинутое руководство по логированию (Перевод)

Библиотека logging использует модульный подход и предлагает несколько категорий компонентов: loggers, handlers, filters, и formatters.

• Logger представляет интерфейс, который использует непосредственно код приложения.
• Handler посылает запись лога (созданную logger'ом) в соответствующее расположение.
• Filter позволяет определить, какую запись лога выводить.
• Formatter определяет расположение записи лога в итоговом выводе.

Информация логирования передаётся между logger, handler, filter и formatter в экземпляре LogRecord.

Логирование осуществляется вызовом методов экземпляра класса Logger (тут и далее он будет называться loggers). Каждый экземпляр имеет своё имя и эти имена располагаются в иерархии пространства имён, используя точки в качестве разделителей. Например, logger с именем ‘scan’ является родительским logger'ом для logger'ов ‘scan.text’, ‘scan.html’ и ‘scan.pdf’. Имена logger'ов могут быть любыми, как Вы хотите, и отображают место, где было создано сообщение лога.

Общепринято использовать  для имён logger'ов имена модулей:

logger = logging.getLogger(__name__)

В таком случае имя logger'a соответствует иерархии пакетов/модулей и интуитивно становится понято, где именно события логируются уже из имени logger'a.

Корень иерархии logger'ов называется root logger. Этот тот logger, который используется функциями debug(), info(), warning(), error() и critical(), которые просто вызывают одноимённые меоды root logger'a. Функции и методы имеют одну и ту же подпись. Имя root logger’а отображается как ‘root’ в выводе логов.

Конечно же возможно логировать сообщения в разные места. Вы можете записывать сообщения в файлы, передавать по HTTP GET/POST, email'y через SMTP, сокеты или OS-специфичные механизмы логирования, такие как syslog или Windows NT event log. Место, куда отправляются логи, определяется классами handler. Вы можете создать свой собственный класс направления логов, если у Вас есть какие-то свои особые потребности.

По умолчанию место направления не задано для сообщение логов. Вы можете определить его при помощи basicConfig(), как в примерах руководства. Если Вы вызываете функции debug(), info(), warning(), error() и critical(), они будут проверять, задано ли это место, и если оно не задано, то вывод направляется в консколь (sys.stderr) и используется формат отображения сообщений по умолчанию.

Формат отображения, задаваемый по умолчанию в basicConfig() для сообщений:

severity:logger name:message

Вы можете изменить его передав строку формата в basicConfig() в аргументе format. Более подробно все опции форматирования описаны в Formatter Objects.

Поток форматирования

иллюстрация тут

Перемещение информации лога между logger'ами и handler'ами иллюстрирован диаграммой по ссылке выше.

Logger'ы

Объекты Logger имеют тройную работу. Во-первых, они предоставляют методы коду приложения, так что приложение может в процессе выполнения логировать сообщения. Во-вторых, объекты logger определяют какие сообщения логов будут работать на этом уровне (объекте фильтра). В третих, объекты logger передают подходящие сообщения логов всем заинтересованным handler'ам.
Чаще всего используемые методы объекта logger относятся к одной из двух категорий: настройка и отправка сообщений.
Вот наиболее часто использемые методы настройки:

• Logger.setLevel() определяет минимальный уровень сообщений, которые будут обработаны; debug - минимальный встроенный уровень, а critical - максимальный. Например, если установлен уровень INFO, logger будет обрабатывать сообщения уровня INFO, WARNING, ERROR и CRITICAL и игнорировать сообщения уровня DEBUG.
• Logger.addHandler() и Logger.removeHandler() добавляют и удаляют объекты handler из объекта logger. Handler'ы более подробно обсуждены в Handlers.
• Logger.addFilter() и Logger.removeFilter() добавляют и удалют объекты filter из объекта logger. Filter'ы более подробно обсуждаются в Filter Objects.

Вам не нужно вызывать эти методы каждый раз для каждого logger, который Вы создаёте. Смотрите последние два абазца этого раздела.
Когда объект logger настроен, следующие методы создают сообщения логов:

• 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() возвращает ссылку на экземпляр logger'а с именем, если оно задано, или root, если нет. Имена представляют из себя иерархическую структуру с точками в качестве разделителей. Множественные вызовы getLogger() с одним и тем же имененм будут возвращать ссылку на один и тот же объект logger'а. Logger'ы, находящиеся ниже в иерархии являются дочерними для logger'ов, которые находятся выше. Например, для logger'а с имененм foo logger'ы с именами foo.bar, foo.bar.baz и foo.bam будут дочерними.
Logger'ы поддерживают концепцию эффективного уровня. Если для logger'а не задан уровень явно, то используется уровень его родителя. Если и его родитель не имеет заданного уровня - смотрится родитель родителя, и так далее. Корневой logger всегда имеет явно заданный уровень (по умолчанию это WARNING). При решении вопроса обрабатывать ли событи используется именно эффективный уровень.
Дочерние logger'ы распространяют сообщения handler'ам, связанным с родительским logger'ом. Из-за этого нет необходимости определять и настраивать handler'ы для всех logger'ов в приложении. Но важно сконфигурировать handler'ы для logger'ов верхнего уровня и уже потом создавать при необходимости дочерние logger'ы. (Однако, распространение сообщений можно отключить, задав значением атрибута propagate logger'a равным False.)

Handler'ы

Объекты Handler отвечают за отправку соответствующего сообщения (соответствующего уровня) к его месту назначения, определённого в handler'e. Объекты logger могут добавить себе ноль или более handler'ов при помощи метода addHandler(). Например, приложение может хотеть отправлять все сообщения в файл логов, сообщения уровня ошибки и выше в stdout, а все критические сообщения отправлять на почту. Этот сценарий требует три handler'a, каждый из которых отвечает за отправку сообщений определённого уровня в определённое место.
Стандартная библиотека включает в себя несколько типов handler'ов (см Useful Handlers); это руководство по большей части использует в примерах StreamHandler и FileHandler.
Есть несколько методов у handler'a для разработчиков приложений, о которых стоит позаботиться. Методы, которые нужны тем, кто будет пользоваться встроенными handler'ами (то есть, не будет использовать самописные) следующие:

• Метод Handler.setLevel() аналогичен методу объекта logger, он определяет минимальный уровень, который будет направлен в соответствующее место. Зачем нужно два метода setLevel()? Уровень, заданный в logger'e определяет уровень сообщений, который будет передан в handler'ы. Уровень, заданный в каждом handler'e определяет сообщения, которые этот handler будут посылать.
• setFormatter() определяет объект Formatter, который будет использовать этот handler.
• addFilter() и removeFilter() соответственно добавляют и удаляют объекты фильтров из handler'a.

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

Formatter'ы

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

logging.Formatter.__init__(fmt=None, datefmt=None)

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

%Y-%m-%d %H:%M:%S

где миллисекунды присоединяются к концу строки.
Строка формата сообщения использует стиль подстановки %(<dictionary key>)s; возможные ключи указаны в LogRecord attributes.
Следующая строка формата отобразит сообщение в виде: ЧитаемоеВремя - УровеньСообщения - СамоСообщение:

'%(asctime)s - %(levelname)s - %(message)s'

Formatter'ы используют настраеваемую функцию для преобразования времени создания записи в кортеж. По умолчанию используется функция time.localtime(); для того, чтобы это изменить присвойте аттрибуту converter функцию с той же сигнатурой, что и у time.localtime() или time.gmtime(). Для того, чтобы изменить это для всех formatter'ов, например, если Вы хотите, чтобы время логирования отображалось в GMT, задайте атрибут converter класса Formatter (равным time.gmtime для отображения в GMT).

Настройка логирования

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

1. Явно создать logger'ы, handler'ы, and formatter'ы при помощи кода на Python, который вызывает методы конфигурации, о которых мы говорили выше.
2. Создать файл настройки и считать его функцией fileConfig().
3. Создать словрь с информацией конфигурации и передать его функции dictConfig().

Документацию последних двух вариантов Вы можете найти в Configuration functions. Следующие примеры настраивают очень простой logger, консаольный handler и простой formatter при помощи кода на Python:

import logging

# создаём logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# создаём консольный handler и задаём уровень
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# создаём formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# добавляем formatter в ch
ch.setFormatter(formatter)

# добавляем ch к logger
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 создаёт logger, handler и formatter, почти аналогичные примеру выше, отличие лишь в именах объектов:

import logging
import logging.config

logging.config.fileConfig('logging.conf')

# создаём logger
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

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

Предупреждение:

Функция fileConfig() принимает параметр по умолчанию disable_existing_loggers со значением True для обратной совместимости. Это может быть тем, что Вы хотите, или нет, так как из-за этого все уже существующие до вызова fileConfig() logger'ы будут деактивированы, если только они не перечислены в конфигурации. Более подробно смотрите документацию и при необходимости используйте в качестве значения параметра False.

Словарь, передаваемый в функцию dictConfig() может также определить логическое значение для ключа disable_existing_loggers, который, если не определён явно в этом словаре, получает значение по умолчанию True.

Обратите внимание, что имена классов в конфигурационном файле должны быть заданы либо относительно модуля логирования или абсолютно, так, что они могут быть разрешены обычным механизмом импорта. Таким образом, Вы можете использовать либо WatchedFileHandler (относительно модуля логирования) или mypackage.mymodule.MyHandler (для класса, определённого в пакете mypackage и модуля mymodule, где mypackage - доступный для импорта в Python).
В Python 2.7, была добавлена возможность конфигурирования логгинга с исполльзованием словаря. Это расширение функциональность подхода конфигурирования при помощи файла и он рекомендуется для новых приложений. Поскольку конфигурация хранится в словаре, а его можно заполнить разными способами, у Вас появляется множество способов настройки. Например, Вы можете использовать конфигурационный файл в формате JSON, или YAML. Или же Вы можете сконструировать словарь в коде Python, получить его через сокет в сериализованной форме (pickled), или использовать любой другой подход.
Вот пример тойже самой настройки в формате 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]

Более подробно по поводу логирования при помощи словаря описано в Configuration functions.

Что происходит, если конфигурация не задана

Если конфигурация логировани не задана, то может сложиться ситуация, в которой сообщение должно быть обработано, но для его вывода не найден ни один handler. Поведение модуля в таком случае будет зависеть от версии Python.
Для Python 2.x, поведение таково:

• Если logging.raiseExceptions = False (режим production), сообщение просто игнорируется.
• Если logging.raiseExceptions = True (режим development), будет один раз выведено сообщение ‘No handlers could be found for logger X.Y.Z’.

Конфигурирование логирования для библиотеки

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

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

даст желаемый Вам эффект. Если ваша организация разрабатывает несколько библиотек, то именем logger'a должно быть ‘orgname.foo’, а не просто ‘foo’.

Примечание
Очень рекомендуется не добавлять handler'ы, отличные от NullHandler в logger'ы вашей библиотеки по той причине, что конфигурация handler'ов является прерогативой разработчика приложения, который будет использовать вашу библиотеку. Разработчик приложения знает свою целевую аудиторию и какие handler'ы больше подходят для их целей. Если же Вы добавляете handler'ы "под капотом", Вы можете вмешаться в их способность  проходить юнит-тесты и добавить им проблем.

Уровни логирования

Числовые значения уровней логирования приведены ниже в таблице. В основном это интересно в случае, если Вы хотите объявить свой собственный уровень логирования и хотите придать им значения, относительно предопределённых уровней. Если Вы определите уровень с тем же числовым значением, он переопределит предопределённое значение и имя предопределённого значения будет потеряно.

Уровень	Числовое значение
CRITICAL	50
ERROR	40
WARNING	30
INFO	20
DEBUG	10
NOTSET	0

Уровни могут быть так же ассоциированны с logger'ами, будучи заданными либо разработчиком, либо загрузкой сохранённой конфигурации. Когда вызывается метод логирования, logger сравнивает свой уровень с уровнем, асооциированным с вызовом метода. Если уровень logger'a больше, чем у метода, то сообщение игнорируется. Это основной механизм контроля подробности логирования.
Сообщения кодируются экземляром класса LogRecord. Когда logger решает залогировать событие, из сообщения создаётся экземпляр LogRecord.
Сообщения отправляются через handler'ы, которые являются экземплярами подклассов класса Handler. Handler'ы отвечают за то, чтобы убедиться, что сообщение (в форме LogRecord) окажется в нужном месте (или наборе мест), что полезно для целевой аудиенции этого сообщения (таких как конечные пользователи, служба поддержки, системных администраторов, разработчиков). Handler'ы передают экзмепляры LogRecord в конктерное место назначения. Каждый logger может иметь 0 или больше ассоциированных handler'ов (при помощи метода addHandler() класса Logger). Кроме handler'a, напрямую связанного с logger'ом, все handler'ы, связанные с его предками так же вызываются для отправки сообщения (если только для logger флаг propagate не установлен в занчение false, так как в этом случае распространение сообщения будет остановлено на этом logger'е).
Как и logger'ы, handler'ы могут иметь ассоциированные с ними уровни. Уровень handler’а работает как фильтр так же, как уровень logger’а. Если handler решает переслать сообщение, то используется метод emit() для отправки сообщения по адресу. Большая часть пользовательских подклассов будет переопределять этот метод.

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

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

Полезные Handler'ы

В дополнении к базовому классу Handler, есть ещё много полезных дочерних классов:

1. StreamHandler посылает сообщения в потоки (файло-подобные объекты)
2. FileHandler посылает сообщения в файлы на диске.
3. BaseRotatingHandler - базовый класс handler'ов, которые ротируют файлы логов в определённый момент. Его не надо использовать непосредственно, вместо этого используйте RotatingFileHandler или TimedRotatingFileHandler.
4. RotatingFileHandler посылает сообщения в файлы на диске, с поддержкой максимального размера файла логов и ротиции файлов.
5. TimedRotatingFileHandler посылает сообщения в файл на диск и делает ротацию через некоторый временной интервал.
6. SocketHandler посылает сообщения через сокеты TCP/IP.
7. DatagramHandler посылает сообщения через UDP сокеты.
8. SMTPHandler посылает сообщения на определённый адрес электронной почты.
9. SysLogHandler посылает сообщения демону Unix syslog, возможно, на удалённой машине.
10. NTEventLogHandler посылает сообщения в Windows NT/2000/XP event log.
11. MemoryHandler посылает сообщения в буфер в памяти, который скидывается на диск при соответствии определённому критерию.
12. HTTPHandler посылает сообщения на HTTP сервер методами GET или POST.
13. WatchedFileHandler наблюдает за файлами, куда идёт логирование. Если файл изменяется, то он закрывается и открывается заново по имени файла. Полезен только на Unix-подобных системах; Windows не поддерживает нужного механизма.
14. NullHandler ничего не делает с сообщениями об ошибках. Он используется разработчиками библиотек, которые хотят исопльзовать логирование, но при этом избежать сообщений ‘No handlers could be found for logger XXX’, которые могут быть отображены, если пользователь библиотеки не настроил логирование. Более подробно смотрите в Configuring Logging for a Library.

Новое с версии 2.7: Класс NullHandler.

Классы NullHandler, StreamHandler и FileHandler определены в ядре пакета логирования. Другие handler'ы определены в подмодуле logging.handlers. (Есть ещё один подмодуль, logging.config, содержащий всё необходимое для конфигурирования.)
Сообщения форматируются для отображения экземплярами класса Formatter. Для их инициализции нужна строка формата, которую можно исопльзовать с оператором % и словарём.
Для форматирования нескольких сообщений сразу можно использовать экземпляры класса BufferingFormatter. Кроме строки формата (которая применяется к каждому сообщению в наборе) даются ещё и строки формата для заголовка и завершающего сообщения.Если фильтрование на уровне logger'a или handler'a не достаточно, можно добавить экземпляр Filter и к Logger и к Handler (при помощи их метода addFilter()). Перед тем, как решать, обрабатывать ли сообщение, logger'ы и handler'ы смотрят на свои фильтры для проверки разрешений. Если какой-либо фильтр возвращает значение false, то сообщение не будет обработано.
Базовая функциональность Filter позволяет отфильтровать сообщения по имени logger'а. Если это используется, то сообщения, посланные указанному logger'у или его потомкам пропускаются через фильтр, а все остальные игнорируются.

Исключения, возникающие во время логирования

Пакет логирования предназначен для поглощения исключений, которые возникают в работающем продукте. То есть, ошибки, которые возникают при обработке событий логирования, такие как проблемы с настройкой, сетью и т.п, не прерывают работу самого продукта.
Исключения SystemExit и KeyboardInterrupt никогда не поглощаются. Другие исключения, возникающие в методе emit() подкласса Handler передаются методу handleError().
Реализация по умолчанию handleError() в Handler проверяет, задана ли переменна уровня модуля raiseExceptions. Если она задана, то трассировка отображается в sys.stderr. Если нет - исключение поглощается.

Примечание

Значением по умолчанию raiseExceptions является True, потому что в процессе разработки Вы скорее всего хотите знать обо всех возникающих исключениях. В работающей уже библиотеке рекомендуется установить в качестве значения raiseExceptions False.

Использование произвольных объектов в качестве сообщений

В предыдущих разделах и примерах мы подразумевали, что в качестве сообщения передаётся строка. Однако, можно передать любой объект, у которого будет вызван метод __str__(), когда его потребуется преобразовать в строку. На самом деле, если Вы хотите, Вы можете даже избежать перевода объекта в строковое преобразование, например, SocketHandler посылает событие сериализуя его и отправляя по сети.

Оптимизация

Форматирование аргументов сообщения происходит как можно позже, когда его уже нельзя избежать. Однако, вычисление аргументов, переданных методу логирования может стоить дорого и Вы можете хотеть избежать этого, особенно в случае если сообщение будет просто отброшено. Для этого Вы можете использовать метод isEnabledFor(), который принимает в качестве аргумента уровень и возвращает true, если событие будет обработано logger'ом для этого уровня. Код может быть такой:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug('Message with %s, %s', expensive_func1(),
                                        expensive_func2())

так что если порог logger’а выше, чем DEBUG, вызовы expensive_func1() и expensive_func2() не будут произведены.

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

Чего Вы не хотите собирать	Как этого избежать
Информацию о том, где был сделан вызов	logging._srcfile = None.
Информацию о потоках	logging.logThreads = 0.
Информацию о процессах	logging.logProcesses = 0.

Обратите внимание, что ядро модуля логирования содержит только основные handler'ы. Если Вы не импортируете logging.handlers и logging.config, они не будут занимать память.