Context propagation и MDC в Spring Boot

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

Когда в логах нет ни requestId, ни userId, расследовать инцидент почти невозможно: непонятно, чей запрос упал, к какой трассировке относится строка, и что вообще произошло. Цель context propagation — сделать так, чтобы эти поля были в каждом логе автоматически, без передачи через параметры каждого метода.

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

Что такое MDC

MDC (Mapped Diagnostic Context) — это хранилище пар «ключ → значение», которое Slf4j/Logback привязывает к текущему потоку. Всё, что вы положили в MDC, автоматически появляется в каждой строке лога этого потока.

Без MDC нужно было бы писать так:

log.info("Processing order orderId={} requestId={} userId={}", orderId, requestId, userId);

С MDC достаточно:

log.info("Processing order orderId={}", orderId);
// requestId и userId подтянутся автоматически из MDC

Это делает логи чище и защищает от случаев, когда разработчик забыл передать requestId в метод — контекст уже в потоке.

Главное ограничение MDC: он потоко-локальный. Когда задача уходит в другой поток (асинхронные задачи, @Async, CompletableFuture), MDC в новом потоке пустой. Об этом — в разделе про TaskDecorator.

Строки одного запроса ничем не связаны: один фильтр на весь запрос

Самый важный компонент — фильтр, который кладёт requestId в MDC в самом начале каждого HTTP-запроса и очищает его в конце:

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MdcFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse resp,
                                     FilterChain chain) throws ServletException, IOException {
        var requestId = Optional.ofNullable(req.getHeader("X-Request-Id"))
            .orElseGet(() -> UUID.randomUUID().toString());
        MDC.put("requestId", requestId);
        resp.setHeader("X-Request-Id", requestId);
        try {
            chain.doFilter(req, resp);
        } finally {
            MDC.clear();
        }
    }
}

Что здесь происходит:

• Если клиент прислал заголовок X-Request-Id — используем его. Это позволяет клиенту и серверу использовать один и тот же идентификатор при разборе инцидента.
• Если заголовка нет — генерируем UUID.
• Кладём requestId в MDC — с этого момента он будет в каждом логе запроса.
• Возвращаем X-Request-Id в ответе — клиент может его сохранить и при необходимости предоставить в поддержку.
• В блоке finally вызываем MDC.clear() — это критически важно, об этом ниже.

@Order(Ordered.HIGHEST_PRECEDENCE) означает, что фильтр запускается первым — ещё до цепочки фильтров Spring Security. Это важно: если запрос падает на аутентификации, в логах всё равно будет requestId.

Заголовок от клиента нельзя брать как есть

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

Чем это плохо, по возрастанию неприятности. Мусор в поиске: клиент прислал пустую строку, одно и то же значение на все свои запросы или строку в килобайт — и по идентификатору больше ничего не находится. Порча журнала: если в значении есть перевод строки, в текстовом формате журнала оно превращается в отдельную запись, которую злоумышленник сочиняет сам — можно подделать строку уровня ERROR от чужого сервиса или закрыть кавычку так, что разбор сломается. Это классическая инъекция в журнал, и JSON-формат от неё защищает (перевод строки экранируется), но текстовый формат в разработке и любой агент со склейкой многострочных записей — нет. Порча метки в хранилище: если это же значение уходит куда-то ещё как метка, можно получить взрыв кардинальности с чужой стороны.

Проверка простая и делается один раз:

private static final Pattern SAFE_ID = Pattern.compile("[A-Za-z0-9._-]{1,64}");

private String requestId(HttpServletRequest req) {
    var header = req.getHeader("X-Request-Id");
    return header != null && SAFE_ID.matcher(header).matches()
            ? header
            : UUID.randomUUID().toString();
}

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

MDC.clear() в finally — почему это обязательно

Tomcat и другие серверы переиспользуют потоки из пула. После завершения одного запроса тот же поток берётся для следующего запроса другого пользователя.

Если не очистить MDC в finally, а вместо этого вызвать MDC.clear() в обычном коде:

// Опасно — MDC.clear() не выполнится при исключении
@Override
protected void doFilterInternal(HttpServletRequest req, HttpServletResponse resp,
                                 FilterChain chain) throws ServletException, IOException {
    MDC.put("requestId", UUID.randomUUID().toString());
    chain.doFilter(req, resp);
    MDC.clear();  // если выше бросили исключение — этой строки не будет
}

Сценарий: обработчик бросил исключение → MDC.clear() не вызвался → поток вернулся в пул → следующий запрос другого пользователя получил поток с чужим requestId и userId в MDC → все его логи будут помечены чужими данными.

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

