Логирование в Python

Оглавление

• Модуль ведения журнала
• Базовые конфигурации
• Форматирование вывода
  • Регистрация переменных данных
  • Захват трасс стека
• Классы и функции
• Использование обработчиков
• Другие методы конфигурации
• Сохраняйте спокойствие и читайте журналы

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

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

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

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

Модуль ведения журнала

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

Добавить протоколирование в вашу программу на Python очень просто:

import logging

Импортировав модуль logging, вы можете использовать нечто, называемое "logger", для регистрации сообщений, которые вы хотите видеть. По умолчанию существует 5 стандартных уровней, определяющих степень серьезности событий. Каждый из них имеет соответствующую функцию, которая может быть использована для регистрации событий данного уровня серьезности. Определенные уровни, в порядке возрастания серьезности, следующие:

• DEBUG
• INFO
• WARNING
• ERROR
• CRITICAL

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

import logging

logging.debug('This is a debug message')
logging.info('This is an info message')
logging.warning('This is a warning message')
logging.error('This is an error message')
logging.critical('This is a critical message')

Вывод приведенной выше программы будет выглядеть следующим образом:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

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

Заметьте, что сообщения debug() и info() не были зарегистрированы. Это потому, что по умолчанию модуль регистрации регистрирует сообщения с уровнем серьезности WARNING и выше. При желании это можно изменить, настроив модуль регистрации на регистрацию событий всех уровней. Вы также можете определить свои собственные уровни серьезности, изменив конфигурацию, но обычно это не рекомендуется, так как это может привести к путанице с журналами некоторых сторонних библиотек, которые вы можете использовать.

Базовые конфигурации

Вы можете использовать функцию basicConfig(**kwargs) для настройки протоколирования:

"Вы заметите, что модуль протоколирования нарушает правила стиля PEP8 и использует соглашения об именовании camelCase. Это связано с тем, что он был заимствован из Log4j, утилиты ведения логов в Java. Это известная проблема в пакете, но к тому времени, когда было решено добавить его в стандартную библиотеку, он уже был принят пользователями, и его изменение для соответствия требованиям PEP8 привело бы к проблемам обратной совместимости." (Источник)

Некоторые из часто используемых параметров для basicConfig() следующие:

• level: Корневой регистратор будет установлен на указанный уровень серьезности.
• filename: Указывается файл.
• filemode: Если указано filename, файл открывается в этом режиме. По умолчанию используется a, что означает append.
• format: Это формат сообщения журнала.

С помощью параметра level можно установить, на каком уровне будут записываться сообщения журнала. Это можно сделать, передав одну из констант, доступных в классе, что позволит записывать в журнал все вызовы, находящиеся на этом уровне или выше. Вот пример:

import logging

logging.basicConfig(level=logging.DEBUG)
logging.debug('This will get logged')

DEBUG:root:This will get logged

Все события на уровне DEBUG или выше теперь будут регистрироваться.

Аналогично, для записи в файл, а не в консоль, можно использовать filename и filemode, а формат сообщения можно определить с помощью format. В следующем примере показано использование всех трех вариантов:

import logging

logging.basicConfig(filename='app.log', filemode='w', format='%(name)s - %(levelname)s - %(message)s')
logging.warning('This will get logged to a file')

root - ERROR - This will get logged to a file

Сообщение будет выглядеть примерно так, но вместо консоли оно будет записано в файл с именем app.log. Режим файла установлен на w, что означает, что файл журнала открывается в "режиме записи" каждый раз, когда вызывается basicConfig(), и каждый запуск программы будет перезаписывать файл. По умолчанию для режима filemode установлено значение a, то есть append.

Вы можете настроить корневой логгер еще больше, используя дополнительные параметры для basicConfig(), которые можно найти здесь.

Следует отметить, что вызов basicConfig() для конфигурирования корневого регистратора работает только в том случае, если корневой регистратор не был сконфигурирован ранее. По сути, эта функция может быть вызвана только один раз.

debug(), info(), warning(), error() и critical() также автоматически вызывают basicConfig() без аргументов, если он не был вызван ранее. Это означает, что после первого вызова одной из вышеперечисленных функций вы больше не сможете настроить корневой регистратор, так как они будут вызывать функцию basicConfig() изнутри.

