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

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

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

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

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

Если ваши потребности в логгировании простые, то воспользуйтесь приведенными выше примерами для включения логгирования в свои скрипты, а если вы столкнетесь с проблемами или что-то не поймете, задайте вопрос на Usenet-группе comp.lang.python (доступно по адресу 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.addFilter() и Logger.removeFilter() добавляют и удаляют объекты фильтров из объекта логгера. Фильтры более подробно рассматриваются в Объекты фильтров.

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

После того, как объект логгера сконфигурирован, следующие методы создают сообщения логов:

• Logger.debug(), Logger.info(), Logger.warning(), Logger.error() и Logger.critical() все создают записи логов с сообщением и уровнем, соответствующим их именам методов. Сообщение фактически представляет собой строку формата, которая может содержать стандартную синтаксис подстановки строк %s, %d, %f, и так далее. Остальные аргументы – список объектов, соответствующих полям подстановки в сообщении. Что касается **kwargs, методы ведения логов заботятся только о ключевом слове exc_info и используют его, чтобы определить, нужно ли регистрировать информацию об исключении.
• Logger.exception() создаёт сообщение лога, аналогичное Logger.error(). Разница в том, что Logger.exception() выводит трассировку стека вместе с ним. Вызывайте этот метод только из обработчика исключений.
• Logger.log() принимает уровень лога в качестве явного аргумента. Это немного более подробный способ регистрации сообщений, чем использование удобных методов уровня лога, перечисленных выше, но это способ регистрации на пользовательских уровнях логов.

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

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

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

Обработчики

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

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

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

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

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

Форматизаторы

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

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

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

1. Создать логгеры, обработчики и форматизаторы явно с помощью кода Python, вызывающего методы конфигурации, перечисленные выше.
2. Создать файл конфигурации логгирования и прочитать его с помощью функции fileConfig().
3. Создать словарь с информацией о конфигурации и передать его функции dictConfig().

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

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Запуск этого модуля из командной строки приводит к следующему выводу:

$ python simple_logging_module.py
2005-03-19 15:10:26,618 - simple_example - DEBUG - debug message
2005-03-19 15:10:26,620 - simple_example - INFO - info message
2005-03-19 15:10:26,695 - simple_example - WARNING - warn message
2005-03-19 15:10:26,697 - simple_example - ERROR - error message
2005-03-19 15:10:26,773 - simple_example - CRITICAL - critical message

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

import logging
import logging.config

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

# create logger
logger = logging.getLogger('simpleExample')

# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')

Вот файл logging.conf:

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

Вывод практически идентичен выводу примера без файла конфигурации:

$ python simple_logging_config.py
2005-03-19 15:38:55,977 - simpleExample - DEBUG - debug message
2005-03-19 15:38:55,979 - simpleExample - INFO - info message
2005-03-19 15:38:56,054 - simpleExample - WARNING - warn message
2005-03-19 15:38:56,055 - simpleExample - ERROR - error message
2005-03-19 15:38:56,130 - simpleExample - CRITICAL - critical message

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

Обратите внимание, что имена классов, упомянутые в файлах конфигурации, должны быть либо относительными к модулю logging, либо абсолютными значениями, которые можно разрешить с помощью обычных механизмов импорта. Таким образом, вы можете использовать либо WatchedFileHandler (относительно модуля logging), либо mypackage.mymodule.MyHandler (для класса, определённого в пакете mypackage и модуле mymodule, где mypackage доступен в пути импорта Python).

В Python 3.2 был представлен новый способ настройки логгирования, использующий словари для хранения информации о конфигурации. Это обеспечивает расширенный функционал по сравнению с подходом на основе файла конфигурации, описанным выше, и является рекомендуемым методом конфигурации для новых приложений и развертываний. Так как используется словарь Python для хранения информации о конфигурации, и вы можете заполнять его различными способами, у вас больше вариантов для конфигурации. Например, вы можете использовать файл конфигурации в формате JSON или, если у вас есть доступ к функциональности обработки YAML, файл в формате YAML для заполнения словаря конфигурации. Или, конечно, вы можете создать словарь в коде Python, получить его в сериализованном виде по сокету или использовать любой подход, который имеет смысл для вашего приложения.

Вот пример той же конфигурации, что и выше, в формате YAML для нового подхода на основе словарей:

version: 1
formatters:
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout
loggers:
  simpleExample:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

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

Что происходит при отсутствии конфигурации

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

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

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

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

должен иметь желаемый эффект. Если организация создаёт несколько библиотек, то указанное имя логгера может быть ‘orgname.foo’, а не только ‘foo’.

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

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