Трассировка Spring Boot 3 микрометра в MDC

Мне нужно организовать пользовательскую трассировку и журналирование. Журналирование журнала (Slf4j).

У меня есть сервис, которому нужно читать поля из заголовка и добавлять их в корреляцию (перед переходом на Spring Boot 3 я использовал MDC для распределения данных). Плюс я также добавил в MDC настраиваемые поля для ведения журналов.

После перехода на Spring Boot 3 (с сыщика на микрометр) я не понимаю, как можно управлять данными в MDC.

Подскажите, как правильно добавить в корреляцию произвольные поля? Как заполнить МДК при использовании микрометра. Как перенести все из родительского потока в новый и очистить после завершения?

Вот мой пример:

  1. Настройте шаблон ведения журнала:
logging:
  pattern:
    console: "%clr(%d){faint} %clr(%5p) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%X{testRemoteBaggage}-%X{testLocalBaggage}]){magenta} %clr([%40.40t]){faint} %clr(${LOG_CORRELATION_PATTERN:-}){faint}%clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n%wEx"
  1. Настроил добавление в корреляцию произвольных полей (первое поле должно отправляться с запросами, второе - нет):
management:
  tracing:
    sampling:
      probability: 1.0
    baggage:
      correlation:
        fields: testRemoteBaggage, testLocalBaggage
      remote-fields: testRemoteBaggage
      local-fields: testLocalBaggage
  1. Настроил исполнитель задач на асинхронную работу с виртуальными потоками:
spring:
  threads:
    virtual:
      enabled: true
@EnableAsync
@Configuration(proxyBeanMethods = false)
public class DummyJsonTracingConfiguration {

    @Bean
    public AsyncTaskExecutor applicationTaskExecutor() {
        return new TaskExecutorAdapter(Executors.newVirtualThreadPerTaskExecutor());
    }

    @Bean
    public TomcatProtocolHandlerCustomizer<?> protocolHandlerVirtualThreadExecutorCustomizer() {
        return protocolHandler -> {
            protocolHandler.setExecutor(Executors.newVirtualThreadPerTaskExecutor());
        };
    }
}
  1. Добавлен фильтр, который добавляет в корреляцию пользовательские поля:
@Component
@Slf4j
@RequiredArgsConstructor
public class AddBaggageFilter extends OncePerRequestFilter implements OrderedFilter {
    private static final String fieldRemote = "testRemoteBaggage";
    private static final String fieldLocal = "testLocalBaggage";

    private final Tracer tracer;

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {

        String baggagefieldRemote = request.getHeader(fieldRemote);
        if (StringUtils.isEmpty(baggagefieldRemote)) {
            baggagefieldRemote = "autoValue"+fieldRemote;
        }
        String baggagefieldLocal = request.getHeader(fieldLocal);
        if (StringUtils.isEmpty(baggagefieldLocal)) {
            baggagefieldLocal = "autoValue"+fieldLocal;
        }
        log.warn("baggagefieldRemote value : [{}]", baggagefieldRemote);
        log.warn("baggagefieldLocal value : [{}]", baggagefieldLocal);

        try (BaggageInScope baggageRemote = tracer.createBaggageInScope(fieldRemote, baggagefieldRemote);
             BaggageInScope baggageLocal = tracer.createBaggageInScope(fieldLocal, baggagefieldLocal)) {
            log.warn("baggagefieldRemote was created!");
            filterChain.doFilter(request, response);
        }
    }

    @Override
    public int getOrder() {
        return Ordered.HIGHEST_PRECEDENCE + 2;
    }
}

Но в логах вижу, что корреляция отображается только для основного потока.

2024-07-14 14:05:28,274  WARN 23716 --- [test1-] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] b.g.t.rest.AddBaggageFilter              : baggagefieldRemote value : [test1]
2024-07-14 14:05:28,275  WARN 23716 --- [test1-] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] b.g.t.rest.AddBaggageFilter              : baggagefieldLocal value : [autoValuetestLocalBaggage]
2024-07-14 14:05:28,276  WARN 23716 --- [test1-autoValuetestLocalBaggage] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] b.g.t.rest.AddBaggageFilter              : baggagefieldRemote was created!
2024-07-14 14:05:28,279 DEBUG 23716 --- [test1-autoValuetestLocalBaggage] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] o.s.web.servlet.DispatcherServlet        : POST "/categoryInfo", parameters = {}
2024-07-14 14:05:28,285 DEBUG 23716 --- [test1-autoValuetestLocalBaggage] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to by.gvu.testtracingrestclient.controller.SimpleController#getListProducts()
2024-07-14 14:05:29,128 DEBUG 23716 --- [test1-autoValuetestLocalBaggage] [                        tomcat-handler-1] [6693bf08c4ecb0e29507c9dbc43570fe-9507c9dbc43570fe] o.s.web.client.DefaultRestClient         : Reading to [java.util.List<java.lang.String>]
2024-07-14 14:05:29,377 DEBUG 23716 --- [-] [        ForkJoinPool.commonPool-worker-9] [                                                 ] o.s.web.client.DefaultRestClient         : Reading to [java.util.List<by.gvu.testtracingrestclient.model.Product>]
2024-07-14 14:05:29,689 DEBUG 23716 --- [-] [       ForkJoinPool.commonPool-worker-10] [                                                 ] o.s.web.client.DefaultRestClient         : Reading to [java.util.List<by.gvu.testtracingrestclient.model.Product>]
2024-07-14 14:05:29,734 DEBUG 23716 --- [-] [        ForkJoinPool.commonPool-worker-4] [                                                 ] o.s.web.client.DefaultRestClient         : Reading to [java.util.List<by.gvu.testtracingrestclient.model.Product>]
2024-07-14 14:05:29,734 DEBUG 23716 --- [-] [       ForkJoinPool.commonPool-worker-12] [                                                 ] o.s.web.client.DefaultRestClient         : Reading to [java.util.List<by.gvu.testtracingrestclient.model.Product>]

