Accessing trace ID within reactive WebFilter

[chechoochoo]

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<List> or Mono but always falls into "fallback" when controller returns Flux;

I am not sure if it is a known limitation now, or some additional configuration / code change is needed on my end?

[quaff]

Have you tried MDC.get("traceId") ?

[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

[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"}

traceIdis 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 ?

[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.