Affects: 6.0.8 (spring-webflux)
I have a simple filter that should just inject current trace ID to the response:
package some.controller;
import io.micrometer.tracing.Span;
import io.micrometer.tracing.Tracer;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.core.Ordered;
import org.springframework.http.HttpHeaders;
import org.springframework.stereotype.Component;
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebFilter;
import org.springframework.web.server.WebFilterChain;
import reactor.core.publisher.Mono;
import java.util.UUID;
@Slf4j
@Component
public class AddResponseHeaderWebFilter implements WebFilter, Ordered {
private final Tracer tracer;
public AddResponseHeaderWebFilter(
final Tracer tracer
) {
this.tracer = tracer;
}
@SuppressWarnings("NullableProblems")
@Override
public Mono<Void> filter(final ServerWebExchange exchange, final WebFilterChain chain) {
return chain.filter(withCallback(exchange));
}
private ServerWebExchange withCallback(final ServerWebExchange exchange) {
exchange
.getResponse()
.beforeCommit(() -> {
HttpHeaders httpHeaders = exchange.getResponse().getHeaders();
httpHeaders.add("trace-id", callId());
return Mono.empty();
});
return exchange;
}
private static String fallbackValue() {
String fallbackValue = UUID.randomUUID().toString();
log.warn("Could not use trace ID; generated dummy UUID for tracking purposes: {}", fallbackValue);
return fallbackValue;
}
private String callId() {
Span currentSpan = this.tracer.currentSpan();
return currentSpan == null
? fallbackValue()
: currentSpan.context().traceId();
}
@Override
public int getOrder() {
return Ordered.HIGHEST_PRECEDENCE;
}
}
it works well if my controller returns Mono> or Mono
I am not sure if it is a known limitation now, or some additional configuration / code change is needed on my end?
Comment From: quaff
Have you tried MDC.get("traceId")
?
Comment From: chechoochoo
@quaff my filter is based on webflux/reactive stack;
such call to MDC returns the "00000000000000000000000000000000" so the result of https://github.com/open-telemetry/opentelemetry-java/blob/47ee573f07c9025547d494608863d9314b29df4b/api/all/src/main/java/io/opentelemetry/api/trace/TraceId.java#L51
note: I updated issue summary with a note it is on reactive stack
Comment From: Storje
Same issue for me with Spring Boot 3 (it's ok with Spring Boot 2) Unable to have a traceId in a webFilter even in logs.
With this attached project , after lauching the test, we can see in the logs that traceId is available only in the REST Controller :
{"@timestamp":"2023-06-30T14:11:37.982Z","level":"INFO","message":"In filter with null","logger_name":"com.example.demo.TestFilter"}
{"@timestamp":"2023-06-30T14:11:38.003338Z","level":"INFO","message":"In ping","logger_name":"com.example.demo.DemoApplication","traceId":"649ee2995bae5e514c22a6bb1283fd1b","spanId":"4c22a6bb1283fd1b"}
{"@timestamp":"2023-06-30T14:11:38.033049Z","level":"INFO","message":"Success","logger_name":"com.example.demo.TestFilter"}
{"@timestamp":"2023-06-30T14:11:38.033174Z","level":"INFO","message":"OnEach","logger_name":"com.example.demo.TestFilter"}
traceId
is not available in logs from the following filter :
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
class TestFilter(private val tracer: Tracer): WebFilter {
private val logger: Logger = LoggerFactory.getLogger(TestFilter::class.java)
override fun filter(exchange: ServerWebExchange, chain: WebFilterChain): Mono<Void> {
val traceId = tracer.currentSpan()?.context()?.traceId()
logger.info("In filter with $traceId")
return chain.filter(exchange)
.doOnSuccess {
logger.info("Success")
}
.doOnEach {
val context = it.contextView
// Any way to get the traceId from this context ?
logger.info("OnEach")
}
}
}
As a workaround, is there a way to get the traceId from the reactor context in a filter ?
Comment From: bclozel
Running your sample app yields the following for me:
{"@timestamp":"2023-07-05T15:17:22.68438Z","level":"INFO","message":"In filter with null","logger_name":"com.example.demo.TestFilter"}
{"@timestamp":"2023-07-05T15:17:22.721378Z","level":"INFO","message":"In ping","logger_name":"com.example.demo.DemoApplication","traceId":"64a5898227ebba51c3b4e4e50052c59a","spanId":"c3b4e4e50052c59a"}
{"@timestamp":"2023-07-05T15:17:22.73997Z","level":"INFO","message":"Success","logger_name":"com.example.demo.TestFilter","traceId":"64a5898227ebba51c3b4e4e50052c59a","spanId":"c3b4e4e50052c59a"}
{"@timestamp":"2023-07-05T15:17:22.740158Z","level":"INFO","message":"OnEach","logger_name":"com.example.demo.TestFilter","traceId":"64a5898227ebba51c3b4e4e50052c59a","spanId":"c3b4e4e50052c59a"}
Doing the same when the filter is configured at @Order(Ordered.HIGHEST_PRECEDENCE + 2)
shows this:
{"@timestamp":"2023-07-05T15:18:18.406686Z","level":"INFO","message":"In filter with 64a589ba88545a7873690cb021cac9a8","logger_name":"com.example.demo.TestFilter","traceId":"64a589ba88545a7873690cb021cac9a8","spanId":"73690cb021cac9a8"}
{"@timestamp":"2023-07-05T15:18:18.423131Z","level":"INFO","message":"In ping","logger_name":"com.example.demo.DemoApplication","traceId":"64a589ba88545a7873690cb021cac9a8","spanId":"73690cb021cac9a8"}
{"@timestamp":"2023-07-05T15:18:18.441259Z","level":"INFO","message":"Success","logger_name":"com.example.demo.TestFilter","traceId":"64a589ba88545a7873690cb021cac9a8","spanId":"73690cb021cac9a8"}
{"@timestamp":"2023-07-05T15:18:18.441434Z","level":"INFO","message":"OnEach","logger_name":"com.example.demo.TestFilter","traceId":"64a589ba88545a7873690cb021cac9a8","spanId":"73690cb021cac9a8"}
This can be explained by the fact that the ServerHttpObservationFilter is ordered at Ordered.HIGHEST_PRECEDENCE + 1
. Because of this and other limitations, we've retired the WebFilter
in #30013 and there will be a follow up issue in Spring Boot for that.
I'm closing this issue as this was a problem with the ordering of the WebFilter
in the application.