Custom attributes in MDC are getting lost

[narenderbisht]

boot.zip
Hi
i am facing an issue where in custom attributes in MDC are getting lost when using config spring.sleuth.sampler.probability=1.0
Application log:-

2019-02-25 22:33:46.360  INFO [boot-1,aa5519088fb5bc53,aa5519088fb5bc53,true,10.20.30.40] 22508 --- [nio-2040-exec-1] c.s.study.controller.SampleControllerA   : SampleControllerA hello starts
2019-02-25 22:33:46.393  INFO [boot-1,aa5519088fb5bc53,bf4da017c8a86e69,true,10.20.30.40] 22508 --- [nio-2040-exec-2] c.s.study.controller.SampleControllerB   : SampleControllerB hi starts and ends
2019-02-25 22:33:46.422  INFO [boot-1,aa5519088fb5bc53,aa5519088fb5bc53,true,] 22508 --- [nio-2040-exec-1] c.s.study.controller.SampleControllerA   : SampleControllerA hello ends

After making a rest call trueclientip attribute in MDC is getting lost

Sample application code is attached

[davidmelia]

Hi, just to confirm I get exactly the same issue but in WebFlux

[mpkorstanje]

Can confirm that for any spring.sleuth.sampler.probability>0.0 custom MDC attributes are lost when the sampler selects a trace for sampling.

It would appear that Braves HttpHandler.handleFinish always calls finishInNullScope which causes Slf4jScopeDecorator.decorateScope to incorrectly construct the previous MDC .

final List<AbstractMap.SimpleEntry<String, String>> previousMdc = Stream
     .concat(whitelistedBaggageKeysWithValue(currentSpan),
           whitelistedPropagationKeysWithValue(currentSpan))
     .map((s) -> new AbstractMap.SimpleEntry<>(s, MDC.get(s)))
     .collect(Collectors.toList());

When called with currentSpan == null then whitelistedBaggageKeysWithValue/whitelistedPropagationKeysWithValue will return empty streams as there is no span to check what the extra baggage is.

I don't know if this is a problem in Sleuths implementation of CurrentTraceContext.ScopeDecorator or Braves implementation of HttpHandler.

[mpkorstanje]

I've created a more minimal reproducer here:

https://github.com/mpkorstanje/sleuth-custom-mdc-attributes-removed

[mpkorstanje]

Definitely looks like a problem in Slf4jScopeDecorator. To simplify the explanation I've removed some of the redundant code:

final List<AbstractMap.SimpleEntry<String, String>> previousMdc = Stream
        .concat(whitelistedBaggageKeysWithValue(currentSpan),
                whitelistedPropagationKeysWithValue(currentSpan))
        .map((s) -> new AbstractMap.SimpleEntry<>(s, MDC.get(s)))
        .collect(Collectors.toList());


if (currentSpan != null) {
    whitelistedBaggageKeysWithValue(currentSpan).forEach(
            (s) -> MDC.put(s, ExtraFieldPropagation.get(currentSpan, s)));
    whitelistedPropagationKeysWithValue(currentSpan).forEach(
            (s) -> MDC.put(s, ExtraFieldPropagation.get(currentSpan, s)));
} else {
    whitelistedBaggageKeys().forEach(MDC::remove);
    whitelistedPropagationKeys().forEach(MDC::remove);
}

class ThreadContextCurrentTraceContextScope implements CurrentTraceContext.Scope {

    @Override
    public void close() {
        previousMdc.forEach((e) -> replace(e.getKey(), e.getValue()));
    }

}

When currentSpan == null the keys that are preserved and the keys that are removed are different. So when called with currentSpan == null then whitelistedBaggageKeysWithValue(currentSpan) should return the same as whitelistedBaggageKeys()..

[marcingrzejszczak]

Can you create a test that fails with the current impl?

[mpkorstanje]

Do you mean a unit test or a reproducer? And with the latest master or latest release?

[marcingrzejszczak]

