open-telemetry / open-telemetry/opentelemetry-java

MDC Context lost its associated to individual thread

Open
#7,376 10 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Bug
Dominant language
Java
Stars
2.5k
Forks
1k
Avg merge
3d 17h
Merged PRs (30d)
58

Description

Describe the bug
We have a use case where we are setting the baggage in scope during the webfilter but in the flow the value being lost

Steps to reproduce
we have attached a poc, which contains 2 endpoint, you can just bootrun the application and hit the api localhost:8089/api/quizzes/5d20cccab90a07e7190b2b9f. when we hit the api we get the below in logs, If i explain well, we have created the baggage for username with value "sub" then later we override the value after calling the api with "sub-service1" and we expect the "sub-service1" to be available when we are throwing the IllegalArgumentException

025-05-28T09:53:33.335+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] s.w.r.r.m.a.RequestMappingHandlerMapping : [bc350e2f-1] Mapped to com.example.otel_tracing.resource.QuestionResource#findById(ObjectId)
2025-05-28T09:53:33.545+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] o.s.d.m.core.ReactiveMongoTemplate       : findOne using query: { "id" : { "$oid" : "5d20cccab90a07e7190b2b9f"}} fields: Document{{}} for class: class com.example.otel_tracing.model.entity.Question in collection: question
2025-05-28T09:53:33.581+05:30 " INFO[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] c.e.o.resource.QuestionResource          : Finding question
2025-05-28T09:53:33.587+05:30 " INFO[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] c.e.o.service.QuestionService            : finding question with id: 5d20cccab90a07e7190b2b9f
2025-05-28T09:53:33.703+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub-service1]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] org.mongodb.driver.cluster               : Server selection started for operation with ID 7. Selector: ReadPreferenceServerSelector{readPreference=primary}, topology description: {type=REPLICA_SET, servers=[{address=localhost:27017, type=REPLICA_SET_PRIMARY, roundTripTime=131.2 ms, state=CONNECTED}]
2025-05-28T09:53:33.719+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub-service1]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] org.mongodb.driver.cluster               : Server selection succeeded for operation with ID 7. Selected server: localhost:27017. Selector: ReadPreferenceServerSelector{readPreference=primary}, topology description: {type=REPLICA_SET, servers=[{address=localhost:27017, type=REPLICA_SET_PRIMARY, roundTripTime=131.2 ms, state=CONNECTED}]
2025-05-28T09:53:33.730+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub-service1]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] org.mongodb.driver.connection            : Checkout started for connection to localhost:27017
2025-05-28T09:53:33.742+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,sub-service1]" 10988 --- [otel-tracing] [ctor-http-nio-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] i.o.context.ThreadLocalContextStorage    :  Trying to close scope which does not represent current context. Ignoring the call.
2025-05-28T09:53:34.021+05:30 "DEBUG[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,]" 10988 --- [otel-tracing] [ntLoopGroup-3-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] a.w.r.e.AbstractErrorWebExceptionHandler : [bc350e2f-1] Resolved [IllegalArgumentException: Question with id 5d20cccab90a07e7190b2b9f not found] for HTTP GET /api/quizzes/5d20cccab90a07e7190b2b9f
2025-05-28T09:53:34.022+05:30 "ERROR[otel-tracing,7c400339c6954d64fa1da33cc40da8ec,6c5c7f76e35841ea,]" 10988 --- [otel-tracing] [ntLoopGroup-3-3] [7c400339c6954d64fa1da33cc40da8ec-6c5c7f76e35841ea] a.w.r.e.AbstractErrorWebExceptionHandler : [bc350e2f-1]  500 Server Error for HTTP GET "/api/quizzes/5d20cccab90a07e7190b2b9f"

What did you expect to see?
Previously we were using brave implementation just now we have migrated to otel implementation, with brave we have the following logs username value sub-service1 is not lost.

2025-05-28T09:44:07.924+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] s.w.r.r.m.a.RequestMappingHandlerMapping : [6973f811-1] Mapped to com.example.otel_tracing.resource.QuestionResource#findById(ObjectId)
2025-05-28T09:44:08.268+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] o.s.d.m.core.ReactiveMongoTemplate       : findOne using query: { "id" : { "$oid" : "5d20cccab90a07e7190b2b9f"}} fields: Document{{}} for class: class com.example.otel_tracing.model.entity.Question in collection: question
2025-05-28T09:44:08.341+05:30 " INFO[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] c.e.o.resource.QuestionResource          : Finding question
2025-05-28T09:44:08.349+05:30 " INFO[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] c.e.o.service.QuestionService            : finding question with id: 5d20cccab90a07e7190b2b9f
2025-05-28T09:44:08.511+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub-service1]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] org.mongodb.driver.cluster               : Server selection started for operation with ID 5. Selector: ReadPreferenceServerSelector{readPreference=primary}, topology description: {type=REPLICA_SET, servers=[{address=localhost:27017, type=REPLICA_SET_PRIMARY, roundTripTime=155.1 ms, state=CONNECTED}]
2025-05-28T09:44:08.533+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub-service1]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] org.mongodb.driver.cluster               : Server selection succeeded for operation with ID 5. Selected server: localhost:27017. Selector: ReadPreferenceServerSelector{readPreference=primary}, topology description: {type=REPLICA_SET, servers=[{address=localhost:27017, type=REPLICA_SET_PRIMARY, roundTripTime=155.1 ms, state=CONNECTED}]
2025-05-28T09:44:08.550+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub-service1]" 16920 --- [otel-tracing] [ctor-http-nio-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] org.mongodb.driver.connection            : Checkout started for connection to localhost:27017
2025-05-28T09:44:08.884+05:30 "DEBUG[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub-service1]" 16920 --- [otel-tracing] [ntLoopGroup-3-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] a.w.r.e.AbstractErrorWebExceptionHandler : [6973f811-1] Resolved [IllegalArgumentException: Question with id 5d20cccab90a07e7190b2b9f not found] for HTTP GET /api/quizzes/5d20cccab90a07e7190b2b9f
2025-05-28T09:44:08.887+05:30 "ERROR[otel-tracing,68368d8fc5f4102aed3a583a71288585,ed3a583a71288585,sub-service1]" 16920 --- [otel-tracing] [ntLoopGroup-3-3] [68368d8fc5f4102aed3a583a71288585-ed3a583a71288585] a.w.r.e.AbstractErrorWebExceptionHandler : [6973f811-1]  500 Server Error for HTTP GET "/api/quizzes/5d20cccab90a07e7190b2b9f"

What did you see instead?
A clear and concise description of what you saw instead.

What version and what artifacts are you using?
Artifacts:

Image

Version: (e.g., v0.4.0, 1eb551b, etc)
How did you reference these artifacts? (excerpt from your build.gradle, pom.xml, etc)

Environment
Compiler: oracle openjdk 17.0.12"
OS: Windows 11
Runtime (if different from JDK above): (e.g., "Oracle JRE 8u251")
OS (if different from OS compiled on): (e.g., "Windows Server 2019")

Additional context
In the logs we often see Trying to close scope which does not represent current context. Ignoring the call. Some modification done in the past to close the scope https://github.com/open-telemetry/opentelemetry-java/issues/5055

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the linked POC, boot the application, and call the documented quiz endpoint to reproduce the missing baggage value. Read the logs around the reactive WebFilter, MongoDB operation, and error handler, then review the related issue 5055. Done means the updated baggage value remains in the exception and error logs without the scope-closing warning.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, mongodb, spring
Domain
backend, observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.