По умолчанию в basicConfig() задано, чтобы логгер писал на консоль в следующем формате:

ERROR:root:This is an error message

Форматирование вывода

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

import logging

logging.basicConfig(format='%(process)d-%(levelname)s-%(message)s')
logging.warning('This is a Warning')

18472-WARNING-This is a Warning

format может принимать строку с атрибутами LogRecord в любом удобном для вас порядке. Весь список доступных атрибутов можно найти здесь.

Вот еще один пример, в котором можно добавить информацию о дате и времени:

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', level=logging.INFO)
logging.info('Admin logged in')

2018-07-11 20:12:06,288 - Admin logged in

%(asctime)s добавляет время создания LogRecord. Формат может быть изменен с помощью атрибута datefmt, который использует тот же язык форматирования, что и функции форматирования в модуле datetime, например time.strftime():

import logging

logging.basicConfig(format='%(asctime)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')
logging.warning('Admin logged out')

12-Jul-18 20:53:19 - Admin logged out

Вы можете найти руководство здесь.

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

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

import logging

name = 'John'

logging.error('%s raised an error', name)

ERROR:root: John raised an error

В этом примере в качестве первого аргумента передается строка "%s raised an error". в logging.error(). В строке используется заполнитель %s, который позволяет Python интерполировать строковое значение на его место.

В качестве второго аргумента передается значение переменной, name, которое logging.error() будет интерполировано в строку сообщения.

Лучше использовать этот подход, чем форматировать строку отдельно, например, с помощью f-string, а затем передавать ее в функцию протоколирования.

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

Захват трасс стека

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

import logging

a = 5
b = 0

try:
  c = a / b
except Exception as e:
  logging.error("Exception occurred", exc_info=True)

ERROR:root:Exception occurred
Traceback (most recent call last):
  File "exceptions.py", line 6, in <module>
    c = a / b
ZeroDivisionError: division by zero
[Finished in 0.2s]

Если exc_info не установлен в True, вывод приведенной выше программы ничего не скажет нам об исключении, которое в реальном сценарии может быть не таким простым, как ZeroDivisionError. Представьте, что вы пытаетесь отладить ошибку в сложной кодовой базе с журналом, который показывает только это:

ERROR:root:Exception occurred

Вот небольшой совет: если вы ведете журнал из обработчика исключений, используйте функцию logging.exception(), которая регистрирует сообщение с уровнем ERROR и добавляет к нему информацию об исключении. Проще говоря, вызов logging.exception() аналогичен вызову logging.error(exc_info=True). Но поскольку эта функция всегда сбрасывает информацию об исключениях, ее следует вызывать только из обработчика исключений. Посмотрите на этот пример:

import logging

a = 5
b = 0
try:
  c = a / b
except Exception as e:
  logging.exception("Exception occurred")

ERROR:root:Exception occurred
Traceback (most recent call last):
  File "exceptions.py", line 6, in <module>
    c = a / b
ZeroDivisionError: division by zero
[Finished in 0.2s]

При использовании logging.exception() будет показан журнал на уровне ERROR. Если вам это не нужно, вы можете вызвать любую из других функций ведения журнала от debug() до critical() и передать параметр exc_info как True.

Классы и функции

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

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

• Logger: Это класс, объекты которого будут использоваться в коде приложения непосредственно для вызова функций.

• LogRecord: Логгеры автоматически создают LogRecord объекты, которые содержат всю информацию, связанную с регистрируемым событием, такую как имя логгера, функция, номер строки, сообщение и многое другое.

• Handler: Обработчики отправляют LogRecord в нужное место вывода, например на консоль или в файл. Handler является базой для таких подклассов, как StreamHandler, FileHandler, SMTPHandler, HTTPHandler и других. Эти подклассы отправляют результаты протоколирования в соответствующие места назначения, такие как sys.stdout или дисковый файл.

• Formatter: Здесь задается формат вывода путем указания строкового формата, в котором перечислены атрибуты, которые должен содержать вывод.

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

import logging

logger = logging.getLogger('example_logger')
logger.warning('This is a warning')

This is a warning

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

WARNING:example_logger:This is a warning

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

"Рекомендуется использовать логгеры на уровне модуля, передавая __name__ в качестве параметра name в getLogger() для создания объекта логгера, так как имя самого логгера подскажет нам, откуда регистрируются события. __name__ - это специальная встроенная переменная в Python, которая оценивается как имя текущего модуля." (Источник)

