23.09.2025 09:16
T1_IT 0 300 Источник

Логирование (журналирование) — это не просто запись событий в файл, а стратегический инструмент для диагностики, мониторинга и обеспечения безопасности приложений. Небрежный подход к логированию может привести к серьёзным проблемам: от бесполезных терабайтов данных, в которых невозможно найти нужную информацию, до падения production-систем из-за перегрузки подсистемы логирования. В этой статье мы рассмотрим:

  • рекомендации по выбору уровня детализации (FATAL, ERROR, INFO, DEBUG, TRACE);

  • почему контекст в логах не менее важен, чем сами сообщения;

  • методики сокращения объёма логов без потери полезности;

  • как обеспечить производительность и отказоустойчивость приложения при формировании логов;

  • тестирование логов как не менее важную часть процесса по сравнению с тестированием кода.

Достаточность логирования

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

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

Качество логирования зависит от правильного выбора уровня детализации. Каждый уровень (FATAL, ERROR, WARN, INFO, DEBUG, TRACE) имеет свою область применения. Вот рекомендуемое разделение типа логов по уровням:

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

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

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

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

  • DEBUG — более подробная, расширенная информация о шагах бизнес-логики, подробные шаги доступа во внешние системы. Информация на этом уровне должна быть достаточна, чтобы определить, что происходит без подключения отладчика. Нужно учесть, что эта информация не будет доступна при первичном появлении проблемы, поэтому записи на уровне DEBUG должны быть дополнением к записям типа INFO.

  • TRACE — дополнительная информация к DEBUG: большие DTO, содержимое массивов и т. п. Необходимо следить за величиной записи лога, чтобы она укладывалась в установленные пределы.

Контекст записи

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

2025-02-03 13:00:01 ERROR Отказ в репозитории
2025-02-03 13:00:01 INFO  Сохранение прошло успешно

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

Решение
Сравним с такими записями:

2025-06-15T08:15:30.123456789Z INFO  |b566a678| ProductRepository : Регистрация продукта id=36
2025-06-15T08:15:30.987654321Z ERROR |d346f325| UserRepository : Редактирование пользователя id=34. Ошибка AUTH-25

*(в документации «AUTH-25»: ошибка аутентификации в БД)

Ситуация прояснилась: ошибка в репозитории UserRepository, связанная с аутентификацией, нужно проверить актуальность пароля к БД пользователей. Успешное сохранение относилось к другому репозиторию и не связано с проблемой.
Хорошая запись в лог описывает следующие аспекты:

  1. Когда случилось событие (2025-06-15T08:15:30.123456789Z). Рекомендуется указывать время с наносекундами: даже при использовании миллисекунд в нагруженной системе можно получить одинаковое время и порядок записей нарушится, в некоторых случаях не будет известно, какое событие произошло раньше.

  2. Сквозной ID операции (например, в связке с системой трассировки). Это особенно важно, если операция составная (|b566a678|).

  3. Место, где произошло событие: класс, компонент и т. п. (ProductRepository).

  4. Что именно произошло и какой контекст события, значения важных переменных, шаг операции (Редактирование пользователя id=34. Ошибка AUTH-25).

Для разбора проблем бывает полезно записывать в лог информацию о параметрах вызова сторонних систем: логировать запрос, ответ, объединяя записи с помощью сквозного идентификатора.

Запись лога без контекста в большинстве случаев бессмысленная и даже вредная: она «успокаивает» разработчика: «Ну я же сделал запись в лог!» Такие записи не помогают искать проблемы, получается бесполезный лог и много потраченных сил и нервов на поиск проблемы.

Рекомендация по code-review

  • Любая запись без контекста должна быть под пристальным вниманием на Code Review.

Маскирование

Проблема
При логировании (например, HTTP-запросов, ответов API, пользовательских объектов) можно случайно записать конфиденциальные данные: пароли, токены, персональные данные, платёжную информацию. Это создаёт риски утечки данных через логи (например, при отправке в поддержку), нарушения требований регуляторов (GDPR, PCI DSS и др.) и нарушения безопасности (например, если логи доступны третьим лицам).

Решение
Автоматическая маскировка чувствительных полей с помощью подходящих методов библиотеки логирования (запреты вывода полей типа password, маскирование полей через RegExp в настройках библиотеки логирования).

Рекомендация по code-review

  • Убедиться, что маскировка работает на всех уровнях логирования (DEBUG, TRACE).

  • Проверить исключение чувствительных полей из методов типа toString или существование RegExp на маскирование полей в настройках библиотеки логирования.

Техники сокращения объёма логов

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

Расширенное логирование при ошибке

Проблема
Разберем следующий кейс: есть сложный алгоритм, множество шагов, использование больших по объёму данных. Алгоритм выполняется часто и подробное логирование приводит к генерации большого количества «тяжёлых» записей. Сократить их нельзя, в процессе выполнения могут возникнуть ошибки, и для разбора нужен подробный лог.
Решение
Записывать в лог основные шаги алгоритма, но параллельно собирать информацию в некий объект-статус исполнения. Если возникает ошибка, вывести в лог статус исполнения с подробными данными (возможно, разбив на несколько записей, чтобы одна запись не была слишком большой).

