Reactive logging request/response having request/response logs with span and trace ids zeroes

[maxim-badarau-m10]

We are having reactive context, so followed lates PR ( opentelemetry-java-instrumentation) to accommodate the solution as we are still using spring-boot 3.0.6.
Implemented:

public class TelemetryFilterConfig implements WebFilter, Ordered {

    private final ServerWebExchangeAttributesGetter serverWebExchangeAttributesGetter;

    private final Instrumenter<ServerWebExchange, ServerWebExchange> instrumenter;

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        Context parentContext = Context.current();
        Mono<Void> source = chain.filter(exchange);
        return new TelemetryMonoWrapper(source, instrumenter, serverWebExchangeAttributesGetter, parentContext, exchange);
    }

    @Override
    public int getOrder() {
//        return Ordered.HIGHEST_PRECEDENCE + 1;
        return -1;
    }

}

also to mentioned that having Ordered.HIGHEST_PRECEDENCE + 1 will actually get blocked in: !instrumenter.shouldStart(parentContext, exchange)
After this filter, in the chain is decorator filter, having main purpose of logging request/response:

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        if (!passToLog(exchange)) {
            return chain.filter(exchange);
        }
        BodyCaptureExchange bodyCaptureExchange = new BodyCaptureExchange(exchange, obfuscateHeaders, UUID.randomUUID());
        return bodyCaptureExchange.getRequest().getFullBody()
                .doOnSuccess(requestBodyLog -> log.info("Request: {}", requestBodyLog))
                .flatMap(unused -> chain.filter(bodyCaptureExchange))
                .doOnSuccess(unused -> log.info("Response: {}", bodyCaptureExchange.getResponse().getFullBody()));
    }

    private boolean passToLog(ServerWebExchange exchange) {
        String path = Optional.ofNullable(exchange)
                .map(ServerWebExchange::getRequest)
                .map(ServerHttpRequest::getPath)
                .map(PathContainer::value)
                .orElse("");
        for (String value : exclude) {
            if (!path.isBlank() && path.startsWith(value)) {
                return false;
            }
        }
        return true;
    }

    @Override
    public int getOrder() {
        return 1;
    }

subscribe to new context:

    @Override
    public void subscribe(CoreSubscriber<? super Void> actual) {
        if (!instrumenter.shouldStart(parentContext, exchange)) {
            source.subscribe(actual);
            return;
        }
        Context currentContext = instrumenter.start(parentContext, exchange);
        try (Scope ignored = currentContext.makeCurrent()) {
            this.source.subscribe(
                    new TelemetryWrappedSubscriber(actual, currentContext, instrumenter, serverWebExchangeAttributesGetter, exchange));
        }
    }

After subscribe calling Context.current() directly after in the next in chain filter will return empty context, but nothing in the decorators request logs nothing, response logs, only
"traceId":"00000000000000000000000000000000","spanId":"0000000000000000"

Configuration looks like:

@Configuration
public class OpenTelemetryConfiguration {

    @Bean
    public Resource resource(@Value("${spring.application.name}") String applicationName) {
        return Resource.getDefault().toBuilder().put(ResourceAttributes.SERVICE_NAME, applicationName)
                .put(ResourceAttributes.SERVICE_VERSION, "1.0.0").build();
    }

    @Bean
    public SdkTracerProvider sdkTracerProvider(Resource resource) {
        return SdkTracerProvider.builder()
//                .addSpanProcessor(SimpleSpanProcessor.create(LoggingSpanExporter.create()))
                .setResource(resource)
                .build();
    }

    @Bean
    public SdkMeterProvider sdkMeterProvider(Resource resource) {
        return SdkMeterProvider.builder()
                .registerMetricReader(PeriodicMetricReader.builder(LoggingMetricExporter.create()).build())
                .setResource(resource)
                .build();
    }

    @Bean
    public SdkLoggerProvider sdkLoggerProvider(Resource resource) {
        return SdkLoggerProvider.builder()
                .addLogRecordProcessor(BatchLogRecordProcessor.builder(SystemOutLogRecordExporter.create()).build())
                .setResource(resource)
                .build();
    }

    @Bean
    public OpenTelemetry openTelemetry(SdkTracerProvider sdkTracerProvider,
                                       SdkMeterProvider sdkMeterProvider,
                                       SdkLoggerProvider sdkLoggerProvider) {
        return OpenTelemetrySdk.builder()
                .setTracerProvider(sdkTracerProvider)
                .setMeterProvider(sdkMeterProvider)
                .setLoggerProvider(sdkLoggerProvider)
                .setPropagators(ContextPropagators.create(TextMapPropagator.composite(W3CTraceContextPropagator.getInstance(),
                        W3CBaggagePropagator.getInstance())))
                .build();
    }

    @Bean
    public OtlpHttpSpanExporter otlpHttpSpanExporter(@Value("${tracing.url}") String url) {
        return OtlpHttpSpanExporter.builder().setEndpoint(url).build();
    }

    @Bean
    public SpanNameExtractor<ServerWebExchange> spanNameExtractor(ServerWebExchangeAttributesGetter serverWebExchangeAttributesGetter) {
        return HttpSpanNameExtractor.create(serverWebExchangeAttributesGetter);
    }

