Сталкивались ли вы с трудностями при отладке Python-кода? Если это так — то изучение того, как наладить логирование (журналирование, logging) в Python, способно помочь вам упростить задачи, решаемые при отладке.
Если вы — новичок, то вы, наверняка, привыкли пользоваться командой print()
, выводя с её помощью определённые значения в ходе работы программы, проверяя, работает ли код так, как от него ожидается. Использование print()
вполне может оправдать себя при отладке маленьких Python-программ. Но, когда вы перейдёте к более крупным и сложным проектам, вам понадобится постоянный журнал, содержащий больше информации о поведении вашего кода, помогающий вам планомерно отлаживать и отслеживать ошибки.
Из этого учебного руководства вы узнаете о том, как настроить логирование в Python, используя встроенный модуль logging
. Вы изучите основы логирования, особенности вывода в журналы значений переменных и исключений, разберётесь с настройкой собственных логгеров, с форматировщиками вывода и со многим другим.
Вы, кроме того, узнаете о том, как Sentry Python SDK способен помочь вам в мониторинге приложений и в упрощении рабочих процессов, связанных с отладкой кода. Платформа Sentry обладает нативной интеграцией со встроенным Python-модулем logging
, и, кроме того, предоставляет подробную информацию об ошибках приложения и о проблемах с производительностью, которые в нём возникают.
Начало работы с Python-модулем logging
В Python имеется встроенный модуль logging
, применяемый для решения задач логирования. Им мы будем пользоваться в этом руководстве. Первый шаг к профессиональному логированию вы можете выполнить прямо сейчас, импортировав этот модуль в своё рабочее окружение.
import logging
Встроенный модуль логирования Python даёт нам простой в использовании функционал и предусматривает пять уровней логирования. Чем выше уровень — тем серьёзнее неприятность, о которой сообщает соответствующая запись. Самый низкий уровень логирования — это debug (10)
, а самый высокий — это critical (50)
.
Дадим краткие характеристики уровней логирования:
-
Debug (10)
: самый низкий уровень логирования, предназначенный для отладочных сообщений, для вывода диагностической информации о приложении. -
Info (20)
: этот уровень предназначен для вывода данных о фрагментах кода, работающих так, как ожидается. -
Warning (30)
: этот уровень логирования предусматривает вывод предупреждений, он применяется для записи сведений о событиях, на которые программист обычно обращает внимание. Такие события вполне могут привести к проблемам при работе приложения. Если явно не задать уровень логирования — по умолчанию используется именноwarning
. -
Error (40)
: этот уровень логирования предусматривает вывод сведений об ошибках — о том, что часть приложения работает не так как ожидается, о том, что программа не смогла правильно выполниться. -
Critical (50)
: этот уровень используется для вывода сведений об очень серьёзных ошибках, наличие которых угрожает нормальному функционированию всего приложения. Если не исправить такую ошибку — это может привести к тому, что приложение прекратит работу.
В следующем фрагменте кода показано использование вышеперечисленных уровней логирования при выводе нескольких сообщений. Здесь используется синтаксическая конструкция logging.<level>(<message>)
.
logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")
Ниже приведён результат выполнения этого кода. Как видите, сообщения, выведенные с уровнями логирования warning
, error
и critical
, попадают в консоль. А сообщения с уровнями debug
и info
— не попадают.
WARNING:root:A WARNING
ERROR:root:An ERROR
CRITICAL:root:A message of CRITICAL severity
Это так из-за того, что в консоль выводятся лишь сообщения с уровнями от warning
и выше. Но это можно изменить, настроив логгер и указав ему, что в консоль надо выводить сообщения, начиная с некоего, заданного вами, уровня логирования.
Подобный подход к логированию, когда данные выводятся в консоль, не особо лучше использования print()
. На практике может понадобиться записывать логируемые сообщения в файл. Этот файл будет хранить данные и после того, как работа программы завершится. Такой файл можно использовать в качестве журнала отладки.
Обратите внимание на то, что в примере, который мы будем тут разбирать, весь код находится в файле main.py
. Когда мы производим рефакторинг существующего кода или добавляем новые модули — мы сообщаем о том, в какой файл (имя которого построено по схеме <module-name>.py
) попадает новый код. Это поможет вам воспроизвести у себя то, о чём тут идёт речь.
Логирование в файл
Для того чтобы настроить простую систему логирования в файл — можно воспользоваться конструктором basicConfig()
. Вот как это выглядит:
logging.basicConfig(level=logging.INFO, filename="py_log.log",filemode="w")
logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")
Поговорим о логгере root
, рассмотрим параметры basicConfig()
:
-
level
: это — уровень, на котором нужно начинать логирование. Если он установлен вinfo
— это значит, что все сообщения с уровнемdebug
игнорируются. -
filename
: этот параметр указывает на объект обработчика файла. Тут можно указать имя файла, в который нужно осуществлять логирование. -
filemode
: это — необязательный параметр, указывающий режим, в котором предполагается работать с файлом журнала, заданным параметромfilename
. Установкаfilemode
в значениеw
(write, запись) приводит к тому, что логи перезаписываются при каждом запуске модуля. По умолчанию параметрfilemode
установлен в значениеa
(append, присоединение), то есть — в файл будут попадать записи из всех сеансов работы программы.
После выполнения модуля main
можно будет увидеть, что в текущей рабочей директории был создан файл журнала, py_log.log
.
Так как мы установили уровень логирования в значение info
— в файл попадут записи с уровнем info
и с более высокими уровнями.
Записи в лог-файле имеют формат <logging-level>:<name-of-the-logger>:<message>
. По умолчанию <name-of-the-logger>
, имя логгера, установлено в root
, так как мы пока не настраивали пользовательские логгеры.
Помимо базовой информации, выводимой в лог, может понадобится снабдить записи отметками времени, указывающими на момент вывода той или иной записи. Это упрощает анализ логов. Сделать это можно, воспользовавшись параметром конструктора format
:
logging.basicConfig(level=logging.INFO, filename="py_log.log",filemode="w",
format="%(asctime)s %(levelname)s %(message)s")
logging.debug("A DEBUG Message")
logging.info("An INFO")
logging.warning("A WARNING")
logging.error("An ERROR")
logging.critical("A message of CRITICAL severity")
Существуют и многие другие атрибуты записи лога, которыми можно воспользоваться для того чтобы настроить внешний вид сообщений в лог-файле. Настраивая поведение логгера root
— так, как это показано выше, проследите за тем, чтобы конструктор logging.basicConfig()
вызывался бы лишь один раз. Обычно это делается в начале программы, до использования команд логирования. Последующие вызовы конструктора ничего не изменят — если только не установить параметр force
в значение True
.
Логирование значений переменных и исключений
Модифицируем файл main.py
. Скажем — тут будут две переменных — x
и y
, и нам нужно вычислить значение выражения x/y
. Мы знаем о том, что при y=0
мы столкнёмся с ошибкой ZeroDivisionError
. Обработать эту ошибку можно в виде исключения с использованием блока try/except
.
Далее — нужно залогировать исключение вместе с данными трассировки стека. Чтобы это сделать — можно воспользоваться logging.error(message, exc_info=True)
. Запустите следующий код и посмотрите на то, как в файл попадают записи с уровнем логирования info
, указывающие на то, что код работает так, как ожидается.
x = 3
y = 4
logging.info(f"The values of x and y are {x} and {y}.")
try:
x/y
logging.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
logging.error("ZeroDivisionError",exc_info=True)
Теперь установите значение y
в 0
и снова запустите модуль.
Исследуя лог-файл py_log.log
, вы увидите, что сведения об исключении были записаны в него вместе со стек-трейсом.
x = 4
y = 0
logging.info(f"The values of x and y are {x} and {y}.")
try:
x/y
logging.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
logging.error("ZeroDivisionError",exc_info=True)
Теперь модифицируем код так, чтобы в нём имелись бы списки значений x
и y
, для которых нужно вычислить коэффициенты x/y
. Для логирования исключений ещё можно воспользоваться конструкцией logging.exception(<message>)
.
x_vals = [2,3,6,4,10]
y_vals = [5,7,12,0,1]
for x_val,y_val in zip(x_vals,y_vals):
x,y = x_val,y_val
logging.info(f"The values of x and y are {x} and {y}.")
try:
x/y
logging.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
logging.exception("ZeroDivisionError")
Сразу после запуска этого кода можно будет увидеть, что в лог-файл попала информация и о событиях успешного вычисления коэффициента, и об ошибке, когда возникло исключение.
Настройка логирования с помощью пользовательских логгеров, обработчиков и форматировщиков
Отрефакторим код, который у нас уже есть. Объявим функцию test_division
.
def test_division(x,y):
try:
x/y
logger2.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
logger2.exception("ZeroDivisionError")
Объявление этой функции находится в модуле test_div
. В модуле main
будут лишь вызовы функций. Настроим пользовательские логгеры в модулях main
и test_div
, проиллюстрировав это примерами кода.
Настройка пользовательского логгера для модуля test_div
import logging
logger2 = logging.getLogger(__name__)
logger2.setLevel(logging.INFO)
# настройка обработчика и форматировщика для logger2
handler2 = logging.FileHandler(f"{__name__}.log", mode='w')
formatter2 = logging.Formatter("%(name)s %(asctime)s %(levelname)s %(message)s")
# добавление форматировщика к обработчику
handler2.setFormatter(formatter2)
# добавление обработчика к логгеру
logger2.addHandler(handler2)
logger2.info(f"Testing the custom logger for module {__name__}...")
def test_division(x,y):
try:
x/y
logger2.info(f"x/y successful with result: {x/y}.")
except ZeroDivisionError as err:
logger2.exception("ZeroDivisionError")
Настройка пользовательского логгера для модуля main
import logging
from test_div import test_division
# получение пользовательского логгера и установка уровня логирования
py_logger = logging.getLogger(__name__)
py_logger.setLevel(logging.INFO)
# настройка обработчика и форматировщика в соответствии с нашими нуждами
py_handler = logging.FileHandler(f"{__name__}.log", mode='w')
py_formatter = logging.Formatter("%(name)s %(asctime)s %(levelname)s %(message)s")
# добавление форматировщика к обработчику
py_handler.setFormatter(py_formatter)
# добавление обработчика к логгеру
py_logger.addHandler(py_handler)
py_logger.info(f"Testing the custom logger for module {__name__}...")
x_vals = [2,3,6,4,10]
y_vals = [5,7,12,0,1]
for x_val,y_val in zip(x_vals,y_vals):
x,y = x_val, y_val
# вызов test_division
test_division(x,y)
py_logger.info(f"Call test_division with args {x} and {y}")
Разберёмся с тем, что происходит коде, где настраиваются пользовательские логгеры.
Сначала мы получаем логгер и задаём уровень логирования. Команда logging.getLogger(name)
возвращает логгер с заданным именем в том случае, если он существует. В противном случае она создаёт логгер с заданным именем. На практике имя логгера устанавливают с использованием специальной переменной name
, которая соответствует имени модуля. Мы назначаем объект логгера переменной. Затем мы, используя команду logging.setLevel(level)
, устанавливаем нужный нам уровень логирования.
Далее мы настраиваем обработчик. Так как мы хотим записывать сведения о событиях в файл, мы пользуемся FileHandler
. Конструкция logging.FileHandler(filename)
возвращает объект обработчика файла. Помимо имени лог-файла, можно, что необязательно, задать режим работы с этим файлом. В данном примере режим (mode
) установлен в значение write
. Есть и другие обработчики, например — StreamHandler
, HTTPHandler
, SMTPHandler
.
Затем мы создаём объект форматировщика, используя конструкцию logging.Formatter(format)
. В этом примере мы помещаем имя логгера (строку) в начале форматной строки, а потом идёт то, чем мы уже пользовались ранее при оформлении сообщений.
Потом мы добавляем форматировщик к обработчику, пользуясь конструкцией вида <handler>.setFormatter(<formatter>)
. А в итоге добавляем обработчик к объекту логгера, пользуясь конструкцией <logger>.addHandler(<handler>)
.
Теперь можно запустить модуль main
и исследовать сгенерированные лог-файлы.
Рекомендации по организации логирования в Python
До сих пор мы говорили о том, как логировать значения переменных и исключения, как настраивать пользовательские логгеры. Теперь же предлагаю вашему вниманию рекомендации по логированию.
-
Устанавливайте оптимальный уровень логирования. Логи полезны лишь тогда, когда их можно использовать для отслеживания важных ошибок, которые нужно исправлять. Подберите такой уровень логирования, который соответствует специфике конкретного приложения. Вывод в лог сообщений о слишком большом количестве событий может быть, с точки зрения отладки, не самой удачной стратегией. Дело в том, что при таком подходе возникнут сложности с фильтрацией логов при поиске ошибок, которым нужно немедленно уделить внимание.
-
Конфигурируйте логгеры на уровне модуля. Когда вы работаете над приложением, состоящим из множества модулей — вам стоит задуматься о том, чтобы настроить свой логгер для каждого модуля. Установка имени логгера в
name
помогает идентифицировать модуль приложения, в котором имеются проблемы, нуждающиеся в решении. -
Включайте в состав сообщений логов отметку времени и обеспечьте единообразное форматирование сообщений. Всегда включайте в сообщения логов отметки времени, так как они полезны в деле поиска того момента, когда произошла ошибка. Единообразно форматируйте сообщения логов, придерживаясь одного и того же подхода в разных модулях.
-
Применяйте ротацию лог-файлов ради упрощения отладки. При работе над большим приложением, в состав которого входит несколько модулей, вы, вполне вероятно, столкнётесь с тем, что размер ваших лог-файлов окажется очень большим. Очень длинные логи сложно просматривать в поисках ошибок. Поэтому стоит подумать о ротации лог-файлов. Сделать это можно, воспользовавшись обработчиком
RotatingFileHandler
, применив конструкцию, которая строится по следующей схеме:logging.handlers.RotatingFileHandler(filename, maxBytes, backupCount)
. Когда размер текущего лог-файла достигнет размераmaxBytes
, следующие записи будут попадать в другие файлы, количество которых зависит от значения параметраbackupCount
. Если установить этот параметр в значениеK
— у вас будетK
файлов журнала.
Сильные и слабые стороны логирования
Теперь, когда мы разобрались с основами логирования в Python, поговорим о сильных и слабых сторонах этого механизма.
Мы уже видели, как логирование позволяет поддерживать файлы журналов для различных модулей, из которых состоит приложение. Мы, кроме того, можем конфигурировать подсистему логирования и подстраивать её под свои нужды. Но эта система не лишена недостатков. Даже когда уровень логирования устанавливают в значение warning
, или в любое значение, которое выше warning
, размеры лог-файлов способны быстро увеличиваться. Происходит это в том случае, когда в один и тот же журнал пишут данные, полученные после нескольких сеансов работы с приложением. В результате использование лог-файлов для отладки программ превращается в нетривиальную задачу.
Кроме того, исследование логов ошибок — это сложно, особенно в том случае, если сообщения об ошибках не содержат достаточных сведений о контекстах, в которых происходят ошибки. Когда выполняют команду logging.error(message)
, не устанавливая при этом exc_info
в True
, сложно обнаружить и исследовать первопричину ошибки в том случае, если сообщение об ошибке не слишком информативно.
В то время как логирование даёт диагностическую информацию, сообщает о том, что в приложении нужно исправить, инструменты для мониторинга приложений, вроде Sentry, могут предоставить более детальную информацию, которая способна помочь в диагностике приложения и в исправлении проблем с производительностью.
В следующем разделе мы поговорим о том, как интегрировать в Python-проект поддержку Sentry, что позволит упростить процесс отладки кода.
Интеграция Sentry в Python-проект
Установить Sentry Python SDK можно, воспользовавшись менеджером пакетов pip
.
pip install sentry-sdk
После установки SDK для настройки мониторинга приложения нужно воспользоваться таким кодом:
sentry_sdk.init(
dsn="<your-dsn-key-here>",
traces_sample_rate=0.85,
)
Как можно видеть — вам, для настройки мониторинга, понадобится ключ dsn
. DSN расшифровывается как Data Source Name (имя источника данных). Найти этот ключ можно, перейдя в Your-Project > Settings > Client Keys (DSN)
.
После того, как вы запустите Python-приложение, вы можете перейти на Sentry.io и открыть панель управления проекта. Там должны быть сведения о залогированных ошибках и о других проблемах приложения. В нашем примере можно видеть сообщение об исключении, соответствующем ошибке ZeroDivisionError
.
Изучая подробности об ошибке, вы можете увидеть, что Sentry предоставляет подробную информацию о том, где именно произошла ошибка, а так же — об аргументах x
и y
, работа с которыми привела к появлению исключения.
Продолжая изучение логов, можно увидеть, помимо записей уровня error
, записи уровня info
. Налаживая мониторинг приложения с использованием Sentry, нужно учитывать, что эта платформа интегрирована с модулем logging
. Вспомните — в нашем экспериментальном проекте уровень логирования был установлен в значение info
. В результате Sentry записывает все события, уровень которых соответствует info
и более высоким уровням, делая это в стиле «навигационной цепочки», что упрощает отслеживание ошибок.
Sentry позволяет фильтровать записи по уровням логирования, таким, как info
и error
. Это удобнее, чем просмотр больших лог-файлов в поиске потенциальных ошибок и сопутствующих сведений. Это позволяет назначать решению проблем приоритеты, зависящие от серьёзности этих проблем, и, кроме того, позволяет, используя навигационные цепочки, находить источники неполадок.
В данном примере мы рассматриваем ZeroDivisionError
как исключение. В более крупных проектах, даже если мы не реализуем подобный механизм обработки исключений, Sentry автоматически предоставит диагностическую информацию о наличии необработанных исключений. С помощью Sentry, кроме того, можно анализировать проблемы с производительностью кода.
Код, использованный в данном руководстве, можно найти в этом GitHub-репозитории.
Итоги
Освоив это руководство, вы узнали о том, как настраивать логирование с использованием стандартного Python-модуля logging
. Вы освоили основы настройки логгера root
и пользовательских логгеров, ознакомились с рекомендациями по логированию. Вы, кроме того, узнали о том, как платформа Sentry может помочь вам в деле мониторинга ваших приложений, обеспечивая вас сведениями о проблемах с производительностью и о других ошибках, и используя при этом все возможности модуля logging
.
Когда вы будете работать над своим следующим Python-проектом — не забудьте реализовать в нём механизмы логирования. И можете испытать бесплатную пробную версию Sentry.
О, а приходите к нам работать? 🤗 💰
Мы в wunderfund.io занимаемся высокочастотной алготорговлей с 2014 года. Высокочастотная торговля — это непрерывное соревнование лучших программистов и математиков всего мира. Присоединившись к нам, вы станете частью этой увлекательной схватки.
Мы предлагаем интересные и сложные задачи по анализу данных и low latency разработке для увлеченных исследователей и программистов. Гибкий график и никакой бюрократии, решения быстро принимаются и воплощаются в жизнь.
Сейчас мы ищем плюсовиков, питонистов, дата-инженеров и мл-рисерчеров.
Присоединяйтесь к нашей команде.
My job recently tasked me with logging all the tracebacks/exceptions from our application. I tried numerous techniques that others had posted online such as the one above but settled on a different approach. Overriding traceback.print_exception
.
I have a write up at http://www.bbarrows.com/ That would be much easier to read but Ill paste it in here as well.
When tasked with logging all the exceptions that our software might encounter in the wild I tried a number of different techniques to log our python exception tracebacks. At first I thought that the python system exception hook, sys.excepthook would be the perfect place to insert the logging code. I was trying something similar to:
import traceback
import StringIO
import logging
import os, sys
def my_excepthook(excType, excValue, traceback, logger=logger):
logger.error("Logging an uncaught exception",
exc_info=(excType, excValue, traceback))
sys.excepthook = my_excepthook
This worked for the main thread but I soon found that the my sys.excepthook would not exist across any new threads my process started. This is a huge issue because most everything happens in threads in this project.
After googling and reading plenty of documentation the most helpful information I found was from the Python Issue tracker.
The first post on the thread shows a working example of the sys.excepthook
NOT persisting across threads (as shown below). Apparently this is expected behavior.
import sys, threading
def log_exception(*args):
print 'got exception %s' % (args,)
sys.excepthook = log_exception
def foo():
a = 1 / 0
threading.Thread(target=foo).start()
The messages on this Python Issue thread really result in 2 suggested hacks. Either subclass Thread
and wrap the run method in our own try except block in order to catch and log exceptions or monkey patch threading.Thread.run
to run in your own try except block and log the exceptions.
The first method of subclassing Thread
seems to me to be less elegant in your code as you would have to import and use your custom Thread
class EVERYWHERE you wanted to have a logging thread. This ended up being a hassle because I had to search our entire code base and replace all normal Threads
with this custom Thread
. However, it was clear as to what this Thread
was doing and would be easier for someone to diagnose and debug if something went wrong with the custom logging code. A custome logging thread might look like this:
class TracebackLoggingThread(threading.Thread):
def run(self):
try:
super(TracebackLoggingThread, self).run()
except (KeyboardInterrupt, SystemExit):
raise
except Exception, e:
logger = logging.getLogger('')
logger.exception("Logging an uncaught exception")
The second method of monkey patching threading.Thread.run
is nice because I could just run it once right after __main__
and instrument my logging code in all exceptions. Monkey patching can be annoying to debug though as it changes the expected functionality of something. The suggested patch from the Python Issue tracker was:
def installThreadExcepthook():
"""
Workaround for sys.excepthook thread bug
From
http://spyced.blogspot.com/2007/06/workaround-for-sysexcepthook-bug.html
(https://sourceforge.net/tracker/?func=detail&atid=105470&aid=1230540&group_id=5470).
Call once from __main__ before creating any threads.
If using psyco, call psyco.cannotcompile(threading.Thread.run)
since this replaces a new-style class method.
"""
init_old = threading.Thread.__init__
def init(self, *args, **kwargs):
init_old(self, *args, **kwargs)
run_old = self.run
def run_with_except_hook(*args, **kw):
try:
run_old(*args, **kw)
except (KeyboardInterrupt, SystemExit):
raise
except:
sys.excepthook(*sys.exc_info())
self.run = run_with_except_hook
threading.Thread.__init__ = init
It was not until I started testing my exception logging I realized that I was going about it all wrong.
To test I had placed a
raise Exception("Test")
somewhere in my code. However, wrapping a a method that called this method was a try except block that printed out the traceback and swallowed the exception. This was very frustrating because I saw the traceback bring printed to STDOUT but not being logged. It was I then decided that a much easier method of logging the tracebacks was just to monkey patch the method that all python code uses to print the tracebacks themselves, traceback.print_exception.
I ended up with something similar to the following:
def add_custom_print_exception():
old_print_exception = traceback.print_exception
def custom_print_exception(etype, value, tb, limit=None, file=None):
tb_output = StringIO.StringIO()
traceback.print_tb(tb, limit, tb_output)
logger = logging.getLogger('customLogger')
logger.error(tb_output.getvalue())
tb_output.close()
old_print_exception(etype, value, tb, limit=None, file=None)
traceback.print_exception = custom_print_exception
This code writes the traceback to a String Buffer and logs it to logging ERROR. I have a custom logging handler set up the ‘customLogger’ logger which takes the ERROR level logs and send them home for analysis.
Если Вы хотя бы немного знакомы с программированием и пробовали запускать что-то «в продакшен», то вам наверняка станет больно от такого диалога:
— Вась, у нас там приложение слегло. Посмотри, что случилось?
— Эмм… А как я это сделаю?..
Да, у Василия, судя по всему, не настроено логирование. И это ужасно, хотя бы по нескольким причинам:
- Он никогда не узнает, из-за чего его приложение упало.
- Он не сможет отследить, что привело к ошибке (даже если приложение не упало).
- Он не сможет посмотреть состояние своей системы в момент времени N.
- Он не сможет профилактически поглядывать в логи, чтобы следить за работоспособностью приложения.
- Он не сможет хвастаться своим… (кхе-кхе).
Впрочем, последний пункт, наверно, лишний. Однако, одну вещь мы поняли наверняка:
Логирование — крайне важная штука в программировании.
В языке Python основным инструментом для логирования является библиотека logging
. Так давайте вместе с IT Resume рассмотрим её подробней.
Что такое logging?
Модуль logging
в Python — это набор функций и классов, которые позволяют регистрировать события, происходящие во время работы кода. Этот модуль входит в стандартную библиотеку, поэтому для его использования достаточно написать лишь одну строку:
import logging
Основная функция, которая пригодится Вам для работы с этим модулем — basicConfig()
. В ней Вы будете указывать все основные настройки (по крайней мере, на базовом уровне).
У функции basicConfig()
3 основных параметра:
level
— уровень логирования на Python;filename
— место, куда мы направляем логи;format
— вид, в котором мы сохраняем результат.
Давайте рассмотрим каждый из параметров более подробно.
Наверно, всем очевидно, что события, которые генерирует наш код кардинально могут отличаться между собой по степени важности. Одно дело отлавливать критические ошибки (FatalError
), а другое — информационные сообщения (например, момент логина пользователя на сайте).
Соответственно, чтобы не засорять логи лишней информацией, в basicConfig()
Вы можете указать минимальный уровень фиксируемых событий.
По умолчанию фиксируются только предупреждения (WARNINGS
) и события с более высоким приоритетом: ошибки (ERRORS
) и критические ошибки (CRITICALS
).
logging.basicConfig(level=logging.DEBUG)
А далее, чтобы записать информационное сообщение (или вывести его в консоль, об этом поговорим чуть позже), достаточно написать такой код:
logging.debug('debug message')
logging.info('info message')
И так далее. Теперь давайте обсудим, куда наши сообщения попадают.
Отображение лога и запись в файл
За место, в которое попадают логи, отвечает параметр filename
в basicConfig
. По умолчанию все Ваши логи будут улетать в консоль.
Другими словами, если Вы просто выполните такой код:
import logging
logging.error('WOW')
То сообщение WOW
придёт Вам в консоль. Понятно, что в консоли никому эти сообщения не нужны. Как же тогда направить запись лога в файл? Очень просто:
logging.basicConfig(filename = "mylog.log")
Ок, с записью в файл и выбором уровня логирования все более-менее понятно. А как настроить свой шаблон? Разберёмся.
Кстати, мы собрали для Вас сублимированную шпаргалку по логированию на Python в виде карточек. У нас ещё много полезностей, не пожалеете 🙂
Форматирование лога
Итак, последнее, с чем нам нужно разобраться — форматирование лога. Эта опция позволяет Вам дополнять лог полезной информацией — датой, названием файла с ошибкой, номером строки, названием метода и так далее.
Сделать это можно, как все уже догадались, с помощью параметра format
.
Например, если внутри basicConfig
указать:
format = "%(asctime)s - %(levelname)s - %(funcName)s: %(lineno)d - %(message)s"
То вывод ошибки будет выглядеть так:
2019-01-16 10:35:12,468 - ERROR - <module>:1 - Hello, world!
Вы можете сами выбирать, какую информацию включить в лог, а какую оставить. По умолчанию формат такой:
<УРОВЕНЬ>: <ИМЯ_ЛОГГЕРА>: <СООБЩЕНИЕ>
.
Важно помнить, что все параметры logging.basicConfig должны передаваться до первого вызова функций логирования.
Эпилог
Что же, мы разобрали все основные параметры модуля logging
и функции basicConfig
, которые позволят Вам настроить базовое логирование в Вашем проекте. Дальше — только практика и набивание шишек 🙂
Вместо заключения просто оставим здесь рабочий кусочек кода, который можно использовать 🙂
import logging
logging.basicConfig(
level=logging.DEBUG,
filename = "mylog.log",
format = "%(asctime)s - %(module)s - %(levelname)s - %(funcName)s: %(lineno)d - %(message)s",
datefmt='%H:%M:%S',
)
logging.info('Hello')
Если хотите разобраться с параметрами более подробно, Вам поможет официальная документация (очень неплохая, кстати).
Error tracking is essential for any application when many people are relying on the app. If your application is not working in production for whatever reason, it can be a nightmare experience for users depending on correct functionality.
There are many exceptions tracking plugins and modules available. Some of them are open source whereas others are paid, like HoneyBadger, NewRelic, ELK, etc.
What about having a custom exception handler that can track errors in different contexts with additional features like:
-
Send emails or notify developers (interested entities).
-
Create or update tickets in Bugzilla or Jira.
-
Push exceptions to the ELK stack or any other system for analytics and store detailed exceptions in DB.
-
While capturing exceptions, provide local and global variables details (failure context).
You may also like: The Top Four Exception Tracking Services
Error Tracker
Error tracker is a python library. It provides all required interfaces and supports all the above features. One interesting thing about this library is that it can mask variables that are sensitive (i.e should not be exposed, like password, credit card number, etc.). It’s well documented at Error Tracker doc and available via PyPI
A typical setup of Error Tracker can be visualized as:
Error Tracker can be used with any type of Python application. We’ll start with Flask.
Tools we need:
-
Editor any IDE.
-
Python.
-
Pip.
Installation
pip install error-tracker
We’ll use settings file for app configuration you might call it config.py or some other format like YAML etc, we’ll use python file for simplicity.
settings.py
APP_ERROR_SEND_NOTIFICATION = True
APP_ERROR_RECIPIENT_EMAIL = ('dev@example.com',)
APP_ERROR_EMAIL_SENDER="server@example.com"
APP_ERROR_SUBJECT_PREFIX = ""
APP_ERROR_MASK_WITH = "**************"
APP_ERROR_MASKED_KEY_HAS = ("password", "secret")
APP_ERROR_URL_PREFIX = "/dev/error"
There’re seven configurations in this file:
APP_ERROR_SEND_NOTIFICATION
— This configures whether a notification has to be sent or not. If it’s set, then it will try to send notification using the notification interface.
APP_ERROR_RECIPIENT_EMAIL
— This refers to whom the email has to be sent to. It is required to build email content. It can be a list of emails or a single email address.
APP_ERROR_EMAIL_SENDER
— Who is sending email to the recipient(s).
APP_ERROR_SUBJECT_PREFIX
— Any email subject prefix. By default, it will be [IndexError] [GET] http://127.0.0.1:5000/go.
APP_ERROR_MASK_WITH
— What should be used to mask the sensitive information.
APP_ERROR_MASKED_KEY_HAS
— What variables should be masked. It can mask all local and global variables. Masking is done based on the variable name. If a data type is a dictionary, or it’s subclass then their keys are examined.
APP_ERROR_URL_PREFIX
— All unique exceptions are stored in the database and can be browsed at this endpoint.
Create another python file
For email-sender, we’ll implement NotificationMixin
from flask_mail import Mail, Message
class Notifier(Mail, NotificationMixin):
def notify(self, request, exception,
email_subject=None,
email_body=None,
from_email=None,
recipient_list=None):
message = Message(email_subject, recipient_list, email_body, sender=from_email)
self.send(message)
For issue tracking, we’ll implement TicketingMixin
class Ticketing(TicketingMixin):
def raise_ticket(self, exception, request=None):
# implement this method to communicate with Jira or Bugzilla etc
pass
Let’s create a Flask app to serve requests. We’ll use SQLite for simplicity.
app = Flask(__name__)
app.config.from_object(settings)
app.config['SQLALCHEMY_DATABASE_URI'] = "sqlite:///tmp.sqlite"
db = SQLAlchemy(app)
The errors can be tracked by creating an instance of AppErrorTracker
and initializing this with proper details. This application can store all the exceptions in the database.
app_error = AppErrorTracker(app=app, db=db,
notifier=Notifier(app=app), ticketing=Ticketing())
db.create_all()
For error tracking, we are going to use the decorator track_exception
provided by AppErrorTracker
class. We’ll attach this decorator whenever HTTP 500 occurs.
@app.errorhandler(500)
@app_error.track_exception
def error_500(e):
return render_template('500.html'), 500
Now, it’s ready to be used. We can fire some requests and see how it works. For testing, let’s add one endpoint that will throw 500 errors with different types of exceptions.
@app.route('/go')
def die():
import random
password = "test"
foo = {}
foo['password'] = "Oh! My Gosh"
foo['secret'] = "NO ONE KNOWS"
exceptions = [KeyError, ArithmeticError, BaseException, IndentationError, IndexError, MemoryError,
NameError, NotImplementedError, ImportError, FloatingPointError, EOFError,
OSError, AssertionError, AttributeError, GeneratorExit, Exception,
EnvironmentError, ImportError,
NotImplementedError, RuntimeError]
raise random.choice(exceptions)
Now, run the app in debug=False
mode and browse, as it will fail. Now, go to http://127.0.0.1:5000/dev/error/. This will display the current exceptions in a table like:
Any of the specific exceptions can be browsed by clicking the corresponding link, in the Exception detail
section, all frame details that have been captured can be seen.
The complete Flask application can be found at https://github.com/sonus21/error-tracker/tree/master/examples/flask-sample.
Implementation With Django
Using Exception Tracker with Django is also very simple. Install the application using pip install error-tracker
. Once we’ve installed it, we need to configure some part of the applications using the settings.py file.
For the Django application, we need to add this app in the INSTALLED_APPS
list and add Middleware
to catch exceptions. Middleware should be added at the end of the list so that it will be called first whenever an exception occurs.
APP_ERROR_RECIPIENT_EMAIL = ('example@example.com',)
APP_ERROR_SUBJECT_PREFIX = "Server Error"
APP_ERROR_EMAIL_SENDER = 'user@example.com'
INSTALLED_APPS = [
...
'error_tracker.DjangoErrorTracker'
]
MIDDLEWARE = [
...
'error_tracker.django.middleware.ExceptionTrackerMiddleWare'
]
Error Tracker provides a few default pages for listing exception, deleting exception, and browsing a specific exception. These endpoints can be plugged in with Django’s other URLs.
from error_tracker.django import urls
urlpatterns = [
...
url("dev/", include(urls)),
]
These are all the code changes we need for the Django app. The complete code is available at https://github.com/sonus21/error-tracker/tree/master/examples/DjangoSample.
Conclusion
Apps using Error Tracker can be further customized, like what models to use. Currently, it records only one instance of failure, while all failures can be tracked and dumped to some database. Read more about them at https://error-tracker.readthedocs.io/en/latest/index.html#.
The complete code is available on GitHub.
If you found this post helpful, please share and give a thumbs up.
Further Reading
- Python: How to Create an Exception Logging Decorator.
- Error Handling Strategies.
- Create a Simple API Using Django REST Framework in Python.
Opinions expressed by DZone contributors are their own.
In software development, different types of errors can occur. They could be syntax errors, logical errors, or runtime errors.
Syntax errors most probably occur during the initial development phase and are a result of incorrect syntax. Syntax errors can be caught easily when the program is compiled for execution.
Logical errors, on the other hand, are a result of improper logical implementation. An example would be a program accessing an unsorted list assuming it to be sorted. Logical errors are the most difficult ones to track.
Runtime errors are the most interesting errors which occur, if we don’t consider all the corner cases. An example would be trying to access a non-existent file.
- Handling Exceptions Using Try and Except
- Multiple Exceptions
- finally Clause
- User-Defined Exceptions
- Logging in Python
- Getting the Stack Trace
In this tutorial, we’ll learn how to handle errors in Python and how to log the errors for a better understanding of what went wrong in the application.
Handling Exceptions in Python
Let’s start with a simple program to add two numbers in Python. Our program takes in two parameters as input and prints the sum. Here is a Python program to add two numbers:
1 |
def addNumbers(a, b): |
2 |
print a + b |
3 |
|
4 |
addNumbers(5, 10) |
Try running the above Python program, and you should have the sum printed.
15
While writing the above program, we didn’t really consider the fact that anything can go wrong. What if one of the parameters passed is not a number?
We haven’t handled that case, hence our program would crash with the following error message:
1 |
Traceback (most recent call last): |
2 |
File "addNumber.py", line 4, in <module> |
3 |
addNumbers('', 10) |
4 |
File "addNumber.py", line 2, in addNumbers |
5 |
print a + b |
6 |
TypeError: cannot concatenate 'str' and 'int' objects |
We can handle the above issue by checking if the parameters passed are integers. But that won’t solve the issue. What if the code breaks down due to some other reason and causes the program to crash? Working with a program which crashes on being encountered with an error is not a good sight. Even if an unknown error is encountered, the code should be robust enough to handle the crash gracefully and let the user know that something is wrong.
Handling Exceptions Using try
and except
In Python, we use the try
and except
statements to handle exceptions. Whenever the code breaks down, an exception is thrown without crashing the program. Let’s modify the add number program to include the try
and except
statements.
1 |
def addNumbers(a, b): |
2 |
try: |
3 |
return a + b |
4 |
except Exception as e: |
5 |
return 'Error occurred : ' + str(e) |
6 |
|
7 |
print(addNumbers('', 10)) |
Python would process all code inside the try
and except
statement. When it encounters an error, the control is passed to the except
block, skipping the code in between.
As seen in the above code, we have moved our code inside a try
and except
statement. Try running the program and it should throw an error message instead of crashing the program. The reason for the exception is also returned as an exception message.
The above method handles unexpected exceptions. Let’s have a look at how to handle an expected exception. Assume that we are trying to read a particular file using our Python program, but the file doesn’t exist. In this case, we’ll handle the exception and let the user know that the file doesn’t exist when it happens. Have a look at the file reading code:
1 |
try: |
2 |
try: |
3 |
with open('file.txt') as f: |
4 |
content = f.readlines() |
5 |
except IOError as e: |
6 |
print(str(e)) |
7 |
except Exception as e: |
8 |
print(str(e)) |
In the above code, we have handled the file reading inside an IOError
exception handler. If the code breaks down because the file.txt
is unavailable, the error would be handled inside the IOError
handler. Similar to the IOError
exceptions, there are a lot more standard exceptions like Arithmetic
, OverflowError
, and ImportError
, to name a few.
Multiple Exceptions
We can handle multiple exceptions at a time by clubbing the standard exceptions as shown:
1 |
try: |
2 |
with open('file.txt') as f: |
3 |
content = f.readlines() |
4 |
print(content) |
5 |
except (IOError,NameError) as e: |
6 |
print(str(e)) |
The above code would raise both the IOError
and NameError
exceptions when the program is executed.
finally
Clause
Assume that we are using certain resources in our Python program. During the execution of the program, it encountered an error and only got executed halfway. In this case, the resource would be unnecessarily held up. We can clean up such resources using the finally
clause. Take a look at the below code:
1 |
try: |
2 |
filePointer = open('file.txt','r') |
3 |
try: |
4 |
content = filePointer.readline() |
5 |
finally: |
6 |
filePointer.close() |
7 |
except IOError as e: |
8 |
print(str(e)) |
If, during the execution of the above code, an exception is raised while reading the file, the filePointer
would be closed in the finally
block.
User-Defined Exceptions
So far, we have dealt with exceptions provided by Python, but what if you want to define your own custom exceptions? To create user-defined exceptions, you will need to create a class that inherits from the built-in Exception
class. An advantage of creating user-defined exceptions is that they will make sense in our programs. For example, suppose you had a program that ensures that the discounted price of an item is not more than the sale price. Let’s create a custom exception for this type of error.
1 |
class PriceError(Exception): |
2 |
pass
|
Next, add the exception as follows:
1 |
def discount(price,discounted_price): |
2 |
if discounted_price > price: |
3 |
raise PriceError |
4 |
else: |
5 |
print("Discount applied") |
In the code above, the raise
statement forces the PriceError
exception to occur.
Now, if you call the function with values where the disounted_price
is greater than the price, you will get an error, as shown below.
1 |
Traceback (most recent call last): |
2 |
File "/home/vat/Desktop/errors.py", line 75, in <module> |
3 |
discount(100,110) |
4 |
File "/home/vat/Desktop/errors.py", line 70, in discount |
5 |
raise PriceError |
6 |
__main__.PriceError |
The error above does not provide a descriptive message; let’s customize it to give a detailed message of what the error means.
1 |
class PriceError(Exception): |
2 |
def __init__(self, price,discounted_price): |
3 |
self.price = price |
4 |
self.disounted_price = discounted_price |
5 |
|
6 |
def __str__(self): |
7 |
return 'Discounted price greater than price' |
Now, let’s apply the error and call our function.
1 |
def discount(price,discounted_price): |
2 |
if discounted_price > price: |
3 |
raise PriceError(price,discounted_price) |
4 |
else: |
5 |
print("Discount applied") |
6 |
|
7 |
discount(100,110) |
Now, if you call the function, you will get the following error:
1 |
(base) vaati@vaati-Yoga-9-14ITL5:~/Desktop/EVANTO2022$ python3 errors.py |
2 |
Traceback (most recent call last): |
3 |
File "/home/vaati/Desktop/EVANTO2022/errors.py", line 84, in <module> |
4 |
discount(100,110) |
5 |
File "/home/vaati/Desktop/EVANTO2022/errors.py", line 79, in discount |
6 |
raise PriceError(price,discounted_price) |
7 |
__main__.PriceError: Discounted price greater than price |
Logging in Python
When something goes wrong in an application, it becomes easier to debug if we know the source of the error. When an exception is raised, we can log the required information to track down the issue. Python provides a simple and powerful logging library. Let’s have a look at how to use logging in Python.
1 |
try: |
2 |
logging.info('Trying to open the file') |
3 |
filePointer = open('file.txt','r') |
4 |
try: |
5 |
logging.info('Trying to read the file content') |
6 |
content = filePointer.readline() |
7 |
print(content) |
8 |
finally: |
9 |
filePointer.close() |
10 |
except IOError as e: |
11 |
logging.error('Error occurred ' + str(e)) |
As seen in the above code, first we need to import the logging Python library and then initialize the logger with the log file name and logging level. There are five logging levels: DEBUG
, INFO
, WARNING
, ERROR
, and CRITICAL
. Here we have set the logging level to INFO
, so any message that has the level INFO
will be logged.
Getting the Stack Trace
In the above code we had a single program file, so it was easier to figure out where the error had occurred. But what do we do when multiple program files are involved? In such a case, getting the stack trace of the error helps in finding the source of the error. The stack trace of the exception can be logged as shown:
1 |
import logging |
2 |
|
3 |
# initialize the log settings
|
4 |
logging.basicConfig(filename = 'app.log', level = logging.INFO) |
5 |
|
6 |
try: |
7 |
filePointer = open('appFile','r') |
8 |
try: |
9 |
content = filePointer.readline() |
10 |
finally: |
11 |
filePointer.close() |
12 |
except IOError as e: |
13 |
logging.exception(str(e)) |
If you try to run the above program, on raising an exception the following error would be logged in the log file:
1 |
ERROR:root:[Errno 2] No such file or directory: 'appFile' |
2 |
Traceback (most recent call last): |
3 |
File "readFile.py", line 7, in <module> |
4 |
filePointer = open('appFile','r') |
5 |
IOError: [Errno 2] No such file or directory: 'appFile' |
Wrapping It Up
In this tutorial, we saw how to get started with handling errors in Python and using the logging module to log errors. We saw the usage of try
, except
, and finally
statements, which are quite useful when dealing with error handling in Python. For more detailed information, I would recommend reading the official documentation on logging. Also have a look at the documentation for handling exceptions in Python.
This post has been updated with contributions from Esther Vaati. Esther is a software developer and writer for Envato Tuts+.
Did you find this post useful?
I’m a software engineer by profession and love to write tutorials and educational stuff.