Spring-cloud-sleuth: Manually set baggage is not automatically cleaned up from MDC

[aasaru]

I have configured:

spring.sleuth:
  propagation-keys:
    - x-session-id
  log:
    slf4j:
      whitelisted-mdc-keys: x-session-id 

If I pass this propagation key with a value to my app as HTTP header then after the request is completed it is automatically removed from MDC by Slf4jScopeDecorator.

But if I don't pass it as header but manually set the value somewhere during processing of the request then I have to manually set it to two places:

ExtraFieldPropagation.set(continuedSpan.context(), "x-session-id", "mySession123");
MDC.put("x-session-id", "mySession123");

and I also have to create an Interceptor and manually wipe it from MDC after the request processing has completed by calling:
MDC.remove("my-key")

This is because Slf4jScopeDecorator only wipes any baggage that arrived with the request.

I propose to create a mechanism to register the value with single call (so it gets set in both to ExtraFieldPropagation and to MDC) and also after a value has been registered it would be automatically wiped from MDC after the request has completed.

Related StackOverflow post.

[dlsrb6342]

I got same issue. I solved this by giving more higher order to my ExtraFieldPropagationFilter than TraceWebFilter. If you are using MVC, give more higher order than TracingFilter. Or you can change order by spring.sleuth.web.filter-order property.
With this solution, Slf4jScopeDecorator can get proper previousMdc value.
Above solution doesn't work. sorry.

But above is just workaround. If changing Slf4jScopeDecorator like below, can make a problem?

// current
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());

// to be
final List<AbstractMap.SimpleEntry<String, String>> previousMdc = Stream
        .concat(whitelistedBaggageKeys(), whitelistedPropagationKeys())
        .map((s) -> new AbstractMap.SimpleEntry<>(s, MDC.get(s)))
        .collect(Collectors.toList());

Even though, SimpleEntry's values can be null, Slf4jScopeDecorator.replace() can handle it. Baggaged keys will be cleaned up automatically.

[marcingrzejszczak]

Is there a chance for someone to prepare a test that breaks with the current implementation?

[dlsrb6342]

The solution I commented above doesn't work. sorry.. That solution can set and remove MDC automatically, but cannot set ExtraFieldPropagation value because there is no TraceContext yet.

[marcingrzejszczak]

Can you check the pr I've created that should solve the problem?

[dlsrb6342]

@marcingrzejszczak I checked your PR. It solved this issue well.

[aasaru]

Now that cleaning up is solved by PR I have one question remaining - is there any plan to provide a (convenience) method to set baggage and/or propagation keys?

[marcingrzejszczak]

I don't understand. You can use the ExtraPropagation API.

[aasaru]

Can I call ExtraPropagation API in a way that the value also gets added to MDC by the same call? Or should I call MDC separately?

My idea was that if I should make two API calls (one to ExtraPropagation API and one to MDC) maybe there could be a (convenience) method in Sleuth, so I would call this method and it would make both calls. Something like:

public void addBaggage(String key, String value) {
 ExtraFieldPropagation.set(continuedSpan.context(), key, value);
 MDC.put(key, value);
}

But if it doesn't make sense to add this method then it is also fine.

[dlsrb6342]

In my case, just ExtraFieldPropagation.set() call make MDC too. I don't need to call MDC.put(). Could you test with below properties?

# application.yml
spring.sleuth:
  log.slf4j.whitelisted-mdc-keys: [foo, bar]
  propagation-keys: [foo, bar]

[marcingrzejszczak]

When you set ExtraFieldPropagation.set(continuedSpan.context(), key, value); and the key is whitelisted as @dlsrb6342 mentioned, then the Slf4jScopeDecorator will store put all the non empty values in MDC.

[marcingrzejszczak]

BTW are we actually trying to solve a wrong usage example? Why not just use ExtraFieldPropagation.set(key, value); ? That way Sleuth will already take care of clearing the MDC context?

[dlsrb6342]

No. sleuth cannot clear MDC.
In current implementation, previousMdc's key set is consist of whited list keys that have non-null value.
But, if you call ExtraFieldPropagation.set(key, value) after TraceWebFilter.filter(), there is no value in ExtraFieldPropagation when Slf4jScopeDecorator decorate current span.

[marcingrzejszczak]

But, if you call ExtraFieldPropagation.set(key, value) after TraceWebFilter.filter(), there is no value in ExtraFieldPropagation when Slf4jScopeDecorator decorate current span.

so in your next filter, do you create a scope manually? Can you share a small example of how you work with this atm?

[dlsrb6342]

Actually, I cannot fix it. I just clear MDC manually. If you want not working example, I can share it.

[marcingrzejszczak]

Please do!

[dlsrb6342]

@marcingrzejszczak Sorry for late response.
I made with webflux based on sleuth-webmvc-example
Please check https://github.com/dlsrb6342/sleuth-webmvc-example/tree/mdc-issue.

