Антипаттерн: писать в лог всё подряд на всякий случай

MAATRIX

«Добавим побольше логов, потом пригодится» — фраза, которую произносят на каждом код-ревью, и логика в ней вроде бы правильная: больше данных — больше шансов разобраться в инциденте. На практике получается наоборот. Когда в лог пишется каждый вызов функции, каждый параметр запроса и каждая промежуточная переменная без разбора, найти в этом потоке действительно важную строку становится сложнее, чем если бы лога не было вообще. Разберём, почему избыточное логирование — не запас прочности, а отдельная проблема, и как логировать так, чтобы лог реально помогал, а не мешал.

Как выглядит этот антипаттерн на практике

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

def process_order(order_id, user_id, items, payment_method):
    logger.info(f"process_order called with order_id={order_id}")
    logger.info(f"user_id={user_id}")
    logger.info(f"items={items}")
    logger.info(f"payment_method={payment_method}")
    logger.info("Starting validation")
    user = get_user(user_id)
    logger.info(f"user fetched: {user}")
    logger.info("Validation passed")
    for item in items:
        logger.info(f"processing item: {item}")
        stock = check_stock(item)
        logger.info(f"stock check result: {stock}")
    logger.info("Calculating total")
    total = calculate_total(items)
    logger.info(f"total calculated: {total}")
    logger.info("Charging payment")
    charge_result = charge(payment_method, total)
    logger.info(f"charge result: {charge_result}")
    logger.info("process_order finished successfully")
    return charge_result

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

Второй частый вариант — DEBUG-логи, которые забыли выключить или изначально настроили писаться в общий продакшн-поток:

logging.basicConfig(level=logging.DEBUG)

Библиотеки вроде requests, SQLAlchemy или Django ORM на уровне DEBUG пишут буквально всё: полные тексты SQL-запросов с параметрами, заголовки HTTP-запросов, тела ответов сторонних API. Один эндпоинт с несколькими запросами к базе на DEBUG может сгенерировать больше строк, чем весь остальной сервис на INFO за час.

Логика, которая приводит к такому коду, обычно звучит так: «мы не знаем заранее, какая строка понадобится при разборе инцидента, поэтому запишем всё». Верно это лишь отчасти — записать действительно можно всё, а вот полезность от этого не растёт линейно, а после определённой точки начинает падать.

Проблема первая: шум маскирует сигнал

Главная и самая недооценённая проблема избыточного логирования — не место на диске, а то, что происходит с человеком, который открывает этот лог во время инцидента. У разработчика, который ищет причину сбоя в 3 часа ночи, есть ограниченное количество внимания и времени. Если в файле на 50 000 строк за час только 5 действительно значимых, найти их среди сорока пяти тысяч строк вида processing item: {...} — отдельная задача, которая съедает время, предназначенное для решения самого инцидента.

grep "ERROR" app.log | wc -l
# 3
wc -l app.log
# 187420

Три ошибки на 187 тысяч строк — соотношение сигнал/шум примерно 1 к 62000. Даже с grep по ключевому слову приходится вручную просматривать контекст вокруг каждого совпадения, потому что рядом с ошибкой легко пропустить связанную запись, которая случилась на 40 строк раньше или позже — между ними втиснуто ещё двадцать бесполезных строк про то, что цикл for item in items благополучно перешёл к следующей итерации.

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

Проблема вторая: рост затрат на хранение и обработку

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

Если логи уходят во внешнюю систему сбора — Graylog, Grafana Loki, ELK — оплата там обычно привязана к объёму данных или к числу хранимых записей. Сервис, который логирует каждый шаг обработки заказа, платит за хранение и индексацию каждой такой строки точно так же, как за единственную строку ERROR, которая реально понадобится при разборе. Разница в цене между «логировать только значимые события» и «логировать всё» при росте нагрузки в 5-10 раз ощущается не как пропорциональный рост счёта, а как его резкий скачок — это отдельно разобрано в статье про цену логирования и мониторинга при росте в десять раз.

Даже без внешней системы сбора, при простой записи в файл на диске сервера, избыточный лог тоже не бесплатен: диск заполняется быстрее, ротация срабатывает чаще, архивные .gz-файлы занимают место в бэкапах. Случай, когда лог вырос настолько, что занял всё свободное место, а разобрать в нём было почти нечего, — частый сценарий, разобранный в статье логи заняли 300 ГБ, и их никто не читал: проблема там не в объёме самом по себе, а в том, что этот объём не нёс диагностической ценности.

Проблема третья: риск случайного логирования чувствительных данных

Логирование «на всякий случай» почти всегда означает логирование целых объектов — user, payment_method, request.body — без разбора того, что конкретно внутри них лежит. Это системно повышает риск, что в лог попадёт что-то, чего там быть не должно: пароль, токен авторизации, номер карты, персональные данные клиента.

logger.info(f"payment_method={payment_method}")
# payment_method содержит номер карты, срок действия и CVV

Проблема не в том, что разработчик специально решил записать номер карты в лог — он записал объект целиком, не задумываясь, что внутри. При точечном логировании конкретных полей такой вопрос возникает сам собой («а нужно ли мне писать это поле?»), при логировании «всего подряд» — не возникает вовсе, потому что сама привычка исключает разбор содержимого.