    @Bean
    public Instrumenter<ServerWebExchange, ServerWebExchange> instrumenter(OpenTelemetry openTelemetry,
                                                                           @Value("${spring.application.name}") String applicationName,
                                                                           SpanNameExtractor<ServerWebExchange> spanNameExtractor) {
        return Instrumenter.<ServerWebExchange, ServerWebExchange>builder(openTelemetry, applicationName, spanNameExtractor)
                .buildInstrumenter();
    }

Having request/response logged as:

{"@timestamp":"2023-09-25T20:43:55.008Z","@version":"1","message":"Request: {PATH=/auth/sign-up, HEADERS=[Host:\"feature-jaeger.develop.m10payments.com\", X-Request-ID:\"48a1c05bfe8c2179086b052e55f0d9b6\", X-Real-IP:\"18.193.206.75\", X-Forwarded-For:\"18.193.206.75\", X-Forwarded-Host:\"feature-jaeger.develop.m10payments.com\", X-Forwarded-Port:\"443\", X-Forwarded-Proto:\"https\", X-Forwarded-Scheme:\"https\", X-Scheme:\"https\", X-Forwarded-Prefix:\"/ingateway\", Content-Length:\"120\", User-Agent:\"M10\", Content-Type:\"application/json\", Accept:\"*/*\", Postman-Token:\"36a752a9-07c4-44f5-be76-e829d8f282f2\", Accept-Encoding:\"gzip, deflate, br\"], TIMESTAMP=2023-09-25 20:43:55.008, METHOD=POST, UUID=4489a496-7604-41a7-ad5b-21e9d03be5f5, URI=https://localhost:8080/test, BODY={\n    \"name\": \"test\"}, QUERY_PARAMS={}}","logger_name":"com.m10.ingateway.config.filter.logger.LoggingFilterConfig","thread_name":"reactor-http-epoll-3","level":"INFO","level_value":20000}
{"@timestamp":"2023-09-25T20:43:55.158Z","@version":"1","message":"Response: {HEADERS=[Vary:\"Origin\", \"Access-Control-Request-Method\", \"Access-Control-Request-Headers\", Content-Type:\"application/json\", Content-Length:\"50\", Cache-Control:\"no-cache, no-store, max-age=0, must-revalidate\", Pragma:\"no-cache\", Expires:\"0\", X-Content-Type-Options:\"nosniff\", Strict-Transport-Security:\"max-age=31536000 ; includeSubDomains\", X-Frame-Options:\"DENY\", X-XSS-Protection:\"0\", Referrer-Policy:\"no-referrer\"], TIMESTAMP=2023-09-25 20:43:55.157, STATUS_CODE=201 CREATED, UUID=4489a496-7604-41a7-ad5b-21e9d03be5f5, BODY={\"uuid\":\"f69710fd-f530-4272-8d47-34741c8a33b8\"}}","logger_name":"com.m10.ingateway.config.filter.logger.LoggingFilterConfig","thread_name":"reactor-http-epoll-3","level":"INFO","level_value":20000,"traceId":"00000000000000000000000000000000","spanId":"0000000000000000"}

Thanks for replies in advance.

[laurit]

Please provide a minimal sample application that reproduces the issue.

[maxim-badarau-m10]

Hello, @laurit Thanks for reply, give me couple of hours and I would be able to give minimal application setup. Thanks in advance.

[trask]

maybe related to #7739

[maxim-badarau-m10]

Sorry, no not the case. Tried it also.

[maxim-badarau-m10]

@trask Not sure if there is a correlation in between. @laurit Attaching the demo project describing the issue. Sorry for bad code, everything is within root package.
WeTransfer link: https://we.tl/t-RYIsIawdvC

[maxim-badarau-m10]

I guess you are right, will try first to update to 1.30, and indeed in the logback I was missing

    <appender name="OTEL" class="io.opentelemetry.instrumentation.logback.mdc.v1_0.OpenTelemetryAppender">
        <appender-ref ref="STDOUT"/>
    </appender>

btw I was nat 'hoping' that it will magically works, I guess I messed this logback file with tons of experiments and tries forgetting to check it.

[maxim-badarau-m10]

@laurit
Sorry last question, basically we are receiving request with gateway and by rabbit push them further (rpc call). As you can see there are 2 propagators:

    @Bean
    public OpenTelemetry openTelemetry(SdkTracerProvider sdkTracerProvider,
                                       SdkMeterProvider sdkMeterProvider,
                                       SdkLoggerProvider sdkLoggerProvider) {
        return OpenTelemetrySdk.builder()
                .setTracerProvider(sdkTracerProvider)
                .setMeterProvider(sdkMeterProvider)
                .setLoggerProvider(sdkLoggerProvider)
                .setPropagators(ContextPropagators.create(TextMapPropagator.composite(W3CTraceContextPropagator.getInstance(),
                        W3CBaggagePropagator.getInstance())))
                .build();
    }

but unfortunately consumer do not receive trace and span IDs, is there any additional propagator to be used or basically it's enough just adding context to the header in the producer.

[laurit]

For the propagation to happen instrumentation is needed. Firstly ensure that you have added and configured the manual instrumentation library for the framework for which you expect the propagation to happen. If manual instrumentation library is not available for the said framework then try with javaagent.

[maxim-badarau-m10]

@laurit Thanks for the help, it worked, but I guess there is an issue, first call through webflux filter works perfectly, all consecutive will have zeroes for the traceId and spanId

[laurit]

If you believe you have found a bug please raise an issue on github and provide a minimal application that reproduces the issue along with any instructions needed.