class AlgorithmX {
    private ExecutionStatus status = new ExecutionStatus();

    void run() {
        try {
            status.start("Step1: Load data");
            loadData();
            status.logSuccess();

            status.start("Step2: Process");
            processData();
            status.logSuccess();
        } catch (Exception e) {
            status.logErrorDetails(logger); // Выводит статус частями
            throw e;
        }
    }
}

Рекомендация по code-review

  • Основные шаги логируются кратко, детальные данные (большие объекты, промежуточные результаты) сохраняются в объекте-статусе, но не пишутся в лог автоматически.

  • Статус содержит достаточно информации для диагностики.

  • Статус исполнения выводится частями (например, по 10 КБ на запись).

  • Производительность не деградирует из-за сбора статуса.

Периодические задачи

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

2025-02-03 13:01:01 INFO Обработано 0 заданий
2025-02-03 13:02:01 INFO Обработано 0 заданий
2025-02-03 13:03:01 INFO Обработано 0 заданий
2025-02-03 13:04:01 INFO Обработано 0 заданий
...

Это не информативно и не несёт полезной информации, кроме того, что сигнализирует о работе расписания.

Решение
Увеличить период записи в лог и дополнить статистической информацией:

2025-06-15T10:15:30.123456789Z INFO JobSchedule : За период с 2025-06-15T08:15:30 по 2025-06-15T10:15:30 обработано успешно 135 заданий, неудачно 3
2025-06-15T12:15:30.123456789Z INFO JobSchedule : За период с 2025-06-15T10:15:30 по 2025-06-15T12:15:30 обработано успешно 56 заданий, неудачно 0

Рекомендация по code-review

  • Логируются только существенные выполнения задачи (например, раз в N минут/часов, а не при каждом запуске).

  • Для ошибок сохраняется непосредственный вывод в лог.

  • Логи не пишутся при нулевых результатах (пример: Обработано 0 заданий).

  • Периодические задачи отбрасывают необходимые метрики в систему мониторинга (счётчик вызовов, счётчик выполненных работ, счётчик ошибок).

Коды ошибок/операций

Проблема
При генерации большого объёма логов даже небольшие оптимизации длины записи способны ощутимо сократить затраты на хранение. В логах часто встречаются повторы:

2025-06-15T10:15:30.123456789Z INFO  |b566a678| AuthModule: Ошибка ввода неверного логина или пароля пользователя, пользователь ivanov, неверный пароль
2025-06-15T10:15:30.123456789Z INFO  |e6575098| AuthModule: Ошибка - пользователь petrov заблокирован
2025-06-15T12:15:30.123456789Z INFO  |c987a465| AuthModule: Ошибка ввода неверного логина или пароля пользователя, пользователь semenov, неверный пароль

Решение
Ввести коды ошибок (описанные в документации), который позволят кратко описать ситуацию:

2025-06-15T10:15:30.123456789Z INFO  |b566a678| AuthModule: AUTH-ERR-1, ID=ivanov
2025-06-15T10:15:30.123456789Z INFO  |e6575098| AuthModule: AUTH-ERR-4, ID=petrov
2025-06-15T12:15:30.123456789Z INFO  |c987a465| AuthModule: AUTH-ERR-1, ID=semenov

Рекомендация по code-review

  • Обратить внимание на повторяющиеся сообщения (например, Ошибка ввода неверного логина или пароля) и заменить их на краткие коды.

  • Коды задокументированы и понятны команде поддержки.

  • Описания ошибок должны содержать возможные причины и способы исправления.

Логирование коллекций

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

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

Рекомендация по code-review

  • Обратить внимание на логирование сложных объектов (коллекций, JSON-структур и т. п.).

  • Убедиться, что в промышленной среде такие записи не приведут к перегрузке логов из-за их чрезмерного размера.

Много мелких однотипных сообщений

Проблема
Давайте разберём такой пример: разрабатывается процесс обработки заявок, и лог этого процесса состоит из следующих записей:

2025-06-15T08:15:30.123456789Z INFO |b566a678| Worker : Обработана заявка id=56736
2025-06-15T08:15:30.987654321Z INFO |b566a678| Worker : Обработана заявка id=32453
2025-06-15T08:15:31.457457457Z INFO |b566a678| Worker : Обработана заявка id=58568
2025-06-15T08:15:31.567564354Z INFO |b566a678| Worker : Обработана заявка id=23552
...

При этом точное время обработки заявки не очень существенно.

Решение
Можно «схлопнуть» несколько ID заявок в одну запись, что может значительно сэкономить место для хранения лога благодаря экономии на атрибутах лога, таких как время, идентификаторы трассировок и т. п.:

2025-06-15T08:15:30.123456789Z INFO |b566a678| Worker : За период с 2025-06-15T08:15:30 по 2025-06-15T08:15:31 обработаны заявки: 56736, 32453... 
2025-06-15T08:15:30.123456789Z INFO |b566a678| Worker : За период с 2025-06-15T08:15:31 по 2025-06-15T08:15:32 обработаны заявки: 23552, 23523... 
...

