Ведение журнала HOWTO¶

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

Logging предоставляет набор удобных функций для простого ведения журнала. Это 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. Распечатанное сообщение включает указание уровня и описание события, предоставленное в вызове протоколирования, т.е. «Осторожно!». Не беспокойтесь пока о части „root“: она будет объяснена позже. Фактический вывод можно отформатировать достаточно гибко, если вам это нужно; варианты форматирования также будут описаны позже.

Ведение журнала в файл¶

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

import logging
logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
logging.debug('This message should go to the log file')
logging.info('So should this')
logging.warning('And this, too')
logging.error('And non-ASCII stuff, too, like Øresund and Malmö')

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

DEBUG:root:This message should go to the log file
INFO:root:So should this
WARNING:root:And this, too
ERROR:root: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() и т.д. В противном случае эти функции вызовут basicConfig() для вас с опциями по умолчанию. Поскольку эта функция предназначена для одноразовой простой настройки, только первый вызов будет действительно что-то делать: последующие вызовы фактически не работают.

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

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

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

Ведение журнала из нескольких модулей¶

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

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

Регистрация переменных данных¶

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

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

будет отображаться:

WARNING:root:Look before you leap!

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

Изменение формата отображаемых сообщений¶

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

import logging
logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.debug('This message should appear on the console')
logging.info('So should this')
logging.warning('And this, too')

который будет печатать:

DEBUG:This message should appear on the console
INFO:So should this
WARNING:And this, too

Обратите внимание, что „root“, который появлялся в предыдущих примерах, исчез. За полным набором вещей, которые могут появляться в строках формата, вы можете обратиться к документации по Атрибуты LogRecord, но для простого использования вам нужны только levelname (серьезность), message (описание события, включая данные переменных) и, возможно, отображение времени, когда произошло событие. Это описано в следующем разделе.

Отображение даты/времени в сообщениях¶

Чтобы отобразить дату и время события, вы поместите „%(asctime)s“ в строку формата:

import logging
logging.basicConfig(format='%(asctime)s %(message)s')
logging.warning('is when this event was logged.')

который должен вывести что-то вроде этого:

2010-12-12 11:41:42,612 is when this event was logged.

Формат по умолчанию для отображения даты/времени (показан выше) похож на ISO8601 или RFC 3339. Если вам нужно больше контроля над форматированием даты/времени, предоставьте аргумент datefmt в basicConfig, как в этом примере:

import logging
logging.basicConfig(format='%(asctime)s %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p')
logging.warning('is when this event was logged.')

в результате чего на экране появится что-то вроде этого:

12/12/2010 11:46:36 AM is when this event was logged.

Формат аргумента datefmt такой же, как поддерживается time.strftime().

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

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

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

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

Поток регистрации¶

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

Регистраторы¶

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

Наиболее широко используемые методы на объектах регистратора делятся на две категории: конфигурирование и отправка сообщений.

Это наиболее распространенные методы настройки:

• Logger.setLevel() задает наименьшую степень серьезности сообщения журнала, которое будет обрабатывать регистратор, где debug - это самый низкий встроенный уровень серьезности, а critical - самый высокий встроенный уровень серьезности. Например, если уровень серьезности равен INFO, регистратор будет обрабатывать только сообщения INFO, WARNING, ERROR и CRITICAL и будет игнорировать сообщения DEBUG.

• Logger.addHandler() и Logger.removeHandler() добавляют и удаляют объекты обработчиков из объекта logger. Более подробно обработчики рассматриваются в Обработчики.

• Logger.addFilter() и Logger.removeFilter() добавляют и удаляют объекты фильтров из объекта регистратора. Более подробно фильтры рассматриваются в Фильтр объектов.

Вам не нужно всегда вызывать эти методы для каждого создаваемого вами регистратора. См. последние два абзаца в этом разделе.

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

У регистраторов есть понятие эффективный уровень. Если уровень явно не задан в логгере, то в качестве эффективного уровня используется уровень его родителя. Если родитель не имеет явно заданного уровня, то рассматривается его родитель, и так далее - все предки перебираются до тех пор, пока не будет найден явно заданный уровень. Корневой регистратор всегда имеет явно заданный уровень (по умолчанию WARNING). При принятии решения об обработке события эффективный уровень регистратора используется для определения того, будет ли событие передано обработчикам регистратора.

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

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

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

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

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

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

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

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

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

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

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

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, в основном разделение конфигурации и кода и возможность для не-кодеров легко изменять свойства протоколирования.

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

Более подробную информацию о ведении журнала с использованием словаря см. в разделе Функции конфигурации.

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

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

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

При разработке библиотеки, использующей протоколирование, необходимо позаботиться о документировании того, как библиотека использует протоколирование - например, имена используемых протоколирующих устройств. Также необходимо уделить внимание конфигурации протоколирования. Если использующее приложение не использует протоколирование, а код библиотеки выполняет вызовы протоколирования, то (как описано в предыдущем разделе) события со степенью серьезности WARNING и выше будут выводиться в sys.stderr. Это считается лучшим поведением по умолчанию.

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

Обработчик do-nothing включен в пакет logging: NullHandler (начиная с Python 3.1). Экземпляр этого обработчика может быть добавлен в логгер верхнего уровня пространства имен логгирования, используемого библиотекой (если вы хотите предотвратить вывод регистрируемых событий вашей библиотеки в sys.stderr при отсутствии конфигурации логгирования). Если все логирование библиотеки foo выполняется с помощью логгеров с именами, совпадающими с „foo.x“, „foo.x.y“ и т.д., то код:

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

должно привести к желаемому результату. Если организация выпускает несколько библиотек, то указанное имя регистратора может быть „orgname.foo“, а не просто „foo“.

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

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