Springboot3 — Debugging and Tracing requests using Micrometer in Webflux

In this article, I will tell my story of what I had to do to identify, debug and trace individual API requests in my app logs while using Spring Webflux and Micrometer.

When I started with Springboot3 Webflux and Micrometer, the first problem I faced was that the trace_Id and span_Id were not getting printed in logs by just mentioning the Micrometer dependency. This was very unlike Springboot2 where getting these values was comparatively easy and straightforward. I started my research and found that some extra effort will be required in Springboot3 Webflux to achieve what I wanted to be printed in logs.

To begin with I added the actuator and micrometer tracer bridge dependency which are required to set up instrumentation and tracer context.

<!--Required for Tracer instrumentation-->
  <dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-actuator</artifactId>
  </dependency>
  <dependency>
   <groupId>io.micrometer</groupId>
   <artifactId>micrometer-tracing-bridge-brave</artifactId>
  </dependency>

In addition to mentioning dependencies, I also add the below properties for logging.

spring.application.name=webflux-log-tracing
logging.pattern.level=%5p [${spring.application.name:},%X{traceId:-},%X{spanId:-}]

Furthermore, I created a WebFilter to set the request context which will be used by the tracing bridge. This is required to get the log prefix which is logged by Webflux. Since many threads can process 1 request in reactive Spring, this log prefix comes in handy to identify request-specific logs.

@Slf4j
@Component
public class RequestMonitorWebFilter implements WebFilter {
    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        long startTime = System.currentTimeMillis();
        return chain.filter(exchange)
                /** !! IMPORTANT STEP !!
                 * Preparing context for the Tracer Span used in TracerConfiguration
                 */
                .contextWrite(context -> {
                    ContextSnapshot.setThreadLocalsFrom(context, ObservationThreadLocalAccessor.KEY);
                    return context;
                })
                    /**
                     * Logging the metrics for the API call, not really required to have this section for tracing setup
                     */
                .doFinally(signalType -> {
                    long endTime = System.currentTimeMillis();
                    long executionTime = endTime - startTime;
                    /**
                     * Extracting traceId added in TracerConfiguration Webfilter bean
                     */
                    List<String> traceIds = ofNullable(exchange.getResponse().getHeaders().get("traceId")).orElse(List.of());
                    MetricsLogTemplate metricsLogTemplate = new MetricsLogTemplate(
                            String.join(",", traceIds),
                            exchange.getLogPrefix().trim(),
                            executionTime
                    );
                    try {
                        log.info(new ObjectMapper().writeValueAsString(metricsLogTemplate));
                    } catch (JsonProcessingException e) {
                        throw new RuntimeException(e);
                    }
                });
    }

    record MetricsLogTemplate(String traceId, String logPrefix, long executionTime){}
}

Moving on, I wanted to provide the traceId as a header parameter in the API response so that in case of an incorrect response, I can use it to find the logs for the request and debug the issue. So, I add this WebFilter just to add traceId in response headers.

@Configuration(proxyBeanMethods = false)
public class TracerConfiguration {
    @Bean
    WebFilter traceIdInResponseFilter(Tracer tracer) {
        return (exchange, chain) -> {
            Span currentSpan = tracer.currentSpan();
            if (currentSpan != null) {
                // putting trace id value in [traceId] response header
                exchange.getResponse().getHeaders().add("traceId", currentSpan.context().traceId());
            }
            return chain.filter(exchange);
        };
    }
}

Finally, when I run the app on the server, I see the traceId, SpanId and log prefix getting printed in logs.

Postman console log for the API request

Logs generated at the server

TL;DR

GitHub - javed0863/webflux-log-tracing: Log tracing in Springboot 3 and Java17 using micromiter and…

Addressing Memory Issues in RequestMonitorWebFilter Class Using Hooks for Efficient Context Propagation

While the current implementation of the RequestMonitorWebFilter class functions as expected, it introduces a hidden memory issue. The class propagates the context, but not in an optimal manner, leading to increased memory usage that does not decrease over time. This can cause the application container to crash once all available memory is exhausted.

To resolve this memory issue, the framework provides a feature called Hooks. Implementing Hooks allows for more efficient context propagation, minimizing memory usage.

To enable automatic context propagation and address the memory issue, you should configure this at the application startup. This can be done in the PostConstruct method of the application's startup class.

@PostConstruct
public void loadCategoryMappingList() {
    Hooks.enableAutomaticContextPropagation();
}

Remove all the context propagation logic from RequestMonitorWebFilter

@Slf4j
@Component
public class RequestMonitorWebFilter implements WebFilter {
    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        long startTime = System.currentTimeMillis();
        return chain.filter(exchange)
                .doFinally(signalType -> {
                    // You know what to do here :)
                });
    }

    record MetricsLogTemplate(String traceId, String logPrefix, long executionTime){}
}

Thats it, now we can sit back, relax and enjoy our ☕️