Логирование — Python: Веб-разработка (Flask)

• Логирование
• Логирование в Flask
• Уровни логирования
• Ротация логов
• Заключение

Программисты проводят много времени, отлаживая свои программы, пытаясь разобраться, почему они не работают — или работают неправильно. Когда говорят про отладку, подразумевают либо отладочную печать, либо использование специальных программ – дебагеров. С их помощью отслеживается выполнение кода по шагам, во время которого видно, как меняется содержимое переменных. Эти способы хорошо работают в небольших программах, но в реальных приложениях быстро становятся неэффективными.

Возьмем для примера типичный сайт. Что он в себя включает?

• DNS - система трансляции имени сайта в ip-адрес сервера.
• Веб-сервер - программа, обслуживающая входящие запросы, перенаправляет их в код приложения и забирает от приложения данные для пользователей.
• Физический сервер (или виртуальный) с его окружением - включает в себя операционную систему, установленные и запущенные обслуживающие программы, например, мониторинг.
• База данных - внешнее хранилище, с которым связывается код приложения и обменивается информацией.
• Само приложение - помимо кода, который пишут программисты, приложение включает в себя сотни тысяч и миллионы строк кода сторонних библиотек. Кроме этого, код работает внутри фреймворка, у которого свои собственные правила обработки входящих запросов.
• Фронтенд часть - код, который выполняется в браузере пользователя. И системы сборки для разработки, например, Webpack.

И это только самый простой случай. Реальность же значительно сложнее: множество разноплановых серверов, системы кеширования (ускорения доступа), асинхронный код, очереди, внешние сервисы, облачные сервисы. Все это выглядит как многослойный пирог, внутри которого где-то работает написанный нами код. И этот код составляет лишь небольшую часть всего происходящего. Как в такой ситуации понять, на каком этапе был сбой, или все пошло не по плану? Для этого, как минимум, нужно определить, в каком слое произошла ошибка. Но даже это не самое сложное. Об ошибках в работающем приложении узнают не сразу, а уже потом, — когда ошибка случилась и, иногда, больше не воспроизводится.

Логирование

И для всего этого многообразия систем существует единое решение — запись действий программы - логирование. В простейшем случае логирование сводится к файлу на диске, куда разные программы записывают свои действия во время работы. Такой файл называют логом или журналом. Как правило, внутри лога одна строчка соответствует одному действию.

# Формат: ip-address / date / HTTP-method / uri / response code / body size
173.245.52.110 - [19/Jan/2021:01:54:20 +0000] "GET /my HTTP/1.1" 200 46018
108.162.219.13 - [19/Jan/2021:01:54:20 +0000] "GET /sockjs-node/244/gdt1vvwa/websocket HTTP/1.1" 0 0
162.158.62.12 - [19/Jan/2021:01:54:20 +0000] "GET /packs/css/application.css HTTP/1.1" 304 0
162.158.62.84 - [19/Jan/2021:01:54:20 +0000] "GET /packs/js/runtime-eb0a99abbe8cf813f110.js HTTP/1.1" 304 0

Выше небольшой кусок лога веб-сервера Хекслета. Из него видно ip-адрес, с которого выполнялся запрос на страницу и какие ресурсы загружались, метод HTTP, ответ бекенда (кода) и размер тела ответа в HTTP. Очень важно наличие даты. Благодаря ей всегда можно найти лог за конкретный период, например на то время, когда возникла ошибка. Для этого логи "грепают" (слово пошло от консольного приложения grep), то есть ищут по ним запись:

# Выведет 4 минуты логов за 31 марта 2020 года с 19:31 по 19:35
grep "31/Mar/2020:19:3[1-5]" access.log

Когда программисты только начинают свой путь, они, часто не зная причину ошибки, опускают руки и говорят «я не знаю, что случилось, и что делать». Опытный же разработчик всегда первым делом говорит «а что в логах?».Анализировать логи — один из базовых навыков в разработке. В любой непонятной ситуации нужно смотреть логи. Логи пишут все программы без исключения, но делают это по-разному и в разные места. Чтобы точно узнать, куда и как, нужно идти в документацию конкретной программы и читать соответствующий раздел документации.

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

Flask использует встроенный модуль logging. Все сообщения логируются объектом app.logger. Чтобы записать в лог сообщение, его нужно передать в один из его методов:

from flask import Flask
import requests

app = Flask(__name__)


BOOKS_API_URL = # внешний API

@app.route("/")
def index():
    app.logger.info("Получен запрос к главной странице")
    return "Добро пожаловать в библиотеку!"


@app.route("/books")
def get_books():
    app.logger.debug("Начинаем запрос к внешнему API")

    try:
        app.logger.info(f"Отправляем GET запрос к {BOOKS_API_URL}")
        response = requests.get(BOOKS_API_URL)
        response.raise_for_status()

    except requests.exceptions.Timeout:
        app.logger.error(f"Таймаут при запросе к {BOOKS_API_URL}")
        return "Сервер не отвечает", 504

    except requests.exceptions.RequestException as e:
        app.logger.error(f"Ошибка при запросе к API: {str(e)}")
        return "Произошла ошибка при получении списка книг", 500

    books = response.json()
    app.logger.debug(f"Получено {len(books)} книг")
    return f"Книги: {books}"

@app.route("/status")
def status():
    app.logger.debug("Проверка статуса приложения")
    try:
        requests.get(BOOKS_API_URL)
        app.logger.info("Внешний API доступен")
        status = "OK"
    except Exception as e:
        app.logger.warning(f"Внешний API недоступен: {str(e)}")
        status = "API недоступен"

    return f"Статус системы: {status}"

По умолчанию логи выводятся в консоль:

[2025-02-12 14:30:05,456] INFO in app: Получен запрос к главной странице
127.0.0.1 - - [12/Feb/2025 14:30:05] "GET / HTTP/1.1" 200 -

Обратите внимание на методы логера: debug(), info(), warning(), error(). Каждый из методов добавляет сообщение своего уровня логирования.

Уровни логирования

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

• debug
• info
• warning
• error
• critical

У уровней есть также порядок их серьезности:

DEBUG < INFO < WARNING < ERROR < CRITICAL

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

@app.route("/books")
def get_books():
    app.logger.debug("Начинаем запрос к внешнему API")

    try:
        app.logger.info(f"Отправляем GET запрос к {BOOKS_API_URL}")
        response = requests.get(BOOKS_API_URL)
        response.raise_for_status()

    except requests.exceptions.Timeout:
        app.logger.error(f"Таймаут при запросе к {BOOKS_API_URL}")
        return "Сервер не отвечает", 504

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

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

Во Flask по умолчанию используется уровень warning. При таком уровне будут выводиться и warning, и error. Если поставить уровень error, то будут выводиться только ошибки. А если debug, то мы получим лог, максимально наполненный данными. Обычно debug приводит к многократному росту выводимой информации.

Регулировать уровень выводимых логов можно через параметр setLevel(logging.<LEVEL>):

app.logger.setLevel("INFO")


@app.route("/index")
def index():
    app.logger.debug("Debug from index!")
    app.logger.info("Info from index!")
    app.logger.warning("Warning from index!")
    app.logger.error("Error from index!")
    return "Index"

Теперь будут выводиться сообщения от уровня info и выше:

[2025-02-10 19:10:54,858] INFO in app: Info from index!
[2025-02-10 19:10:54,858] WARNING in app: Warning from index!
[2025-02-10 19:10:54,858] ERROR in app: Error from index!
127.0.0.1 - - [10/Feb/2025 19:10:54] "GET /index HTTP/1.1" 200 -

Ротация логов

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

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

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

Заключение

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

Самостоятельная работа

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

Дополнительные материалы

1. Логирование в Flask
2. Библиотека Python logging