Как сделать логгер

Логирование в Python: руководство разработчика

Сталкивались ли вы с трудностями при отладке 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.() .

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

Записи в лог-файле имеют формат :: . По умолчанию , имя логгера, установлено в 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 and .") try: x/y logging.info(f"x/y successful with result: .") 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 and .") try: x/y logging.info(f"x/y successful with result: .") except ZeroDivisionError as err: logging.error("ZeroDivisionError",exc_info=True)

Теперь модифицируем код так, чтобы в нём имелись бы списки значений x и y , для которых нужно вычислить коэффициенты x/y . Для логирования исключений ещё можно воспользоваться конструкцией logging.exception() .

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 and .") try: x/y logging.info(f"x/y successful with result: .") 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: .") 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".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 . ") def test_division(x,y): try: x/y logger2.info(f"x/y successful with result: .") 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".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 . ") 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 and ") 

Разберёмся с тем, что происходит коде, где настраиваются пользовательские логгеры.

Сначала мы получаем логгер и задаём уровень логирования. Команда logging.getLogger(name) возвращает логгер с заданным именем в том случае, если он существует. В противном случае она создаёт логгер с заданным именем. На практике имя логгера устанавливают с использованием специальной переменной name , которая соответствует имени модуля. Мы назначаем объект логгера переменной. Затем мы, используя команду logging.setLevel(level) , устанавливаем нужный нам уровень логирования.

Далее мы настраиваем обработчик. Так как мы хотим записывать сведения о событиях в файл, мы пользуемся FileHandler . Конструкция logging.FileHandler(filename) возвращает объект обработчика файла. Помимо имени лог-файла, можно, что необязательно, задать режим работы с этим файлом. В данном примере режим ( mode ) установлен в значение write . Есть и другие обработчики, например — StreamHandler , HTTPHandler , SMTPHandler .

Затем мы создаём объект форматировщика, используя конструкцию logging.Formatter(format) . В этом примере мы помещаем имя логгера (строку) в начале форматной строки, а потом идёт то, чем мы уже пользовались ранее при оформлении сообщений.

Потом мы добавляем форматировщик к обработчику, пользуясь конструкцией вида .setFormatter() . А в итоге добавляем обработчик к объекту логгера, пользуясь конструкцией .addHandler() .

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

Сейчас мы ищем плюсовиков, питонистов, дата-инженеров и мл-рисерчеров.

Эффективное логирование в Python

В Python существует встроенный модуль logging, который позволяет журналировать этапы выполнения программы. Логирование полезно когда, например, нужно оставить большой скрипт сбора / обработки данных на длительное время, а в случае возникновения непредвиденных ошибок выяснить, с чем они могут быть связаны. Анализ логов позволяет быстро и эффективно выявлять проблемные места в коде, но для удобного использования модуля следует написать несколько функций по взаимодействию с ним и вынести их в отдельный файл — сегодня мы этим и займёмся.

Пишем логгер

Создадим файл loggers.py. Для начала импортируем модули и задаём пару значений по умолчанию — директорию для файла с логом и наименование конфигурационного файла, содержащего шаблоны логирования. Его мы опишем следом.

import os import json import logging import logging.config FOLDER_LOG = "log" LOGGING_CONFIG_FILE = 'loggers.json'

Опишем функцию для создания папки с логом: она принимает наименование для папки, но по умолчанию будет называть её «log». Директорию создаём при помощи модуля os и только в том случае, если такой директории ещё не существует.

def create_log_folder(folder=FOLDER_LOG): if not os.path.exists(folder): os.mkdir(folder)

Теперь опишем функцию создания нового логгера по заданному шаблону. Функция должна создать директорию для логирования, открыть конфигурационный файл и достать нужный шаблон. Затем по шаблону при помощи модуля logging создаём новый логгер:

def get_logger(name, template='default'): create_log_folder() with open(LOGGING_CONFIG_FILE, "r") as f: dict_config = json.load(f) dict_config["loggers"][name] = dict_config["loggers"][template] logging.config.dictConfig(dict_config) return logging.getLogger(name)

Для удобства опишем ещё одну функцию — получение стандартного лога. Она ничего не принимает и нужна только для инициализации лога с шаблоном default:

def get_default_logger(): create_log_folder() with open(LOGGING_CONFIG_FILE, "r") as f: logging.config.dictConfig(json.load(f)) return logging.getLogger("default")

Описываем конфигурационный файл

Создадим по соседству файл loggers.json — он будет содержать настройки логгера. Внутри указываем такие настройки, как версию логгера, форматы логирования для разных уровней, наименование выходного файла и его максимальный размер:

 < "version": 1, "disable_existing_loggers": false, "formatters": < "default": < "format": "%(asctime)s - %(processName)-10s - %(name)-10s - %(levelname)-8s - %(message)s" >>, "handlers": < "console": < "class": "logging.StreamHandler", "level": "INFO", "formatter": "default" >, "rotating_file": < "class": "logging.handlers.RotatingFileHandler", "level": "DEBUG", "formatter": "default", "filename": "log/main.log", "maxBytes": 10485760, "backupCount": 20 >>, "loggers": < "default": < "handlers": ["console", "rotating_file"], "level": "DEBUG" >> >

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

Теперь давайте представим, что вы выгружаете данные по API и складываете их в базу данных на примере нашего материала про транзакции в SQLAlchemy. Рассмотрим заключительную часть кода: добавим строку с инициализацией стандартного логгера и изменим код так, чтобы сначала в лог выводился offset, затем в случае успеха предложение «Successfully inserted data», а в случае ошибки выводилась сама ошибка и предложение: «Error: tried to insert data but got an error».

logger = get_logger('main') offset = 0 subs_count = get_subs_count(group_id) while offset < subs_count: with engine.connect() as conn: transaction = conn.begin() try: logger.info(f"/ ") df = get_subs_info(group_id, offset) df.to_sql('subscribers', con=conn, if_exists='append', index=False) if offset == 10: raise(ValueError("This is a test errror")) transaction.commit() logger.info(f"Successfully inserted data") except Exception as E: transaction.rollback() logger.error(f"Error: tried to insert but got an error: ") time.sleep(1) offset += 10

Теперь во время работы программы будет отображаться такой вывод, который также будет записан в файл main.log папки log в директории проекта. После завершения работы программы можно исследовать логи, посмотреть, на каких offset возникли проблемы, какие данные не удалось вставить и прочитать текст ошибки:

Введение в logging на Python

22 Ноя. 2020 , Python, 62920 просмотров, The Ultimate Guide To Python Logging

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

Зачем нужны логи?

Логи это рентген снимок выполнения вашей программы. Чем детальнее лог, тем проще разобраться в нестандартных ситуациях, которые могут приключиться с вашим скриптом. Наиболее популярным примером логов служат access логи веб-сервера, например, Apache httpd или nginx. Пример куска access лога моего блога:

92.63.107.227 - - [04/Nov/2020:06:30:48 +0000] "GET /ru/hosted-open-vpn-server/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-" 92.63.107.227 - - [04/Nov/2020:06:30:49 +0000] "GET /ru/data-engineering-course/ HTTP/1.1" 301 169 "-" "python-requests/2.11.1" "-" 213.180.203.50 - - [04/Nov/2020:06:36:07 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; YandexMetrika/2.0; +http://yandex.com/bots yabs01)" "-" 114.119.160.75 - - [04/Nov/2020:06:36:41 +0000] "GET /robots.txt HTTP/1.1" 301 169 "-" "(compatible;PetalBot;+https://aspiegel.com/petalbot)" "10.179.80.67" 90.180.35.207 - - [04/Nov/2020:06:47:11 +0000] "GET / HTTP/1.0" 301 169 "-" "-" "-" 46.246.122.77 - - [04/Nov/2020:06:53:22 +0000] "GET / HTTP/1.1" 301 169 "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/66.0.3359.181 Safari/537.36" "-" 66.249.76.16 - - [04/Nov/2020:06:53:30 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" "-" 66.102.9.118 - - [04/Nov/2020:07:11:19 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36 Google Favicon" "46.159.204.234" 71.6.167.142 - - [04/Nov/2020:07:11:55 +0000] "GET / HTTP/1.1" 301 169 "-" "Mozilla/5.0 (Windows NT 6.1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2228.0 Safari/537.36" "-"

Помимо access логов веб-сервер также пишет error лог, там хранится информация обо всех ошибках при обработке HTTP запросов. Также и в ваших скриптах, логи могут делиться на информационные — вывод текущего состояния выполнения, отладочной информации, и на логи с ошибками — вывод исключений, ошибок с дополнительной информацией для отладки, содержащей контекст).