И одна ловушка, о которой узнают поздно. Если обработчик возвращает DeferredResult, Callable или StreamingResponseBody, запрос на этом не заканчивается: поток Tomcat освобождается, цепочка фильтров сворачивается — и finally с MDC.clear() срабатывает, пока ответ ещё готовится. Остаток обработки идёт уже без контекста, а повторно фильтр не позовут: OncePerRequestFilter по умолчанию пропускает асинхронную доставку. Если в сервисе есть такие обработчики, переопределите shouldNotFilterAsyncDispatch() на false — тогда фильтр отработает и на второй заход.

trace_id и span_id — автоматически через OpenTelemetry

Если в проекте подключена библиотека opentelemetry-logback-mdc-1.0, трассировочные идентификаторы появляются в логах сами:

implementation("io.opentelemetry.instrumentation:opentelemetry-logback-mdc-1.0")

После этого в каждом логе будут идентификаторы текущего активного span'а. Только называются поля не так, как ожидает большинство: trace_id, span_id и trace_flags — через нижнее подчёркивание, как в спецификации OpenTelemetry. Привычный traceId в логах не появится, и поиск по нему ничего не найдёт.

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

<appender name="OTEL" class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
    <traceIdKey>traceId</traceIdKey>
    <spanIdKey>spanId</spanIdKey>
    <appender-ref ref="STDOUT"/>
</appender>

Важно не какое написание выбрано, а что оно одно на все сервисы: если один пишет trace_id, а другой traceId, собрать логи всей системы одним запросом не выйдет.

И ещё одна тонкость: аппендер не кладёт эти поля в MDC — он дописывает их к событию в момент записи строки. Значит, MDC.put("trace_id", ...) вручную делать не нужно, а MDC.clear() на них никак не влияет.

userId после аутентификации

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

@Component
@Order(SecurityProperties.DEFAULT_FILTER_ORDER + 10)
public class UserIdMdcFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse resp,
                                     FilterChain chain) throws ServletException, IOException {
        try {
            var auth = SecurityContextHolder.getContext().getAuthentication();
            if (auth != null && auth.isAuthenticated()) {
                MDC.put("userId", auth.getName());
            }
            chain.doFilter(req, resp);
        } finally {
            MDC.remove("userId");
        }
    }
}

Обратите внимание: здесь MDC.remove("userId"), а не MDC.clear(). Полную очистку делает MdcFilter в своём finally — этот фильтр лишь убирает конкретный ключ, чтобы не затронуть requestId, который продолжает жить до конца запроса. Идентификаторы трассировки трогать не приходится: их в MDC никто не клал, они дописываются к каждой строке отдельно.

TaskDecorator для асинхронных задач

Когда метод помечен @Async или задача уходит в CompletableFuture.runAsync(...), она выполняется на другом потоке из пула. MDC потоко-локальный — в новом потоке он пустой:

@Async
public CompletableFuture<Void> sendEmail(Long userId) {
    log.info("Sending email to user");  // requestId и traceId отсутствуют
    emailClient.send(userId);
    return CompletableFuture.completedFuture(null);
}

Это значит, что логи асинхронной задачи никак не связаны с исходным запросом — в трассировщике они выглядят оторванными.

Решение — TaskDecorator. Он запускается в момент передачи задачи в пул: копирует MDC из текущего потока и восстанавливает его в потоке-исполнителе:

@Bean
public TaskDecorator mdcTaskDecorator() {
    return runnable -> {
        var contextMap = MDC.getCopyOfContextMap();  // снимок MDC в submitting-потоке
        return () -> {
            var previous = MDC.getCopyOfContextMap();  // что было в потоке-исполнителе
            try {
                if (contextMap != null) {
                    MDC.setContextMap(contextMap);     // ставим контекст задачи
                } else {
                    MDC.clear();
                }
                runnable.run();
            } finally {
                if (previous != null) {
                    MDC.setContextMap(previous);       // возвращаем как было
                } else {
                    MDC.clear();
                }
            }
        };
    };
}

@Bean("taskExecutor")
public TaskExecutor taskExecutor(TaskDecorator decorator) {
    var executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(10);
    executor.setMaxPoolSize(50);
    executor.setQueueCapacity(100);
    executor.setTaskDecorator(decorator);
    executor.setThreadNamePrefix("async-");
    executor.initialize();
    return executor;
}

Обратите внимание на finally: там не MDC.clear(), а возврат прежней карты. Разница видна, когда задачу выполняет не свободный поток пула, а тот, кто её отправил, — так бывает при политике CallerRunsPolicy, при вложенной отправке задачи и просто в общем на всех пуле. Безусловный clear() в этом случае сотрёт контекст чужого, ни в чём не повинного запроса; возврат снимка — нет.

