Логирование в Java и Spring Boot: JSON, MDC и уровни логов

← назад к разделу

Когда что-то ломается в продакшне в три ночи, единственное, что помогает понять причину — это логи. Если они написаны правильно, расследование занимает минуты. Если нет — часы. Разберём, как устроено нормальное логирование в Java/Spring. Начнём с того, во что обходится формат логов, когда ночью нужно найти один запрос среди миллиона строк.

Почему обычные логи не работают в продакшне

Новичок обычно пишет так:

System.out.println("Order created: " + order.getId());

или так:

Logger log = LoggerFactory.getLogger(OrderService.class);
log.info("Order created: " + order.getId() + " for customer " + order.getCustomerId());

Выглядит разумно. Но в реальном продакшне это не работает:

• Если сервис обрабатывает 1000 запросов в секунду, логи превращаются в миллион строк. Найти нужную без фильтрации невозможно.
• Нет контекста: кто делал запрос? В рамках какого трейса? Какой requestId?
• Строковая склейка через + работает всегда, даже когда уровень выключен — лишний расход CPU.
• System.out не попадает в единый конвейер логов: без уровня, без формата, без метаданных.

Промышленное решение — писать каждую строку лога как JSON-объект с фиксированными полями:

{"ts":"2026-09-23T21:14:05Z","level":"ERROR","service":"orders","traceId":"4bf92f","orderId":"8891","message":"Failed to charge payment"}

Это называют structured logging. Такие логи Loki, ELK и Datadog индексируют и фильтруют без регулярных выражений.

JSON в продакшне, текст при разработке

Logback — стандартный логгер в Spring Boot. Он поддерживает профили: в разработке удобнее читаемый текст, в продакшне нужен JSON.

<configuration>
    <springProfile name="!prod &amp; !staging">
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>%d{HH:mm:ss.SSS} %-5level [%thread] %X{traceId:-} %logger{30} - %msg%n</pattern>
            </encoder>
        </appender>
    </springProfile>

    <springProfile name="prod,staging">
        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <includeMdcKeyName>traceId</includeMdcKeyName>
                <includeMdcKeyName>requestId</includeMdcKeyName>
                <includeMdcKeyName>userId</includeMdcKeyName>
            </encoder>
        </appender>
    </springProfile>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

Условие первого блока — «любой профиль, кроме prod и staging», а не dev,test: <root> ссылается на STDOUT безусловно, и если запустить сервис вообще без активного профиля (локально, в тестах, в сборке), appender'а с таким именем не окажется. Logback напишет «no appender named STDOUT» — и логов не будет вовсе.

Для JSON-кодирования подключают библиотеку logstash-logback-encoder. С Spring Boot 3.4 то же самое умеет и сам фреймворк — одна строка logging.structured.format.console=ecs вместо библиотеки и XML. В продакшне каждая строка лога выглядит так:

{
  "@timestamp": "2026-05-25T22:30:00.123Z",
  "level": "INFO",
  "logger_name": "ru.vikulinva.order.OrderService",
  "message": "Order confirmed: orderId=12345",
  "traceId": "5e92c8a3b1f4d2e6a7c8e9f0a1b2c3d4",
  "requestId": "0193a8f3-7c21-7e3f-9b4a-...",
  "userId": "user-42"
}

Поля из MDC лежат прямо в корне события, а не в отдельном блоке mdc — так их кладёт LogstashEncoder, и так их ждут фильтры Loki и Kibana. И ещё одна тонкость: как только вы указали хотя бы один <includeMdcKeyName>, список становится белым — всё, что в него не попало, в лог не поедет.

@Slf4j — как объявить логгер

Раньше каждый класс начинался с такой строки:

private static final Logger log = LoggerFactory.getLogger(OrderService.class);

Это шаблонный код, который легко написать неправильно (например, скопировать из другого класса и забыть поменять имя). Lombok решает проблему аннотацией @Slf4j:

@Component
@RequiredArgsConstructor
@Slf4j
public class OrderService {

    private final OrderRepository orderRepository;

    public Order confirm(Long orderId) {
        log.info("Confirming order: orderId={}", orderId);
        var order = orderRepository.findById(orderId).orElseThrow();
        order.confirm();
        return orderRepository.save(order);
    }
}

Lombok генерирует private static final Logger log с правильным именем класса. Поле log появляется в скомпилированном коде, не в исходнике.

Параметры через {}, не через +

Slf4j поддерживает ленивые плейсхолдеры:

// правильно
log.info("Order created: orderId={} customerId={}", order.id(), order.customerId());

// неправильно
log.info("Order created: orderId=" + order.id() + " customerId=" + order.customerId());