ОБНОВЛЕНО

Проблема не была связана с виртуальными потоками.

Работает ли это так, как вы ожидаете, если вы не используете виртуальные потоки: spring.threads.virtua.enabled есть false, а Spring Async и обработчик протокола Tomcat не настроены на виртуальные потоки? Если да, не могли бы вы выложить лог?

igor.zh 15.07.2024 00:13

@igor.zh Проверил приложение без виртуальных потоков, приложение тоже не работает так, как я ожидаю. Я создал пример на GitHub, чтобы наглядно это показать: Пример проекта

Heorhi Utseuski 15.07.2024 10:09

Итак, проблема не связана с VT; возможно, имеет смысл соответствующим образом обновить заголовок вопроса. Выложенный вами MRE — отличный ход! Я попробую посмотреть. А пока вы проверили эту ветку? Тестовый проект микрометра, который я создал вчера на основе вашего описания, устанавливает переменные testRemoteBaggage и testRemoteBaggage в контекст MDC, но, насколько я понимаю, вы ищете записи корреляции в журнале.

igor.zh 15.07.2024 16:02

@igor.zh Спасибо за напоминание, я обновил заголовок вопроса и удалил тег. Что касается ветки example, то у меня проблема не только в том, что я не могу найти в логах TraceId и spanId. Журналы, не содержащие этих значений, генерируются асинхронным RestClient, который делает запрос к другому сервису в новом потоке. В результате корреляция не передается вызываемому сервису. Я пытаюсь найти способ распределить контекст MDC по сгенерированным потокам, чтобы при этом корреляция передавалась остальным вызовам.

Heorhi Utseuski 15.07.2024 21:58

Спасибо за редактирование! Позвольте мне уточнить, в чем ваша проблема: когда вы говорите «сгенерировано асинхронным RestClient», вы имеете в виду эту строку 32 клиента DummyJsonTracingService : parallelStream? Когда вы вызываете Сервер в строке 26, заголовок testRemoteBaggage правильно передается на Сервер, верно? В настоящее время я вижу только одну проблему: когда Клиент параллельно вызывает Сервер, заголовок не передается последнему. Это ваша проблема или я что-то еще пропустил? Под «созданными темами» в вашем последнем комментарии вы имеете в виду темы, созданные parallelStream?

igor.zh 16.07.2024 05:13

В классе DummyJsonTracingService.java строки 24–27 выполняют остальной вызов из основного потока. Этот вызов выполняется путем передачи поля testRemoteBaggage в заголовок. Но в классе DummyJsonTracingService.java в строке 30 открыт параллельный поток. Этот параллельный поток в новых потоках выполняет остальные вызовы в строках 33-37. Эти вызовы производятся из потоков, в которых в MDC не заполнены следующие значения:traceId, spanId и testRemoteBaggage. Эти значения не попадают в журнал и также не передаются в заголовок rest-вызовов.

Heorhi Utseuski 16.07.2024 09:01

Хорошо, теперь я вижу проблему. Похоже, что механизм наблюдения, а не только MDC, хранит некоторые данные в ThreadLocal, а потоки, порожденные parallelStream/ForkJoinPool, конечно, не имеют доступа к ThreadLocal "основного" (рабочего Tomcat) потока. Просто дайте мне немного времени, надеюсь, перенести соответствующие значения из «основного» ThreadLocal в первый поток FTJ не составит труда. Любопытно, однако, как это сработало со Сыщиком, с которым вы работали ранее, вы сказали...

igor.zh 17.07.2024 02:12

Я думаю, у меня есть решение. Проблема, как мне кажется, в том, что ObservationRegistry сохраняет текущий Observation.Scope в своем ThreadLocal, а с "неосновными", как вы сказали, потоками нам нужно установить текущую область видимости. В «основном»/рабочем потоке Tomcat эту работу выполняет ServerHttpObservationFilter , настроенный Spring Boot; в «несетевом» режиме нам приходится делать это «вручную». Не хотели бы вы обновить свой вопрос, включив в него использование «параллельного потока», который, как мы договорились, был основным виновником? В противном случае я отвечу на один из ваших комментариев, а не на ваш вопрос.