После этого логи из @Async-методов будут содержать requestId исходного запроса, и ветку задачи можно связать с породившим её запросом.

Копировать только MDC — значит потерять два остальных контекста

У показанного декоратора есть незаметный изъян: он переносит только MDC. А в потоке живут как минимум три потоко-локальных контекста: MDC, контекст трассировки (текущий спан) и контекст безопасности (кто выполняет операцию). Скопировали один — логи задачи получат requestId, но её спан окажется корнем новой трассы, а SecurityContextHolder в задаче будет пуст, и проверка прав внутри неё упадёт или, хуже, пропустит.

Штатное решение — библиотека micrometer-context-propagation, у которой одна задача: собрать все зарегистрированные контексты снимком и восстановить их на другом потоке:

@Bean
TaskDecorator contextTaskDecorator() {
    return runnable -> {
        ContextSnapshot snapshot = ContextSnapshotFactory.builder().build().captureAll();
        return snapshot.wrap(runnable);
    };
}

Кто попадает в снимок, определяется зарегистрированными участниками: Micrometer Tracing регистрирует контекст трассировки, мост SLF4J — MDC, Spring Security — свой контекст. То есть вместо трёх ручных декораторов получается один, и при добавлении новой библиотеки ничего не меняется. wrap возвращает задачу, которая сама ставит контекст перед запуском и восстанавливает прежний после — то есть та же аккуратность с возвратом снимка, что в примере выше, уже внутри.

Тот же снимок работает не только с пулом задач: snapshot.wrap(callable), оборачивание исполнителя целиком (ContextExecutorService) и явное setThreadLocals() внутри чужого обратного вызова. Ручной декоратор с одним MDC остаётся разумным только там, где в проекте нет ни трассировки, ни безопасности, — то есть почти никогда.

Виртуальные потоки: что меняется, а что нет

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

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

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

И MDC.clear() в finally всё равно пишут. Причин две. Первая: сервис может работать и на обычных потоках — профиль, версия, другой контейнер сервлетов, и код должен быть верным в обоих случаях. Вторая: в finally важно не только очистить, но и вернуть прежнее значение, а это нужно при вложенных установках контекста независимо от вида потоков.

Что меняется на практике. Во-первых, пулы задач становятся менее нужными: вместо исполнителя с фиксированным числом потоков берут исполнитель, создающий виртуальный поток на задачу, и TaskDecorator у такого исполнителя настраивается так же. Во-вторых, появляется новый механизм на замену потоко-локальному — значения с областью видимости (ScopedValue): значение видно внутри вызова и наследуется дочерними виртуальными потоками, то есть передаётся в них само. Это точный ответ на задачу «пронести контекст по цепочке вызовов», но у него есть ограничение, которое сейчас решает всё: библиотеки журналирования и трассировки читают потоко-локальные переменные, а не такие значения, поэтому переносить на них MDC пока нельзя — их используют для своего контекста в своём коде.

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

Как проверить, что контекст не утекает

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

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

@SpringBootTest(webEnvironment = WebEnvironment.RANDOM_PORT,
        properties = "server.tomcat.threads.max=1")   // один поток — второй запрос придёт на него же
class MdcLeakTest {

    @Autowired
    TestRestTemplate rest;

    @Test
    void secondRequestHasNoContextOfTheFirst() {
        rest.getForEntity("/test/boom?requestId=first", String.class);      // падает с 500

        var body = rest.getForEntity("/test/echo-mdc", String.class).getBody();

        assertThat(body).doesNotContain("first");
    }
}

Что здесь важно. Ограничение пула до одного потока — единственный способ гарантировать, что второй запрос попадёт на тот же поток, а не на свободный соседний: без него тест зелёный при сломанном фильтре. Первый запрос обязан упасть, потому что на успешном пути MDC.clear() вызывается даже при неправильном коде. И проверочный обработчик отдаёт текущее содержимое контекста — три строки в тестовой конфигурации, которые в продакшн не попадают.

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

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

MDC.put в сервисе или обработчике. Логику наполнения MDC нужно держать в фильтрах, где есть чёткий finally-блок. Если поставить MDC.put в сервисе, легко забыть вызвать MDC.remove — тогда ключ утечёт в следующие запросы на том же потоке.

Если всё же нужно добавить контекст на короткий промежуток, используйте MDCCloseable — он снимается автоматически по завершении блока:

try (var ignored = MDC.putCloseable("orderId", order.id().toString())) {
    processOrder(order);
}
// orderId автоматически убран из MDC

Идентификаторы трассировки вручную. Если подключён OpenTelemetry Logback appender, trace_id и span_id дописываются к каждой строке сами. Ручная запись создаст второе поле с другим написанием и перезапишет правильное значение.

