Мне нужно организовать пользовательскую трассировку и журналирование. Журналирование журнала (Slf4j).
У меня есть сервис, которому нужно читать поля из заголовка и добавлять их в корреляцию (перед переходом на Spring Boot 3 я использовал MDC для распределения данных). Плюс я также добавил в MDC настраиваемые поля для ведения журналов.
После перехода на Spring Boot 3 (с сыщика на микрометр) я не понимаю, как можно управлять данными в MDC.
Подскажите, как правильно добавить в корреляцию произвольные поля? Как заполнить МДК при использовании микрометра. Как перенести все из родительского потока в новый и очистить после завершения?
Вот мой пример:
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"
management:
tracing:
sampling:
probability: 1.0
baggage:
correlation:
fields: testRemoteBaggage, testLocalBaggage
remote-fields: testRemoteBaggage
local-fields: testLocalBaggage
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());
};
}
}
@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>]
ОБНОВЛЕНО
Проблема не была связана с виртуальными потоками.
@igor.zh Проверил приложение без виртуальных потоков, приложение тоже не работает так, как я ожидаю. Я создал пример на GitHub, чтобы наглядно это показать: Пример проекта
Итак, проблема не связана с VT; возможно, имеет смысл соответствующим образом обновить заголовок вопроса. Выложенный вами MRE — отличный ход! Я попробую посмотреть. А пока вы проверили эту ветку? Тестовый проект микрометра, который я создал вчера на основе вашего описания, устанавливает переменные testRemoteBaggage
и testRemoteBaggage
в контекст MDC, но, насколько я понимаю, вы ищете записи корреляции в журнале.
@igor.zh Спасибо за напоминание, я обновил заголовок вопроса и удалил тег. Что касается ветки example, то у меня проблема не только в том, что я не могу найти в логах TraceId и spanId. Журналы, не содержащие этих значений, генерируются асинхронным RestClient, который делает запрос к другому сервису в новом потоке. В результате корреляция не передается вызываемому сервису. Я пытаюсь найти способ распределить контекст MDC по сгенерированным потокам, чтобы при этом корреляция передавалась остальным вызовам.
Спасибо за редактирование! Позвольте мне уточнить, в чем ваша проблема: когда вы говорите «сгенерировано асинхронным RestClient», вы имеете в виду эту строку 32 клиента DummyJsonTracingService
: parallelStream
? Когда вы вызываете Сервер в строке 26, заголовок testRemoteBaggage
правильно передается на Сервер, верно? В настоящее время я вижу только одну проблему: когда Клиент параллельно вызывает Сервер, заголовок не передается последнему. Это ваша проблема или я что-то еще пропустил? Под «созданными темами» в вашем последнем комментарии вы имеете в виду темы, созданные parallelStream
?
В классе DummyJsonTracingService.java строки 24–27 выполняют остальной вызов из основного потока. Этот вызов выполняется путем передачи поля testRemoteBaggage в заголовок. Но в классе DummyJsonTracingService.java в строке 30 открыт параллельный поток. Этот параллельный поток в новых потоках выполняет остальные вызовы в строках 33-37. Эти вызовы производятся из потоков, в которых в MDC не заполнены следующие значения:traceId, spanId и testRemoteBaggage. Эти значения не попадают в журнал и также не передаются в заголовок rest-вызовов.
Хорошо, теперь я вижу проблему. Похоже, что механизм наблюдения, а не только MDC, хранит некоторые данные в ThreadLocal
, а потоки, порожденные parallelStream
/ForkJoinPool
, конечно, не имеют доступа к ThreadLocal
"основного" (рабочего Tomcat) потока. Просто дайте мне немного времени, надеюсь, перенести соответствующие значения из «основного» ThreadLocal
в первый поток FTJ не составит труда. Любопытно, однако, как это сработало со Сыщиком, с которым вы работали ранее, вы сказали...
Я думаю, у меня есть решение. Проблема, как мне кажется, в том, что ObservationRegistry
сохраняет текущий Observation.Scope
в своем ThreadLocal
, а с "неосновными", как вы сказали, потоками нам нужно установить текущую область видимости. В «основном»/рабочем потоке Tomcat эту работу выполняет ServerHttpObservationFilter
, настроенный Spring Boot; в «несетевом» режиме нам приходится делать это «вручную». Не хотели бы вы обновить свой вопрос, включив в него использование «параллельного потока», который, как мы договорились, был основным виновником? В противном случае я отвечу на один из ваших комментариев, а не на ваш вопрос.
Как следует из 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?
Похоже, я все же ответил не на тот вопрос, который ты задал, лол. На самом деле я передал заголовок testRemoteBaggage
с клиента на сервер, раньше это не работало. Но похоже, вы спросили что-то еще, извините за это. Я вставил распространение контекста MDC в FJP/"параллельные" потоки, как вы предложили, но позвольте мне посмотреть поближе, что происходит...
@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.
Я не вижу лога, подобного тому, который вы предоставили. Если у вас есть решение, как это получить, я был бы очень благодарен. Это расширит ответ на мой вопрос.
Предположим, вы применили к своему коду мои изменения, которые я сделал вчера в отношении контекста MDC. Странно... Давайте я выложу свою версию на github, чтобы вы сами увидели.
@Георги Уцевский. Пожалуйста, ознакомьтесь с моим PoC.
Работает ли это так, как вы ожидаете, если вы не используете виртуальные потоки:
spring.threads.virtua.enabled
естьfalse
, а Spring Async и обработчик протокола Tomcat не настроены на виртуальные потоки? Если да, не могли бы вы выложить лог?