I need to organize custom tracing and logging.
Logging logback (Slf4j).
I have a service that needs to read fields from the header and add them to the correlation (before switching to spring boot 3, I used MDC to distribute data). Plus I also added custom fields to MDC for logging.
After switching to spring boot 3 (from sleuth to micrometer), I don’t understand how I can manage data in MDC.
Can you tell me how to correctly add custom fields to the correlation?
How to fill out Mdc when using a micrometer.
How to transfer everything from the parent thread to a new one, and clean it up after completion?
Here’s my example:
- Set up a logging pattern:
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"
- Configured adding custom fields to the correlation (the first field should be sent with requests, the second should not):
management:
tracing:
sampling:
probability: 1.0
baggage:
correlation:
fields: testRemoteBaggage, testLocalBaggage
remote-fields: testRemoteBaggage
local-fields: testLocalBaggage
- Configured a task executor to work asynchronously with virtual threads:
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());
};
}
}
- Added a filter that adds custom fields to the correlation:
@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;
}
}
But in the logs I see that the correlation is displayed only for the main thread.
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>]
UPDATED
The problem was not related to virtual threads.
Heorhi Utseuski is a new contributor to this site. Take care in asking for clarification, commenting, and answering.
Check out our Code of Conduct.
8
As it follows from the MRE the OP posted the problem is with execution of RestClient
-powered requests on separate threads, in OP case by the means of parallelStream
.
List<String> categories = ...
categories.parallelStream().map(category -> {
List<Product> productList = restClient.post()
.uri(uriBuilder -> uriBuilder.path("...").build(category))
.retrieve()
...
RestClient
does integrate with Micrometer Observation: upon execution of a request it starts an Observation
and that one retrieves parent Observation
form ObservationRegistry
. ObservationRegistry
, in turn, stores current Observation
(Observation.Scope
) in its ThreadLocal
. When RestClient
is executed on a container (Tomcat) thread, ServerHttpObservationFilter
, configured by Spring Boot, takes care of setting current Observation
to the registry, but when a thread, managed by ForkJoinPool
, is about to execute RestClient
, this thread does not have an access to ThreadLocal
of Tomcat thread, and therefore, to initial (parent) Observation
.
One obvious solution for the case of parallelStream
, is to save current observation while in “Tomcat” thread and restore it in “ForkJoinPool” thread.
@Autowired
private ObservationRegistry registry;
...
final Scope currentScope = registry.getCurrentObservationScope();
categories.parallelStream().map(category -> {
final Scope oldScope = observationRegistry.getCurrentObservationScope();
try {
registry.setCurrentObservationScope(currentScope);
restClient.post().uri(uriBuilder -> uriBuilder.path("...")
.build(category))
.retrieve()
...
} finally {
registry.setCurrentObservationScope(oldScope);
}
}