Yeah a reproducer is a good idea. First please check if the problem is still there with the latest hoxton snapshots. Then ping us back. A reproducer would be handy for the 2.1.x branch.

[mpkorstanje]

The problem is reproducible in Hoxton.BUILD-SNAPSHOT:

https://github.com/mpkorstanje/sleuth-custom-mdc-attributes-removed

[mpkorstanje]

I was planning on a PR. Didn't get around to it yet. I'm currently using as a work around that puts the baggage and propagation keys back onto the MDC whenever rest template is used:

import lombok.RequiredArgsConstructor;
import org.slf4j.MDC;
import org.springframework.boot.autoconfigure.AutoConfigureAfter;
import org.springframework.boot.web.client.RestTemplateCustomizer;
import org.springframework.cloud.sleuth.autoconfig.SleuthProperties;
import org.springframework.cloud.sleuth.instrument.web.client.TraceWebClientAutoConfiguration;
import org.springframework.cloud.sleuth.log.SleuthSlf4jProperties;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.core.annotation.Order;
import org.springframework.http.HttpRequest;
import org.springframework.http.client.ClientHttpRequestExecution;
import org.springframework.http.client.ClientHttpRequestInterceptor;
import org.springframework.http.client.ClientHttpResponse;

import java.io.IOException;
import java.util.HashMap;
import java.util.Map;
import java.util.stream.Stream;

import static java.util.stream.Stream.concat;

/**
 * Work around for https://github.com/spring-cloud/spring-cloud-sleuth/issues/1220
 * <p>
 * Restores the custom baggage and whitelisted propagation keys after they're
 * removed by the Slf4jScopeDecorator.
 */
@RequiredArgsConstructor
@Configuration
@AutoConfigureAfter(TraceWebClientAutoConfiguration.class)
public class Sleuth1220WorkAround {

    private final SleuthProperties sleuthProperties;
    private final SleuthSlf4jProperties sleuthSlf4jProperties;

    @Bean
    @Order
    public RestTemplateCustomizer sleuth1220WorkAround() {
        // Add first so RestoreBaggedAndPropagation is invoked around
        // TracingClientHttpRequestInterceptor.
        return restTemplate -> restTemplate.getInterceptors()
                .add(0, new RestoreBaggedAndPropagation());
    }


    private final class RestoreBaggedAndPropagation implements ClientHttpRequestInterceptor {

        @Override
        public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException {
            // Duplicates possible
            Map<String, String> previousMdc = new HashMap<>();
            concat(whitelistedBaggageKeys(), whitelistedPropagationKeys())
                    .forEach(s -> previousMdc.put(s, MDC.get(s)));
            try {
                return execution.execute(request, body);
            } finally {
                previousMdc.forEach(MDC::put);
            }
        }

        private Stream<String> whitelistedBaggageKeys() {
            return Sleuth1220WorkAround.this.sleuthProperties.getBaggageKeys().stream().filter(
                    key -> Sleuth1220WorkAround.this.sleuthSlf4jProperties.getWhitelistedMdcKeys().contains(key));
        }

        private Stream<String> whitelistedPropagationKeys() {
            return Sleuth1220WorkAround.this.sleuthProperties.getPropagationKeys().stream().filter(
                    key -> Sleuth1220WorkAround.this.sleuthSlf4jProperties.getWhitelistedMdcKeys().contains(key));
        }
    }
}

[alecl]

Running into this as well. Will this be addressed in the recent 3.0?

Also, @mpkorstanje, thank you for your efforts on this. I'm having trouble running your workaround though. I get a runtime exception on startup.

I'm running Greenwich.RELEASE / Spring Boot 2.1.9.RELEASE if that matters.