Дальше эта строка живёт своей жизнью: попадает в файл на диске, может уехать в систему логирования с более широким доступом, чем у продакшн-базы, может случайно оказаться в логе сборки CI/CD, если переменная окружения с секретом логируется вместе с контекстом запуска. Конкретный разбор того, как секрет утекает именно через такой путь — не через взлом, а через привычку логировать «весь контекст» — приведён в статье про утечку секрета в лог сборки.

Правило простое и его стоит проговаривать вслух на код-ревью: если для события нужен целый объект, логируйте не сам объект, а список конкретных полей, каждое из которых явно проверено на отсутствие чувствительных данных. Это больше работы, чем logger.info(f"user={user}"), но именно она отделяет осознанное логирование от логирования «на всякий случай».

Проблема четвёртая: избыточный I/O может ощутимо влиять на производительность

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

Синхронная запись в файл — самый частый случай в простых конфигурациях — блокирует выполняющий поток на время, пока данные не уйдут в файловый дескриптор. При логировании каждого шага внутри цикла, обрабатывающего сотни или тысячи элементов, число таких операций растёт вместе с размером входных данных, и лог из вспомогательного инструмента превращается в часть критического пути запроса. Насколько это заметно, сильно зависит от диска и от того, синхронная запись или асинхронная — конкретных цифр по задержке называть не будем, они сильно разнятся от системы к системе, и любое число без замера на своём железе будет вводить в заблуждение. Ориентируйтесь на факт: чем больше строк лога на единицу полезной работы, тем больше суммарного времени уходит на это I/O, и при высокой частоте запросов это накапливается в задержку, которую видит уже конечный пользователь.

Отдельно стоит случай, когда за секунду в лог пытаются записать больше строк, чем система успевает обработать — очередь на запись растёт, буферы переполняются, приложение начинает терять записи или ждать, блокируясь на I/O. Практический предел по числу строк в секунду и способы его поднять разобраны в статье про потолок записи в лог — избыточное логирование приближает сервис к этому потолку заметно быстрее, чем осознанное логирование значимых событий.

Как сделать правильно: осознанные уровни логирования

Первый и самый простой шаг — реально использовать уровни логирования по их смыслу, а не писать всё через INFO, как часто получается по инерции.

Ключевая практическая мера — держать DEBUG выключенным в продакшне по умолчанию и включать его точечно, на конкретный сервис или модуль, на ограниченное время, когда идёт реальное расследование:

import logging

logger = logging.getLogger("myapp.orders")
logger.setLevel(logging.INFO)  # в проде по умолчанию

# при расследовании конкретного инцидента — временно:
logging.getLogger("myapp.orders").setLevel(logging.DEBUG)

Для приложений с конфигурацией через переменные окружения это делается ещё проще — уровень логирования читается из LOG_LEVEL при старте, и его можно поднять на время без изменения кода:

import os
import logging

logging.basicConfig(level=os.environ.get("LOG_LEVEL", "INFO"))

# обычный запуск
LOG_LEVEL=INFO python app.py

# на время расследования конкретного инцидента
LOG_LEVEL=DEBUG python app.py

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

Как сделать правильно: структурированное логирование значимых событий

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

import structlog

logger = structlog.get_logger()

def process_order(order_id, user_id, items, payment_method):
    order_logger = logger.bind(order_id=order_id, user_id=user_id)

    total = calculate_total(items)
    charge_result = charge(payment_method, total)

    if charge_result.success:
        order_logger.info(
            "order_completed",
            items_count=len(items),
            total=total,
            payment_status="charged",
        )
    else:
        order_logger.error(
            "order_payment_failed",
            items_count=len(items),
            total=total,
            failure_reason=charge_result.error_code,
        )

    return charge_result

Вместо дюжины строк на каждый заказ — одна структурированная запись на значимое событие (успех или отказ), с конкретными полями, а не с сериализацией целых объектов. На выходе — JSON-строка вида {"event": "order_completed", "order_id": "8842", "items_count": 3, "total": 4590, "payment_status": "charged", "timestamp": "2026-08-27T14:32:11Z"}.

Такую запись можно фильтровать по полю (payment_status="failed"), агрегировать (сколько заказов не прошло оплату за час), строить по ней метрику или алерт — то, что почти невозможно сделать надёжно с текстовой строкой вида logger.info(f"charge result: {charge_result}"), где формат зависит от того, как язык сериализовал произвольный объект в текст, и парсить это регулярным выражением — отдельная неблагодарная задача.

Практический ориентир для того, что считать «значимым событием», а что — шумом: событие значимо, если оно меняет состояние системы (заказ создан, платёж прошёл, сессия истекла), нарушает ожидаемый ход выполнения (повтор запроса, таймаут, отказ валидации) или является точкой входа/выхода из системы (запрос принят, ответ отправлен). Промежуточные шаги внутри одной функции, которые всегда выполняются одинаково при успешном пути, обычно значимым событием не являются — это кандидат на DEBUG или на отсутствие лога вовсе.

Частые вопросы