Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

slf4j integration: MDC is cleared when a Span is ended, and parent span info is not restored into the MDC #23

Closed
jkwatson opened this issue Feb 24, 2021 · 3 comments · Fixed by #24
Assignees
Labels
bug Something isn't working
Milestone

Comments

@jkwatson
Copy link
Contributor

jkwatson commented Feb 24, 2021

Describe the bug
Because the current slf4j integration is done via a SpanProcessor, which knows nothing about the OpenTelemetry Context, the logging MDC data is not being properly managed. When a span is started, it's traceid/spanid is put into the MDC, and the MDC is cleared of that data when the span is ended. However, this is not the proper lifecycle hooks for where data should be put into and removed from the MDC, since ending any span in a trace will completely clear out the MDC, which will not be restored.

Sample
To demonstrate this, you can do something like this:

    @NewSpan
    public void doServiceCall() {
        log.info("start of service call");
        innerCall();
        log.info("end of service call");
    }

    private void innerCall() {
        Span span = tracer.nextSpan().name("inner call");
        try (Tracer.SpanInScope scope = tracer.withSpan(span.start())) {
            log.info("inside inner call");
        } finally {
            span.end();
        }
    }

When the 2nd log statement happens in the doServiceCall() method, the MDC has been cleared by the child span being ended in the innerCall() method, and the logging output does not have the traceid/spanid of the current span any more.

I think the right way to fix this issue is to not use a SpanProcessor to manage the state of the MDC, but probably to interact with the Context Scope lifecycle, instead. This may require some additional extension points/hooks in the OTel Context implementation, but I'm not 100% sure of that yet.

Is there a way to hook into the sleuth context lifecycle to manage this state, rather than relying on the specific sleuth implementation to do this?

@jkwatson jkwatson changed the title Slf4j integration: MDC is cleared when a Span is ended, and parent span info is not restored into the MDC slf4j integration: MDC is cleared when a Span is ended, and parent span info is not restored into the MDC Feb 24, 2021
@jkwatson
Copy link
Contributor Author

Working on understanding what's going on here, and it does look like things are intended to be hooking into the sleuth context lifecycle already. I'm digging in to why it's not working as expected.

@monnetchr
Copy link

Looks like the cause for #22 where I provide a full sample https://github.com/monnetchr/otel-issue

@jkwatson
Copy link
Contributor Author

Please assign this to me. I'm getting close to a fix.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants