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

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

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

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

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

Модуль Logging

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

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

import logging

С импортированным модулем logging вы можете использовать то, что называется «logger», для логирования сообщений, которые вы хотите видеть. По умолчанию существует 5 стандартных уровней severity, указывающих на важность событий. У каждого есть соответствующий метод, который можно использовать для логирования событий на выбранном уровне severity. Список уровней в порядке увеличения важности:

• DEBUG
• INFO
• WARNING
• ERROR
• CRITICAL

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

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

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

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

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

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

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

• level: Корневой логер с установленным указанным уровнем важности (severity).
• filename: Указание файла логов
• filemode: Режим открытия файла. По умолчанию это a, что означает добавление.
• format: Формат сообщений.

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

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 вместо вывода в консоль. Для filemode значение w означает, что файл журнала открывается в «режиме записи» каждый раз, когда вызывается basicConfig(), и при каждом запуске программы файл перезаписывается. Конфигурацией по умолчанию для filemode является a, которое является добавлением.

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

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

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

Формат вывода

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

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

Вы можете найти больше информации о формате datetime в этом руководстве.

Логирование переменных

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

import logging

name = 'John'

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

ERROR:root:John raised an error

Аргументы, передаваемые методу, будут включены в сообщение в качестве переменных.

Хотя вы можете использовать любой стиль форматирования, f-строки, представленные в Python 3.6, являются лучшим способом форматирования строк, поскольку они могут помочь сделать форматирование коротким и легким для чтения:

import logging

name = 'John'

logging.error(f'{name} raised an error')

ERROR:root:John raised an error

Вывод стека

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

Совет: если вы логируете в обработчике исключений (try..except…), используйте метод 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.

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

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

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

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

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

import logging

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

This is a warning

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

WARNING:example_logger:This is a warning

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

Использование Handlers

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

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

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

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

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

[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, один обработчик и один форматер. После того, как определены их имена, они настраиваются путем добавления слов logger, handler и formatter перед их именами, разделенными подчеркиванием.

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

import logging
import logging.config

logging.config.fileConfig(fname='file.conf', 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 используется для сохранения или отключения logger, которые присутствуют при вызове функции. По умолчанию установлено значение True, если не упомянуто.

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

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

Заключение

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

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

Оригинальная статья: Abhinav Ajitsaria  Logging in Python