Разница в том, когда вызывается toString(). При склейке через + — всегда, даже если уровень выключен. При {} — только если уровень активен. Для INFO разница небольшая. Для DEBUG на продакшне — критическая: если у объекта тяжёлый toString, он выполняется миллионы раз впустую.

Правило простое: всегда {}, никогда +.

Уровни логов и их смысл

Уровень отвечает на вопрос «кто это читает и что делает»: ERROR будит дежурного, потому что без человека не обойтись; WARN не будит — сервис справился сам, но утром на это стоит посмотреть; INFO читают при разборе, что происходило с заказом; DEBUG и TRACE включают на время расследования, потому что в обычном режиме они утопят полезное. Так получаются пять уровней:

Уровень	Когда использовать
ERROR	Неустранимый сбой, требует действия: упавшая транзакция, недоступный внешний сервис, необработанное исключение. Всегда со stack trace.
WARN	Проблема, от которой сервис оправился: retry, fallback, circuit breaker открылся.
INFO	Важное бизнес-событие: «заказ подтверждён», «пользователь зарегистрирован», старт/остановка пакетной задачи с количеством.
DEBUG	Детали для отладки. На продакшне выключен, включается временно при расследовании.
TRACE	Максимальная детализация. Только локально при разработке.

Примеры:

log.error("Failed to charge payment: paymentId={}", paymentId, ex);
log.warn("Circuit breaker OPEN for payment-provider, falling back to queue");
log.info("Order confirmed: orderId={} customerId={} amount={}",
    order.id(), order.customerId(), order.amount());
log.debug("Order aggregate state after confirm: {}", order);

Частая ошибка начинающих — писать INFO на каждый HTTP-запрос («Handling GET /orders/123»). Это и есть access-лог, он существует отдельно. Без этой дисциплины 80% объёма продакшн-логов — шум, в котором ничего не найти.

Как включить DEBUG на живом сервисе

В таблице написано «включается временно при расследовании», и здесь стоит сказать, как именно — потому что перезапуск с новым уровнем убивает то состояние, которое вы собирались изучить, а «выкатить с DEBUG» на проде занимает полчаса.

Уровень меняется на работающем процессе одним запросом к Actuator:

curl -X POST http://localhost:8081/actuator/loggers/ru.vikulinva.order.payment   -H 'Content-Type: application/json'   -d '{"configuredLevel":"DEBUG"}'

Работает это по пакетам: указываете не класс, а ветку, и уровень применяется ко всему, что под ней. Посмотреть, что сейчас установлено, — GET /actuator/loggers/<имя>; вернуть как было — {"configuredLevel": null} (именно null, а не INFO: так уровень снова наследуется от родителя, а не фиксируется). Для этого в конфигурации должен быть открыт эндпоинт loggers, о чём статья про конфигурацию.

Два правила пользования. Точечно, а не глобально: DEBUG на корневом логгере под нагрузкой даёт лавину строк, в которой нужную не найти, и заодно счёт за логи; включают одну ветку — тот пакет, где идёт расследование.

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

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

Сколько стоит одна строка лога

Про производительность логирования обычно говорят только про {} против +, и это самая маленькая часть цены. Настоящая цена в том, что запись в лог по умолчанию синхронная: поток, обрабатывающий запрос, сам форматирует строку, сам превращает её в JSON и сам ждёт, пока операционная система примет её в стандартный вывод. Пока он этим занят, он не обрабатывает запрос.

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

Лечится асинхронной записью: строки складываются в очередь, а отдельный поток разбирает её и пишет.

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="STDOUT"/>
    <queueSize>8192</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <neverBlock>true</neverBlock>
</appender>

Каждая строка здесь важна. queueSize — сколько записей ждут в памяти (по умолчанию 256, для нагруженного сервиса мало). discardingThreshold: 0 отключает поведение по умолчанию, при котором Logback молча выбрасывает записи уровня DEBUG и INFO, как только очередь заполнена на 80 % — то есть при всплеске нагрузки вы теряете именно те строки, которые собирались читать. neverBlock: true говорит «лучше потерять запись, чем задержать запрос».

И здесь придётся сделать выбор, который никто не сделает за вас: при переполнении очереди либо теряются строки, либо тормозит сервис. Третьего нет. Разумная расстановка: neverBlock: true (терять) для INFO и ниже, потому что потеря отладочной строки дешевле замедления всех запросов; блокировка допустима только там, где потеря записи недопустима юридически — аудит платежей и доступа, и такие записи вообще правильнее писать не в журнал, а в базу с транзакцией.

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