igor.zh 17.07.2024 18:58
Пользовательский скаляр GraphQL
Пользовательский скаляр GraphQL
Листовые узлы системы типов GraphQL называются скалярами. Достигнув скалярного типа, невозможно спуститься дальше по иерархии типов. Скалярный тип...
Как вычислять биты и понимать побитовые операторы в Java - объяснение с примерами
Как вычислять биты и понимать побитовые операторы в Java - объяснение с примерами
В компьютерном программировании биты играют важнейшую роль в представлении и манипулировании данными на двоичном уровне. Побитовые операции...
Поднятие тревоги для долго выполняющихся методов в Spring Boot
Поднятие тревоги для долго выполняющихся методов в Spring Boot
Приходилось ли вам сталкиваться с требованиями, в которых вас могли попросить поднять тревогу или выдать ошибку, когда метод Java занимает больше...
Полный курс Java для разработчиков веб-сайтов и приложений
Полный курс Java для разработчиков веб-сайтов и приложений
Получите сертификат Java Web и Application Developer, используя наш курс.
1
8
204
1
Перейти к ответу Данный вопрос помечен как решенный

Ответы 1

Ответ принят как подходящий

Как следует из MRE, ОП опубликовал, проблема заключается в выполнении запросов с поддержкой RestClient в отдельных потоках, в случае ОП средствами parallelStream.

List<String> categories = ...

categories.parallelStream().map(category -> {
    List<Product> productList = restClient.post()
                        .uri(uriBuilder -> uriBuilder.path("...").build(category))
                        .retrieve()
...

RestClient интегрируется с Micrometer Observation: при выполнении запроса он запускает Observation и тот извлекает родительскую Observation форму ObservationRegistry. ObservationRegistry, в свою очередь, сохраняет текущий Observation (Observation.Scope) в своем ThreadLocal. Когда RestClient выполняется в потоке контейнера (Tomcat), ServerHttpObservationFilter , настроенный Spring Boot, заботится о установке текущего Observation в реестр, но когда поток, управляемый ForkJoinPool, собирается выполнить RestClient, этот поток не имеет доступ к ThreadLocal потока Tomcat и, следовательно, к начальному (родительскому) Observation.

Одним из очевидных решений для случая parallelStream является сохранение текущего наблюдения в потоке «Tomcat» и восстановление его в потоке «ForkJoinPool».

@Autowired
private ObservationRegistry registry;

... 

final Scope currentScope = registry.getCurrentObservationScope();
final Map<String, String> mdcContext = MDC.getCopyOfContextMap();   
categories.parallelStream().map(category -> {
    final Scope oldScope = observationRegistry.getCurrentObservationScope();
    try {
        MDC.setContextMap(mdcContext);            
        registry.setCurrentObservationScope(currentScope);
        restClient.post().uri(uriBuilder -> uriBuilder.path("...")
        .build(category))
        .retrieve()
        ...         
    } finally {
        MDC.clear();
        registry.setCurrentObservationScope(oldScope);
    }
}
    

Большое спасибо. Оно работает. Но только с отправкой запросов. Журналы по-прежнему не показывают никаких значений. Но я так понимаю, это связано с тем, что для потоков Tomcat тоже нужно заполнять контекст MDC?

Heorhi Utseuski 20.07.2024 21:20

Похоже, я все же ответил не на тот вопрос, который ты задал, лол. На самом деле я передал заголовок testRemoteBaggage с клиента на сервер, раньше это не работало. Но похоже, вы спросили что-то еще, извините за это. Я вставил распространение контекста MDC в FJP/"параллельные" потоки, как вы предложили, но позвольте мне посмотреть поближе, что происходит...

igor.zh 21.07.2024 05:21

@HeorhiUtseuski, да, поскольку контекст MDC распространяется на потоки FJP, я вижу эту запись --- [autoValuetestRemoteBaggage-] [ ForkJoinPool.commonPool-worker-1] [669d34ba6322dd9bc5bc1200fd70c256-c5bc1200fd70c256] o.s.web.client.DefaultRestClient : Reading to [java.util.List<by.gvu.testtracingrestclient.model.Product>] в журнале. Если это то, что вы ищете, я дополню свой ответ несколькими комментариями о MDC.

igor.zh 21.07.2024 18:28

Я не вижу лога, подобного тому, который вы предоставили. Если у вас есть решение, как это получить, я был бы очень благодарен. Это расширит ответ на мой вопрос.

Heorhi Utseuski 22.07.2024 11:12

Предположим, вы применили к своему коду мои изменения, которые я сделал вчера в отношении контекста MDC. Странно... Давайте я выложу свою версию на github, чтобы вы сами увидели.

igor.zh 23.07.2024 04:02

@Георги Уцевский. Пожалуйста, ознакомьтесь с моим PoC.

igor.zh 24.07.2024 00:22

Другие вопросы по теме