logging и Python

Точкой входа в работу с логированием в Python является библиотека logging. На первый взгляд может показаться, что библиотека сложная и запутанная, но потратив некоторое время на её изучение, можно убедиться в обратном. Для меня logging это классический пример дизайна ООП, где композиция преобладает над наследованием, поэтому в исходном коде библиотеки можно встретить множество функциональных классов. Цель этого туториала разобрать по косточкам каждый класс и воссоединить их в единый механизм логирования в Python. Начнём-с.

Logger

Чтобы начать работу с logging необходимо в импортировать библиотеку logging и вызвать функцию getLogger, передав ей имя будущего логера. Функция вернёт инстанс объекта Logger. Логер это рычаг за который мы дёргаем каждый раз, когда нам нужно записать информацию в лог.

import logging logger = logging.getLogger('logger') 

Заметьте, что функция getLogger принимает на вход параметр — имя логера. Можно назначать любое имя или __name__ . Вызов getLogger с одинаковым названием вернёт один и тот же инстанс логера.

Я рекомендую использовать в качестве аргумента __name__ , в этом случае не нужно беспокоиться, что разные модули могут ссылаться на один и тот же логер.

Класс Logger предоставляет наружу несколько методов для записи сообщений разного уровня. Уровни необходимы для понимания контекста сообщения/лога, который мы пишем. В logging существует несколько уровней:

1. DEBUG — уровень отладочной информации, зачастую помогает при разработке приложения на машине программиста.
2. INFO — уровень вспомогательной информации о ходе работы приложения/скрипта.
3. WARNING — уровень предупреждения. Например, мы можем предупреждать о том, что та или иная функция будет удалена в будущих версиях вашего приложения.
4. ERROR — с таким уровнем разработчики пишут логи с ошибками, например, о том, что внешний сервис недоступен.
5. CRITICAL — уровень сообщений после которых работа приложения продолжаться не может.

По умолчанию в logging задан уровень WARNING, это означает, что сообщения уровня DEBUG и INFOбудут игнорироваться при записи в лог. Разработчик может самостоятельно задать необходимый ему уровень логирования через метод setLevel у инстанса Logger:

logger.setLevel(logging.DEBUG) 

Методы для записи сообщений с разными уровнями именуются по тому же принципу:

logger.debug('debug info') logger.info('info') logger.warning('warning') logger.error('debug info') logger.critical('debug info') 

Также есть ещё один метод — exception . Его желательно вызывать в блоке except при обработке исключения. В это случае он сможет уловить контекст исключения и записать его в лог:

try: 1/0 except : logger.exception('exception')

Handler

Задача класса Handler и его потомков обрабатывать запись сообщений/логов. Т.е. Handler отвечает за то куда будут записаны сообщения. В базовом наборе logging предоставляет ряд готовых классов-обработчиков:

• SteamHandler — запись в поток, например, stdout или stderr.
• FileHandler — запись в файл, класс имеет множество производных классов с различной функциональностью (ротация файлов логов по размеру, времени и т.д.)
• SocketHandler — запись сообщений в сокет по TCP
• DatagramHandler — запись сообщений в сокет по UDP
• SysLogHandler — запись в syslog
• HTTPHandler — запись по HTTP

Это далеко не полный список. Чтобы посмотреть все, перейдите по ссылке выше. Для указания Handler, необходимо у инстанса Logger вызвать метод addHandler и передать туда инстанс класса Handler. У одного Logger инстанса может быть множество обработчиков.

Пример записи лога в stdout:

import sys import logging from logging import StreamHandler logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) handler = StreamHandler(stream=sys.stdout) logger.addHandler(handler) logger.debug('debug information') 

Если запустить этот скрипт, то можно увидеть сообщение:

debug information 

Мы видим сообщение уровня DEBUG потому что задачи этот уровень в настройках. Если поменять его на INFO, то сообщение пропадёт:

logger.setLevel(logging.INFO) 

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

Formatter

Formatter это ёщё один класс в семействе logging, отвечающий за отображение лога. Если класс Handler ответственный за то куда будет происходить запись, то класс Formatter отвечает на вопрос как будет записано сообщение. По умолчанию в лог пишется голая строка, которую мы передаём через методы debug , info и т.д. Давайте обогатим наш лог дополнительной метаинформация, например, о времени записи и уровне сообщения. Formatter передаётся инстансу Handler через метод .setFormatter

import sys import logging from logging import StreamHandler, Formatter logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) handler = StreamHandler(stream=sys.stdout) handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s')) logger.addHandler(handler) logger.debug('debug information') 

Запуск скрипта выведет на экран следующее сообщение:

[2020-11-22 13:00:08,751: DEBUG] debug information 

Обратите внимание на строку, которую я передал при инициализации инстанса Formatter :

[%(asctime)s: %(levelname)s] %(message)s 

Это шаблон, который будет заполнен при записи сообщения в лог. Набор таких готовых шаблонов можно посмотреть в разделе LogRecord attributes.

Filter

Задача класса фильтровать сообщения по заданной разработчиком логике. Предположим, что я хочу записывать в лог сообщения, содержащие слово python . Чтобы задать фильтр необходимо вызвать метод addFilter у инстанса Logger. Передать можно либо инстанс класса, реализующий метод filter либо callable объект (например, функцию). На вход прилетит инстанс класса LogRecord, это и есть 1 сообщение лога:

import sys import logging from logging import StreamHandler, Formatter, LogRecord def filter_python(record: LogRecord) -> bool: return record.getMessage().find('python') != -1 logger = logging.getLogger(__name__) logger.setLevel(logging.DEBUG) handler = StreamHandler(stream=sys.stdout) handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s')) logger.addHandler(handler) logger.addFilter(filter_python) logger.debug('python debug information') 

Наглядно и понятно, разве logging может быть сложным? ��

LoggerAdapter

Адаптер нужен для передачи дополнительной контекстной информации при каждой записи лога через Logger. Например, вы написали веб-приложение и вам необходимо в логи дополнительно передавать username пользователя:

class CustomLoggerAdapter(LoggerAdapter): def process(self, msg, kwargs): return f' from ', kwargs logger2 = logging.getLogger('adapter') logger2.setLevel(logging.DEBUG) handler = StreamHandler(stream=sys.stdout) handler.setFormatter(Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s')) adapter = CustomLoggerAdapter(logger2, ) logger2.addHandler(handler) adapter.error('failed to save') 

extra и не только

Строки в логах это хорошо, а что если я хочу помимо строки дополнительно передавать ответ от веб-сервера? Для этого можно использовать аргумент extra при вызове методов debug , info и т.д. Давайте напишем пример вывода

logger.debug('debug info', extra=)

Теперь вывод значения ключа response можно указать через Formatter (при условии, что response передаётся всегда):

Formatter(fmt='[%(asctime)s: %(levelname)s] %(message)s, response: %(response)s') 

Аргумент extra удобен при написании своих кастомных обработчиков логов (например, отсылка логов в телеграм). Далее я покажу пример кастомного Handler класса для отправки логов в Telegram через бота.

Конфигурация logging

Официальная документация рекомендует конфигурировать logging через python-словарь. Для этого необходимо вызвать функцию logging.config.dictConfig и передать ей специальный словарь. Схема словаря описана здесь. Я лишь вкратце пробегусь по основным ключам:

• version — ключ указывает версию конфига, рекомендуется наличие этого ключа со значением 1, нужно для обратной совместимости в случае, если в будущем появятся новые версии конфигов.
• disable_existing_loggers — запрещает или разрешает настройки для существующих логеров (на момент запуска), по умолчанию равен True
• formatters — настройки форматов логов
• handlers — настройки для обработчиков логов
• loggers — настройки существующих логеров

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

import logging.config LOGGING_CONFIG = < 'version': 1, 'disable_existing_loggers': False, 'formatters': < 'default_formatter': < 'format': '[%(levelname)s:%(asctime)s] %(message)s' >, >, 'handlers': < 'stream_handler': < 'class': 'logging.StreamHandler', 'formatter': 'default_formatter', >, >, 'loggers': < 'my_logger': < 'handlers': ['stream_handler'], 'level': 'DEBUG', 'propagate': True >> > logging.config.dictConfig(LOGGING_CONFIG) logger = logging.getLogger('my_logger') logger.debug('debug log') 

Неправда ли удобно? В реальных приложениях настройки выносят в отдельный модуль, который обязательно импортируется на старте, например, модуль в settings.py как в Django. Именно в нём задаются глобальные настройки для всех логеров приложения.

Наследование в logging

Ещё одним удобным механизмом в logging является "наследование" настроек корневого логера его потомками. Наследование задаётся через символ . в названии логера. То есть логер с названием my_package.logger1 унаследует все настройки, заданные для my_package . Давайте обновим пример выше, добавив в LOGGING_CONFIG настройку для my_package

LOGGING_CONFIG['loggers'].update( < 'my_package': < 'handlers': ['stream_handler'], 'level': 'DEBUG', 'propagate': False >>) 

Если у вас есть настройка для конкретного логера и вы не хотите, чтобы он был дополнительно обработан родительскими Handler классами, то ключу propagate нужно присвоить значение False . В этом случае передача управления "вверх" до родителя будет запрещена.

Отправляем логи в Telegram

А теперь давайте напишем свой кастомный Handler для отправки логов через бота в телеграм. Если вы никогда не работали с телеграм-ботами, то почитайте мою статью про создание телеграм-ботов. Я предполагаю, что вы уже создали бота, получили его токен и знаете свой user-id/chat-id, чтобы бот смог посылать сообщения лично вам. Для работы с телеграмом я использую библиотеку pyTelegramBotAPI.

Чтобы создать свой обработчик, необходимо наследоваться от класса Handler и перезаписать метод emit :

import telebot from logging import Handler, LogRecord class TelegramBotHandler(Handler): def __init__(self, token: str, chat_id: str): super().__init__() self.token = token self.chat_id = chat_id def emit(self, record: LogRecord): bot = telebot.TeleBot(self.token) bot.send_message( self.chat_id, self.format(record) ) 

При инициализации инстанса класса TelegramBotHandler ему необходимо будет передать токен бота и chat_id . Замечу, что эти настройки можно задать через конфигурирование:

'handlers': < 'telegram_handler': < 'class': 'handlers.TelegramBotHandler', 'chat_id': '', 'token': '', 'formatter': 'default_formatter', > >, 

Чтобы обработчик начал свою работу, достаточно в настройках вашего логера прописать новый обработчик:

LOGGING_CONFIG['loggers'].update( < 'my_package': < 'handlers': ['stream_handler', 'telegram_handler'], 'level': 'DEBUG', 'propagate': False >>)

Заключение

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

Интересные записи:

• Руководство по работе с HTTP в Python. Библиотека requests
• Работа с MySQL в Python
• Почему Python?
• Pyenv: удобный менеджер версий python
• Обзор Python 3.9
• Celery: начинаем правильно
• Django Channels: работа с WebSocket и не только
• FastAPI, asyncio и multiprocessing
• Что нового появилось в Django Channels?
• Авторизация через Telegram в Django и Python
• Как написать Telegram бота: практическое руководство
• Python-RQ: очередь задач на базе Redis
• Разворачиваем Django приложение в production на примере Telegram бота
• Введение в pandas: анализ данных на Python
• Работа с PostgreSQL в Python
• Django, RQ и FakeRedis
• Итоги первой встречи Python программистов в Алматы
• Обзор Python 3.8
• Интеграция Trix editor в Django
• Участие в подкасте TalkPython
• Строим Data Pipeline на Python и Luigi
• Авторизация через Telegram в Django приложении
• Видео презентации ETL на Python

Как быстро добавить логгер в проект на Python

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

Вот короткая версия того, что было в предыдущих частях:

• логгер — это специальный модуль или библиотека, которая фиксирует определённые события в нашей программе;
• на что реагировать и как фиксировать — решает программист;
• для этого он пишет специальную команду типа лог.добавить('Запускаем главный модуль') или лог.ошибка('Файл не найден') ;
• сам по себе лог ничего не исправляет — он только сообщает о том, что происходит в программе;
• есть несколько основных уровней логирования — ошибки, предупреждения, информационные сообщения, сообщения отладки и разовые события;
• эти уровни нужны для того, чтобы фильтровать сообщения по степени важности, например посмотреть только сообщения об ошибках или о штатных срабатываниях;
• лог можно выводить в консоль, в файл или передавать с помощью сокетов или API в другую программу;
• когда мы подключили логгер в наш проект с арканоидом на JavaScript, то неожиданно для себя нашли ошибку, которую без логгера мы не замечали.

Теперь поработаем с логгером в проекте на Python и посмотрим, найдём ли мы ещё ошибки в своём коде.

Настраиваем логгер

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

С этого момента мы можем использовать логгер в любом месте, просто указав нужный уровень сообщения, например:

logging.debug("Это сообщение для отладки программы") logging.info("Информационное сообщение") logging.warning('Предупреждение — нужно проверить, всё ли в порядке') logging.error("Ошибка! Что-то пошло не так")

Если запустить этот код, то мы увидим только последние два сообщения:

Дело в том, что логгер по умолчанию выводит только сообщения с уровнем warning и выше. Чтобы вывести все сообщения начиная с самого нижнего уровня debug, используем такую команду:

Теперь все сообщения на месте:

Выводим сообщения в файл

По умолчанию логгер пишет всё в консоль, но можно отправлять все сообщения в файл. Для этого в настройках логгера укажем имя файла:

logging.basicConfig(level=logging.DEBUG, filename="thecode.log")

Файл появится в той же папке, что и программа, и мы сможем открыть его в любом текстовом редакторе:

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

# добавляем поток вывода в файл file_log = logging.FileHandler("thecode.log") # и вывод в консоль console_out = logging.StreamHandler() # указываем эти два потока в настройках логгера logging.basicConfig(handlers=(file_log, console_out), level=logging.DEBUG)

Теперь лог будет выводиться и в файл, и в консоль.

Добавляем логгер в проект

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

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

Мы добавим несколько логов

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

Вот готовый код:

# подключаем логгер import logging # добавляем поток вывода в файл file_log = logging.FileHandler("thecode.log") # и вывод в консоль console_out = logging.StreamHandler() # указываем эти два потока в настройках логгера logging.basicConfig(handlers=(file_log, console_out), level=logging.DEBUG) logging.info("Объявляем переменные") # Сколько джуниоров было на старте в старом офисе junior = 1 # Сколько дней ушло на заполнение старого офиса day = 30 # Сделаем диапазон для цикла month = range(1,day) # Каждый день в старом офисе… logging.warning("Входим в цикл удваивания старых джуниоров") for current_day in month: # …удваивалось количество джуниоров junior = junior * 2 logging.debug("Количество старых джуниоров: " + str(junior)) # В новом офисе у нас уже два джуниора на старте new_junior = 2 # Заведём переменную для подсчёта дней в новом офисе new_day = 0 # Пока в новом офисе не станет столько же людей, как и в новом… logging.warning("Входим в цикл удваивания новых джуниоров") while new_junior 

Когда мы запустим этот код, то увидим очень много сообщений в консоли. Это произошло потому, что мы выводим логи всех уровней — от отладочных до критических:

Так произошло из-за того, что мы указали уровень DEBUG в настройках логгера. Изменим их так, чтобы логгер нам их не показывал, а всё другое — оставил:

logging.basicConfig(handlers=(file_log, console_out), level=logging.INFO)

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

Любишь Python? Зарабатывай на нём!
Изучите самый модный язык программирования и станьте крутым бэкенд-разработчиком. Старт — бесплатно.

Получите ИТ-профессию

В «Яндекс Практикуме» можно стать разработчиком, тестировщиком, аналитиком и менеджером цифровых продуктов. Первая часть обучения всегда бесплатная, чтобы попробовать и найти то, что вам по душе. Дальше — программы трудоустройства.

Похожие публикации:

1. Addeventlistener js что это
2. Как организовать работу команды
3. Как правильно разместить телескоп на борту мкс
4. Опера не открывает некоторые сайты как исправить