Использование обработчиков

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

Созданный вами логгер может иметь более одного обработчика, что означает, что вы можете настроить его на сохранение в файл журнала, а также на отправку по электронной почте.

Как и в логгерах, в обработчиках можно задавать уровень серьезности. Это полезно, если вы хотите установить несколько обработчиков для одного и того же логгера, но для каждого из них нужны разные уровни серьезности. Например, вы можете захотеть, чтобы логи с уровнем WARNING и выше записывались в консоль, но все, что с уровнем ERROR и выше, должно также сохраняться в файл. Вот программа, которая это делает:

# logging_example.py

import logging

# Create a custom logger
logger = logging.getLogger(__name__)

# Create handlers
c_handler = logging.StreamHandler()
f_handler = logging.FileHandler('file.log')
c_handler.setLevel(logging.WARNING)
f_handler.setLevel(logging.ERROR)

# Create formatters and add it to handlers
c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
c_handler.setFormatter(c_format)
f_handler.setFormatter(f_format)

# Add handlers to the logger
logger.addHandler(c_handler)
logger.addHandler(f_handler)

logger.warning('This is a warning')
logger.error('This is an error')

__main__ - WARNING - This is a warning
__main__ - ERROR - This is an error

Здесь logger.warning() создает LogRecord, в котором хранится вся информация о событии, и передает его всем обработчикам, которые у него есть: c_handler и f_handler.

c_handler является StreamHandler с уровнем WARNING и получает информацию от LogRecord для создания вывода в заданном формате и печати его на консоль. f_handler - это FileHandler с уровнем ERROR, и он игнорирует этот LogRecord, так как его уровень WARNING.

При вызове logger.error() c_handler ведет себя точно так же, как и раньше, а f_handler получает LogRecord на уровне ERROR, поэтому переходит к генерации вывода, как и c_handler, но вместо печати на консоль записывает его в указанный файл в таком формате:

2018-08-03 16:12:21,723 - __main__ - ERROR - This is an error

Имя регистратора, соответствующее переменной __name__, регистрируется как __main__, что является именем, которое Python присваивает модулю, с которого начинается выполнение. Если этот файл импортируется каким-то другим модулем, то переменная __name__ будет соответствовать его имени logging_example. Вот как это будет выглядеть:

# run.py

import logging_example

logging_example - WARNING - This is a warning
logging_example - ERROR - This is an error

Другие методы конфигурирования

Вы можете настроить ведение журнала, как показано выше, используя функции модуля и класса или создав файл конфигурации или словарь и загрузив его с помощью fileConfig() или dictConfig() соответственно. Это удобно в том случае, если вы хотите изменить конфигурацию протоколирования в работающем приложении.

Вот пример конфигурации файла:

config.ini

[loggers]
keys=root,sampleLogger

[handlers]
keys=consoleHandler

[formatters]
keys=sampleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_sampleLogger]
level=DEBUG
handlers=consoleHandler
qualname=sampleLogger
propagate=0

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

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

В приведенном выше файле есть два логгера, один обработчик и один форматер. После того как их имена определены, они конфигурируются путем добавления слов logger, handler и formatter перед их именами, разделенных знаком подчеркивания.

Чтобы загрузить этот файл конфигурации, нужно использовать fileConfig():

import logging
import logging.config

logging.config.fileConfig(fname='config.ini', disable_existing_loggers=False)

# Get the logger specified in the file
logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

2018-07-13 13:57:45,467 - __main__ - DEBUG - This is a debug message

Путь к файлу конфигурации передается в качестве параметра функции fileConfig(), а параметр disable_existing_loggers используется для сохранения или отключения логгеров, которые присутствуют на момент вызова функции. По умолчанию он принимает значение True, если не указан.

Вот та же конфигурация в формате 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:
  sampleLogger:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

Вот пример, показывающий, как загрузить конфигурацию из yaml файла:

import logging
import logging.config
import yaml

with open('config.yaml', 'r') as f:
    config = yaml.safe_load(f.read())
    logging.config.dictConfig(config)

logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

2018-07-13 14:05:03,766 - __main__ - DEBUG - This is a debug message

Сохраняйте спокойствие и читайте журналы

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

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

Вернуться на верх