Что даёт больше всего без всякой асинхронности: не писать лишнего. Одна строка на запрос при тысяче запросов в секунду — это около 26 гигабайт в сутки и заметная доля процессора на форматирование JSON.

MDC — контекст в каждом сообщении

MDC (Mapped Diagnostic Context) — это словарь, который Logback автоматически добавляет к каждому лог-сообщению в текущем потоке. Именно так traceId и requestId оказываются в JSON без явного указания в каждом log.info.

Три ключевых поля:

• traceId и spanId — их добавляет трассировка, руками класть не надо. Имя поля зависит от того, чем она подключена: мост Micrometer Tracing пишет traceId и spanId, аппендер OpenTelemetry — trace_id и span_id. Написание стоит выбрать одно на все сервисы, иначе поиск по логам всей системы не соберётся. Дальше по этому полю находят все логи конкретного запроса — даже в распределённой системе.
• requestId — фильтр при входящем HTTP-запросе берёт заголовок X-Request-Id или генерирует UUID, кладёт в MDC.
• userId — добавляется после JWT-валидации в фильтр-цепочке Spring Security.

Благодаря MDC можно искать в Loki: {traceId="5e92c8a3..."} — и получить все лог-строки этого запроса от всех сервисов в хронологическом порядке. Без MDC каждое расследование начинается с нуля.

Подробнее о том, как настроить фильтры — Context propagation.

Что и где логировать

Логи полезны на границах — там, где сервис общается с внешним миром:

• Входящий REST-запрос — access-лог настраивается отдельно (server.tomcat.accesslog.enabled или тот же лог на балансировщике). В самом handler INFO пишут только для критичных команд (платежи).
• Исходящий HTTP — INFO на вызов («Вызов payment-provider»), WARN на 4xx/5xx, ERROR на сетевую ошибку.
• Доменные события — INFO на публикацию: «Published OrderCreated: orderId=...».
• Планировщики — INFO на старт и конец с количеством: «Outbox relay опубликовал 100 событий за 50ms».

Внутри бизнес-логики логируют только важные решения или деградации. «Entering method», «Loaded N rows» — это шум.

Частые ошибки

Личные данные в логах

Email, телефон, ФИО, паспорт, номер карты, JWT-токены, пароли — всё это нельзя писать в логи в открытом виде. Доступ к логам обычно шире, чем к базе данных; хранятся они дольше; индексируются везде.

// плохо — персональные данные в открытом виде
log.info("User registered: email={} phone={}", user.email(), user.phone());

// хорошо — только внутренний идентификатор
log.info("User registered: userId={}", user.id());

// хорошо — если нужно для расследования, маскировать
log.info("Email verification sent: userId={} emailMask={}",
    user.id(), maskEmail(user.email())); // u***@example.com

У способа с maskEmail(...) есть слабое место: он держится на дисциплине в каждом вызове. Достаточно одного нового разработчика, одного log.info("request: {}", body) при отладке, одного исключения, в сообщение которого библиотека положила запрос целиком, — и данные в журнале. Поэтому в командах, где это важно, ставят вторую линию защиты, не требующую дисциплины: маскирование в момент записи.

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

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
    <jsonGeneratorDecorator
        class="net.logstash.logback.mask.MaskingJsonGeneratorDecorator">
        <defaultMask>****</defaultMask>
        <path>phone</path>
        <valueMask>
            <value>\b[\w.%-]+@[\w.-]+\.[A-Za-z]{2,}\b</value>
            <mask>***@***</mask>
        </valueMask>
    </jsonGeneratorDecorator>
</encoder>

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

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

System.out.println и printStackTrace

Оба метода пишут в stdout без уровня, без MDC, без формата. Они не попадают в JSON-конвейер.

// плохо
System.out.println("Order: " + order);
e.printStackTrace();

// хорошо
log.info("Order: {}", order);
log.error("Unexpected error", e);

log.error без исключения

// плохо — stack trace теряется, причину не узнать
log.error("Failed to charge: " + e.getMessage());

// хорошо — Slf4j видит последний аргумент Throwable и добавляет stack_trace в JSON
log.error("Failed to charge: orderId={}", orderId, e);

Полный request body в логах для денег и персональных данных

// плохо — в теле запроса могут быть реквизиты карты
log.info("Charge request: {}", chargeRequest);

// хорошо — только идентификаторы
log.info("Charge request: orderId={} amount={}",
    chargeRequest.orderId(), chargeRequest.amount());

Когда JSON не нужен

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

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

Тесты. В отчёте о прогоне нужна причина падения, а не структура. JSON в тестовом выводе делает падение нечитаемым, а искать по нему всё равно никто не будет.

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