Нужно ограничивать размер записи лога и формировать пачки ID заявок заранее определённого, конечного размера: разбивать одно сообщение на несколько, если одно сообщение становится слишком большим.

Рекомендация по code-review

  • Ошибочные записи не группируются с успешными.

  • Для ошибок сохраняется полный контекст, можно соотнести ошибку с текущим контекстом возникновения.

  • Соблюдены лимиты размера записей.

Производительность и отказоустойчивость

Асинхронная запись

Проблема
Рассмотрим пример: в Kubernetes развёрнут под, у него настроена проба liveness, при работе которой в лог пишутся сообщения. Происходит отказ системы записи логов (переполнен диск, нет связи с Kafka, куда отправляются логи, и т. п.). В этот момент liveness-проба отказывает: либо происходит ошибка, либо таймаут (из-за ожидания успешности записи лога), Kubernetes считает, что под неработоспособен, и завершает его работу. Новый под тоже не может запуститься. Всё приложение не работает из-за отказа системы регистрации логов. Такая проблема касается не только liveness-проб, но и работы самого приложения: довольно неприятно, если важный процесс прервался из-за ошибки при записи в лог.

Иногда потеря записей логов недопустима (например, когда используется для аудита безопасности). Но в большинстве случаев приложение всё же должно работать при отказе системы логирования (особенно, если оно кратковременное).

Решение
Применение неблокирующей (асинхронной) записи логов. Такой вариант поддерживают распространённые библиотеки логирования (например, Log4j2 и logback). Нужно настроить библиотеку на полную асинхронность (по умолчанию приложение блокируется при заполнении буфера логов на отправку). Правда, есть недостаток: при такой настройке при длительной недоступности системы регистрации логов будут теряться записи. Также нужно задать разумный размер буфера логов.

Рекомендация по code-review

  • Логгер не пробрасывает исключения при ошибках записи.

  • Liveness-проба не зависит от успешности записи логов.

  • Есть метрики и оповещения для мониторинга очереди логов. Есть fallback-логгер (например, в файл) на случай недоступности основного.

Сокращение затрат на формирование ненужных сообщений

Проблема
Формирование логов — это вычислительные затраты. Разберём пример кода:

logger.debug("User details: " + computeExpensiveUserReport());

При формировании такого лога произойдут две операции: вычисление объёмного отчёта в computeExpensiveUserReport() и конкатенация строк. Представим, что включён уровень INFO, в этом случае эти вычисления были выполнены напрасно: они всё равно не будут зафиксированы в системе логирования, а память и процессорное время будут потрачены.

Решение
Исправим код:

if (logger.isDebugEnabled()) {
	logger.debug("User details: {}", computeExpensiveUserReport());
}

в этом случае при включённом уровне INFO не произойдёт лишних вычислений.

Ещё пример:

logger.debug("User details: {}", user);

Здесь user — объект, в котором реализован метод toString(). Тут также не будет лишних вычислений при включённом уровне INFO: для формирования лога используется встроенный в библиотеку логирования шаблонизатор, метод user.toString() просто не будет вызван библиотекой на уровне INFO и выше.

Рекомендация по code-review

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

  • Если для формирования лога производятся вычисления, их нужно всегда обрамлять в проверку, что включён требуемый уровень логирования. Это делается с помощью встроенных методов библиотеки: они реализованы с учётом проверки уровня (например, DEBUG и ниже — TRACE).

Тестирование логирования

Проблема
Логи используют для тестирования программы, но они и сами требуют тестирования. Представим себе ситуацию: в промышленном контуре случаются ошибки, и уровня INFO оказалось недостаточно, чтобы определить причину. Решено переключить уровень на DEBUG. Команда сопровождения меняет значение в конфигурации, и программа, которая до этого работала, упала и больше не запускается. Возврат INFO позволяет снова запустить её, но к решению проблемы не приблизились, да ещё было прерывание работы программы с более фатальными последствиями. После разбора причин оказалось, что на уровне DEBUG формируется объект для записи в лог, при формировании которого случается ошибка Null Reference. При тестировании ПО этого никто не заметил, потому что никто не переключал программу на уровень DEBUG и не прогонял сценарии с таким уровнем.

Решение
Запускать тесты на максимальном уровне логирования, при этом настроить вывод лога в файл или консоль только до уровня INFO (чтобы не было избыточных логов в тестах).

Рекомендация по code-review

  • Убедиться, что проводится обязательное тестирование на уровнях DEBUG/TRACE.

Заключение

Эффективное логирование должно соблюдать три ключевых принципа:

  1. Информативность: логи должны содержать достаточно данных для анализа проблем без необходимости дополнительной отладки.

  2. Оптимальность: избыточные логи перегружают системы хранения и усложняют анализ.

  3. Безопасность: в логах не должно быть конфиденциальных данных (паролей, токенов, персональной информации).

Воячек Владислав
Архитектор, ИТ-холдинг Т1

Комментарии (0)