@Async без TaskDecorator. Контекст не передаётся в новый поток, логи асинхронной операции не связаны с исходным запросом, трассировка разрывается.

Глубже: через брокер и в фоновые задачи: заголовки, потребитель, планировщик, outboxрасширенное

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

Через брокер. Сообщение в Kafka или RabbitMQ несёт заголовки, и в них едет тот же traceparent, что в HTTP. Spring Boot 3 с Micrometer Tracing пишет его при отправке и читает в слушателе, если включить наблюдение у шаблона и слушателя (spring.kafka.template.observation-enabled, spring.kafka.listener.observation-enabled, у RabbitMQ те же свойства с rabbitmq); спан потребителя становится продолжением трассы отправителя, а trace_id попадает в MDC слушателя автоматически. Свои поля MDC (requestId, userId) через брокер сами не едут: их кладут в заголовки при отправке и достают в слушателе, и это делает один перехватчик с обеих сторон, а не каждый обработчик. Обрыв трассы на очереди почти всегда означает, что наблюдение включено с одной стороны или сообщение отправлено сторонней библиотекой мимо шаблона.

Фоновые задачи без запроса. У @Scheduled нет входящего запроса, значит нет ни трассы, ни MDC, и записи прогона в журнале не связаны ничем. Прогон объявляют единицей работы сам: @Observed на методе задачи или Observation.createNotStarted("outbox-relay") вокруг тела создаёт новую трассу на каждый прогон, а в MDC кладут имя задачи и идентификатор прогона (MDC.putCloseable("jobRun", runId)). Тогда «что делал отправитель outbox в 03:14» это поиск по одному полю, а сбой внутри прогона несёт свою трассу.

Outbox и восстановление трассы. Событие записано в outbox в транзакции запроса, а отправлено отправителем через секунду в другом потоке и другой трассе. Чтобы потребитель события оказался в трассе исходного запроса, trace_id сохраняют в строке outbox вместе с событием и при отправке кладут в заголовок как родителя; спан отправителя при этом связывают с исходной трассой ссылкой, а не делают её продолжением, потому что отправитель обслуживает много запросов за один прогон. Так на одной трассе видно: запрос, запись события, его отправка через секунду и обработка потребителем через две.

Проверяют всё это одним тестом: запрос, событие через брокер, обработка, и в логах потребителя тот же trace_id, что в логах запроса. Без такого теста включённое наблюдение отключается при обновлении зависимости, и об этом узнают на инциденте.

Коротко

• MDC — потоко-локальное хранилище, которое Logback автоматически добавляет в каждый лог. Позволяет не передавать requestId/userId через параметры.
• MdcFilter с @Order(HIGHEST_PRECEDENCE) наполняет MDC в начале каждого запроса и очищает его в finally. userId добавляется отдельным фильтром после Spring Security, когда SecurityContextHolder уже заполнен.
• MDC.clear() обязательно в finally, а не в обычном потоке — иначе при исключении контекст утечёт в следующий запрос чужого пользователя.
• trace_id и span_id (именно так, через подчёркивание) дописываются автоматически через opentelemetry-logback-mdc-1.0 — вручную их не ставить, написание держать одно на все сервисы.
• Для @Async нужен TaskDecorator, который копирует MDC из исходного потока в поток-исполнитель.
• Через брокер контекст едет в заголовках: traceparent при включённом наблюдении шаблона и слушателя, свои поля MDC одним перехватчиком; @Scheduled заводит свою трассу и jobRun в MDC; outbox хранит trace_id события и передаёт его при отправке.
• Заголовок X-Request-Id от клиента проверяют белым списком символов и длиной, иначе перевод строки в значении подделывает записи журнала; на публичной границе его перезаписывают своим.
• Ручной декоратор переносит только MDC и теряет контекст трассировки и безопасности: штатный способ — снимок всех контекстов через micrometer-context-propagation.
• На виртуальных потоках утечка контекста в следующий запрос исчезает (поток умирает с запросом), но передача в другой поток по-прежнему требует снимка, а ScopedValue библиотеки журналов пока не читают.
• Утечку ловит тест из двух запросов на одном потоке, где первый падает: без него правильная передача контекста тихо отключается при обновлении зависимости.

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

• Логирование в Spring Boot — как MDC-поля попадают в структурированный JSON-лог.
• Трассировка и OpenTelemetry — как работает автоматический traceId/spanId в MDC.
• От алерта до строки лога: как по requestId и trace_id из тревоги дойти до конкретной записи в журнале.
• Профилирование и утечки памяти: забытый ключ в потоко-локальном хранилище это одна из самых частых утечек.