Многострочные записи — то, что портит JSON чаще всего, и стоит отдельного слова. Стек исключения — это десятки строк, и в кодировщике JSON он попадает в одно поле события одной строкой с символами перевода строки внутри: агент читает событие как одну запись, и стек остаётся целым. Ломается это в двух случаях: когда в журнал пишет не логгер, а сама библиотека или сторонний процесс (тогда стек уезжает в стандартный вывод построчно, и агент видит двадцать бессвязных записей — их придётся склеивать правилом на агенте, что ненадёжно), и когда в текстовом режиме кто-то настроил сборку многострочных записей по отступу. Отсюда простое требование: в продакшне в стандартный вывод пишет только логгер, а printStackTrace и прямая печать закрыты не потому, что «некрасиво», а потому что ломают разбор.

Глубже: что происходит после stdout: агент, конвейер, хранилище, срок и ценарасширенное

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

Агент на узле. На каждой машине или узле кластера работает агент (Fluent Bit, Vector, Promtail, OpenTelemetry Collector), который читает файлы, куда среда выполнения складывает stdout контейнеров, разбирает JSON, добавляет метаданные (сервис, под, узел, окружение), собирает пачки и отправляет дальше. Приложение о нём не знает; всё, что от приложения требуется, это JSON в одну строку на запись и никаких многострочных стеков без обрамления, иначе агент режет стек на отдельные записи.

Хранилище. Два семейства, и разница в цене в разы. Полнотекстовые (Elasticsearch, OpenSearch) индексируют каждое поле каждой строки: поиск по любому слову за секунды, а индекс весит больше самих логов и требует памяти. Хранилища с индексом только по меткам (Loki и похожие) индексируют сервис, окружение, уровень, а тело хранят сжатым и читают перебором внутри выбранного среза: в несколько раз дешевле, а поиск по редкому слову за неделю медленнее. Колоночные (ClickHouse) между ними. Управляемые сервисы облаков берут за приём по гигабайтам, о чём статьи про облака.

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

Цена и что делать, когда бюджет кончился. Сервис, пишущий 50 тысяч строк в секунду по 300 байт, даёт больше терабайта в сутки; в полнотекстовом хранилище это тысячи долларов в месяц, и тут заканчивается бюджет. Режут по порядку: журнал проверок здоровья и отладочный уровень отбрасывают на агенте, не доводя до хранилища; повторяющиеся записи одного вида превращают в метрику со счётчиком; на самых шумных путях включают выборку (каждая десятая успешная запись, все ошибки); сокращают горячий срок; переезжают с полнотекстового на индекс по меткам. Не режут никогда ошибки, предупреждения и аудит. И считают цену строки заранее: одна лишняя запись на запрос при тысяче запросов в секунду это 26 гигабайт в сутки.

Коротко

• В продакшне — JSON через logstash-logback-encoder, в разработке — читаемый текстовый pattern. Настраивается через профили Logback.
• Объявляй логгер через @Slf4j (Lombok), не через LoggerFactory.getLogger вручную.
• Параметры всегда через {}, никогда через + — Slf4j ленив и не вызывает toString на выключенных уровнях.
• ERROR — требует действия и всегда со stack trace. WARN — деградация, от которой оправились. INFO — важное бизнес-событие. DEBUG и TRACE — только для разработки.
• MDC автоматически добавляет requestId и userId к каждому лог-сообщению, а идентификаторы трассировки приходят от самой трассировки — под именами traceId/spanId или trace_id/span_id, смотря чем она подключена.
• Личные данные (email, телефон, паспорт, токены) в логах — серьёзное нарушение. Только идентификаторы или маскированные значения.
• System.out.println и e.printStackTrace() не работают в structured-конвейере — заменяй на log.*.
• После stdout строку читает агент на узле и везёт в хранилище: полнотекстовое дорого и быстро, по меткам дёшево и медленнее; горячее на две недели, архив на год; бюджет спасают отбрасывание на агенте, метрики вместо повторов и выборка, но не на ошибках.
• Уровень меняется на живом процессе запросом к /actuator/loggers по пакету, точечно и с обязательным возвратом на null; запрос приходит только на одну реплику.
• Запись в журнал по умолчанию синхронная и под нагрузкой тормозит обработку: асинхронный аппендер с очередью решает это ценой выбора «терять строки или задерживать запросы», а маскирование ставят тремя рубежами — ревью, кодировщик, конвейер.

Что почитать дальше

• Context propagation (MDC) — как traceId и requestId попадают в MDC.
• Metrics — Micrometer и Prometheus: что измерять и как.
• Tracing — OpenTelemetry и распределённая трассировка.