java.lang.IllegalStateException: Error processing condition on org.springframework.boot.autoconfigure.context.MessageSourceAutoConfiguration
at org.springframework.boot.autoconfigure.condition.SpringBootCondition.matches(SpringBootCondition.java:60)
at org.springframework.context.annotation.ConditionEvaluator.shouldSkip(ConditionEvaluator.java:108)
at org.springframework.context.annotation.ConfigurationClassBeanDefinitionReader$TrackedConditionEvaluator.shouldSkip(ConfigurationClassBeanDefinitionReader.java:447)
at org.springframework.context.annotation.ConfigurationClassBeanDefinitionReader.loadBeanDefinitionsForConfigurationClass(ConfigurationClassBeanDefinitionReader.java:128)
at org.springframework.context.annotation.ConfigurationClassBeanDefinitionReader.loadBeanDefinitions(ConfigurationClassBeanDefinitionReader.java:117)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.processConfigBeanDefinitions(ConfigurationClassPostProcessor.java:327)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.postProcessBeanDefinitionRegistry(ConfigurationClassPostProcessor.java:232)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanDefinitionRegistryPostProcessors(PostProcessorRegistrationDelegate.java:275)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:95)
at org.springframework.context.support.AbstractApplicationContext.invokeBeanFactoryPostProcessors(AbstractApplicationContext.java:705)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:531)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:141)
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:744)
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:391)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:312)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1215)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1204)
at com.synchronoss.mmp.observability_poc.Application.main(Application.java:28)
Caused by: org.springframework.beans.factory.BeanDefinitionStoreException: Invalid bean definition with name 'sleuth1220WorkAround' defined in class path resource [com/.../Sleuth1220WorkAround.class]: factory-bean reference points back to the same bean definition
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.getTypeForFactoryMethod(AbstractAutowireCapableBeanFactory.java:715)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.determineTargetType(AbstractAutowireCapableBeanFactory.java:679)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.predictBeanType(AbstractAutowireCapableBeanFactory.java:647)
at org.springframework.beans.factory.support.AbstractBeanFactory.isFactoryBean(AbstractBeanFactory.java:1518)
at org.springframework.beans.factory.support.AbstractBeanFactory.isFactoryBean(AbstractBeanFactory.java:1023)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.requiresEagerInit(BeanTypeRegistry.java:208)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.addBeanTypeForNonAliasDefinition(BeanTypeRegistry.java:186)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.addBeanTypeForNonAliasDefinition(BeanTypeRegistry.java:156)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.addBeanType(BeanTypeRegistry.java:149)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.updateTypesIfNecessary(BeanTypeRegistry.java:137)
at java.util.Iterator.forEachRemaining(Iterator.java:116)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.updateTypesIfNecessary(BeanTypeRegistry.java:132)
at org.springframework.boot.autoconfigure.condition.BeanTypeRegistry.getNamesForType(BeanTypeRegistry.java:96)
at org.springframework.boot.autoconfigure.condition.OnBeanCondition.collectBeanNamesForType(OnBeanCondition.java:269)
at org.springframework.boot.autoconfigure.condition.OnBeanCondition.getBeanNamesForType(OnBeanCondition.java:262)
at org.springframework.boot.autoconfigure.condition.OnBeanCondition.getBeanNamesForType(OnBeanCondition.java:251)
at org.springframework.boot.autoconfigure.condition.OnBeanCondition.getMatchingBeans(OnBeanCondition.java:171)
at org.springframework.boot.autoconfigure.condition.OnBeanCondition.getMatchOutcome(OnBeanCondition.java:145)
at org.springframework.boot.autoconfigure.condition.SpringBootCondition.matches(SpringBootCondition.java:47)
... 17 common frames omitted

[mpkorstanje]

I'm having trouble running your workaround though. I get a runtime exception on startup.
I'm running Greenwich.RELEASE / Spring Boot 2.1.9.RELEASE if that matters.

Not a clue sorry.

[mpkorstanje]

@marcingrzejszczak this no longer reproduceable with spring-cloud-sleuth:3.0.1. Feel free to close.

https://github.com/mpkorstanje/sleuth-custom-mdc-attributes-removed