If you send first request, ExtraFieldPropagation is not set when TraceWebFilter logic is being applied. This is because addFieldFilter is applied after TraceWebFilter. So there is no requestId in MDC.

But If you send next request, there is requestId in MDC. ExtraFieldPropagation was set In first request. So Slf4jScopeDecorator put requestId into MDC.

To confirm you that MDC is not cleared, if requestId is in MDC, I use requestId again.
In thrid request, you can see requestId is same as second request. That means requestId is not cleared.

[marcingrzejszczak]

Hi, thanks! However whenever I send the GET @ :8081 I don't see any repeated request Id in MDC.

[dlsrb6342]

I updated example just to log requestId not full MDC.

First Request

2019-08-07 10:17:48.856 [5d4a26bc5998d3758321f19230154bbd/8321f19230154bbd] INFO  [reactor-http-nio-3] s.w.Frontend - In Filter.PRE RequestId : null
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Filter.PRE RequestId : null
2019-08-07 10:17:48.893 [5d4a26bc5998d3758321f19230154bbd/8321f19230154bbd] DEBUG [reactor-http-nio-3] o.s.w.r.h.AbstractHandlerMapping - [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
 59151 --- [ctor-http-nio-3] o.s.w.r.f.s.s.RouterFunctionMapping      : [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
2019-08-07 10:17:48.895 [5d4a26bc5998d3758321f19230154bbd/8321f19230154bbd] INFO  [reactor-http-nio-3] s.w.Frontend - In Handler MDC : null
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Handler MDC : null

Second Request

2019-08-07 10:18:38.278 [5d4a26ee296eb1b7b9320f93ee01b203/b9320f93ee01b203] INFO  [reactor-http-nio-3] s.w.Frontend - In Filter.PRE RequestId : 67d842c6-887a-4570-ada9-d4d461a3544d
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Filter.PRE RequestId : 67d842c6-887a-4570-ada9-d4d461a3544d
2019-08-07 10:18:38.281 [5d4a26ee296eb1b7b9320f93ee01b203/b9320f93ee01b203] DEBUG [reactor-http-nio-3] o.s.w.r.h.AbstractHandlerMapping - [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
 59151 --- [ctor-http-nio-3] o.s.w.r.f.s.s.RouterFunctionMapping      : [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
2019-08-07 10:18:38.282 [5d4a26ee296eb1b7b9320f93ee01b203/b9320f93ee01b203] INFO  [reactor-http-nio-3] s.w.Frontend - In Handler MDC : 67d842c6-887a-4570-ada9-d4d461a3544d
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Handler MDC : 67d842c6-887a-4570-ada9-d4d461a3544d

Third Request

2019-08-07 10:19:18.202 [5d4a271644361731ab47b404a65f213b/ab47b404a65f213b] INFO  [reactor-http-nio-3] s.w.Frontend - In Filter.PRE RequestId : 67d842c6-887a-4570-ada9-d4d461a3544d
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Filter.PRE RequestId : 67d842c6-887a-4570-ada9-d4d461a3544d
2019-08-07 10:19:18.205 [5d4a271644361731ab47b404a65f213b/ab47b404a65f213b] DEBUG [reactor-http-nio-3] o.s.w.r.h.AbstractHandlerMapping - [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
 59151 --- [ctor-http-nio-3] o.s.w.r.f.s.s.RouterFunctionMapping      : [d3386756] Mapped to sleuth.webmvc.Frontend$$Lambda$427/0x00000008014c5440@38c827a3
2019-08-07 10:19:18.206 [5d4a271644361731ab47b404a65f213b/ab47b404a65f213b] INFO  [reactor-http-nio-3] s.w.Frontend - In Handler MDC : 67d842c6-887a-4570-ada9-d4d461a3544d
 59151 --- [ctor-http-nio-3] sleuth.webmvc.Frontend                   : In Handler MDC : 67d842c6-887a-4570-ada9-d4d461a3544d

Above is my log. requestId is same in second and third, "67d842c6-887a-4570-ada9-d4d461a3544d"

Could you show me your log?

[ajishashah]

I did set yml like
spring.sleuth:
log.slf4j.whitelisted-mdc-keys: [test, name]
propagation-keys: [test, name]

In controller i have :
ExtraFieldPropagation.set(tracer.currentSpan().context(), "test", "nothing");

in logback i have %X{test} in pattern

But it is not showing in my log. What am i missing. Using spring boot 2.1.8 and greenwhich sr3

[dlsrb6342]

This feature is not released yet I think.

[ajishashah]

Ok what about propagating fields to downstream ? How do I get value for the key in downstream after upstream has set it with above code? I can manually set Mdc as a workaround for log.

[ajishashah]

Can some one help me with this? I see anything in header is going downstream but what about something being set in application?

[dlsrb6342]

spring:
  sleuth:
    log.slf4j.whitelisted-mdc-keys: [test, id]
    propagation-keys: [test, id]

I'm using like this. and Downstream can find test and id from RequestHeader.
And please create new issue. this issue is already closed.