Руководство по ведению логов

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

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

Если вы запустите вышеуказанный скрипт несколько раз, сообщения из последующих запусков будут добавлены в файл 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

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

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

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

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

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

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