Hello,
The error occurs using Spring Boot 3.0.2. The error can be reproduced using https://github.com/ruben-garciapariente/error-tracing-with-brave-baggage/blob/main/src/main/java/com/example/bravetracing/BraveTracingApplication.java
We have used micrometer-tracing-bridge-brave for tracing
<dependency>
<groupId>io.micrometer</groupId>
<artifactId>micrometer-tracing-bridge-brave</artifactId>
</dependency>
Configured to instrument async observability as indicated at https://github.com/micrometer-metrics/tracing/wiki/Spring-Cloud-Sleuth-3.1-Migration-Guide#async-instrumentation.
// Example of Async Servlets setup
@Configuration(proxyBeanMethods = false)
static class AsyncConfig implements WebMvcConfigurer {
@Override
public void configureAsyncSupport(AsyncSupportConfigurer configurer) {
configurer.setTaskExecutor(new SimpleAsyncTaskExecutor(r -> new Thread(ContextSnapshot.captureAll().wrap(r))));
}
}
And we have a controller with asynchronous methods
@RequestMapping(path = "/callable", produces = "text/html")
Callable<ResponseEntity<String>> callable() {
logger.info(String.format("1 - Thread %s - Span %s",Thread.currentThread().getName(), tracer.currentSpan().context().toString()));
return () -> {
logger.info(String.format("2 - Thread %s - Span %s",Thread.currentThread().getName(), tracer.currentSpan().context().toString()));
return ResponseEntity.status(HttpStatus.OK).body("OK");
};
}
And we configure the baggage fields
management:
tracing:
baggage:
remote-fields:
- TEST1
correlation:
fields:
- TEST1
When running the BraveTracingApplicationTests#testCallable test the following error is returned
2023-02-06T13:13:34.900+01:00 INFO [63e0eeee37d15812d3f53ac42c7c8307,d3f53ac42c7c8307,test1] 25824 --- [ Thread-2] c.example.bravetracing.TestController : 2 - Thread Thread-2 - Span 63e0eeee37d15812d3f53ac42c7c8307/d3f53ac42c7c8307
2023-02-06T13:13:34.923+01:00 INFO [63e0eeee37d15812d3f53ac42c7c8307,a2a553d4c5737736,test1] 25824 --- [ main] c.example.bravetracing.TestController : Thread main - Span 63e0eeee37d15812d3f53ac42c7c8307/a2a553d4c5737736
[ERROR] Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 6.458 s <<< FAILURE! - in com.example.bravetracing.BraveTracingApplicationTests
[ERROR] testCallable Time elapsed: 0.814 s <<< FAILURE!
java.lang.AssertionError: Misalignment: popped updateScope false != expected false
at com.example.bravetracing.BraveTracingApplicationTests.testCallable(BraveTracingApplicationTests.java:31)
[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR] BraveTracingApplicationTests.testCallable:31 Misalignment: popped updateScope false != expected false
Many thanks
Comment From: wilkinsona
Thanks for the sample, @ruben-garciapariente. I have reproduced the problem when running BraveTracingApplicationTests#testCallable. The problem does not occur when running the application's main method and making a request to http://localhost:8080/callable. Can you confirm that's the behavior that you also see?
Comment From: wilkinsona
It looks to me like there's a race condition. CorrelationUpdateScope is an AtomicBoolean sub-class and there's an equality check performed against the popped scope and the expected scope. The AssertionError is being thrown because the two scopes don't have the same value:
static void popCurrentUpdateScope(CorrelationUpdateScope expected) {
Object popped = updateScopeStack().pop();
assert equal(popped, expected) :
"Misalignment: popped updateScope " + popped + " != expected " + expected;
}
By the time the error message is produced, both scopes have the same false value:
Misalignment: popped updateScope false != expected false
Comment From: wilkinsona
My analysis above is incorrect. CorrelationUpdateScope does not override equals so the equality check is asserting that expected and popped are the same (==) object.
Comment From: wilkinsona
This looks like a Micrometer bug to me. With the custom thread factory and some extra output hacked into CorrelationFlushScope and CorrelationUpdateScope, we end up with the following output:
Thread[main,5,main] created 1311562833
Thread[main,5,main] pushed 1311562833
2023-02-07T14:43:59.392Z INFO [63e263af84059dc2a56019d467f5da25,a56019d467f5da25,test1] 20549 --- [ main] c.example.bravetracing.TestController : 1 - Thread main - Span 63e263af84059dc2a56019d467f5da25/a56019d467f5da25
Thread[Thread-2,5,main] created 361238228
Thread[Thread-2,5,main] pushed 361238228
2023-02-07T14:43:59.398Z INFO [63e263af84059dc2a56019d467f5da25,a56019d467f5da25,test1] 20549 --- [ Thread-2] c.example.bravetracing.TestController : 2 - Thread Thread-2 - Span 63e263af84059dc2a56019d467f5da25/a56019d467f5da25
Thread[main,5,main] popped 1311562833
java.lang.AssertionError: Misalignment: popped updateScope 1311562833 != expected 361238228
at brave.baggage.CorrelationFlushScope.popCurrentUpdateScope(CorrelationFlushScope.java:89)
at brave.baggage.CorrelationFlushScope.close(CorrelationFlushScope.java:37)
at io.micrometer.tracing.brave.bridge.BraveScope.close(BraveCurrentTraceContext.java:114)
at io.micrometer.tracing.handler.TracingObservationHandler.onScopeClosed(TracingObservationHandler.java:102)
at io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.lambda$onScopeClosed$5(ObservationHandler.java:154)
at java.base/java.util.Optional.ifPresent(Optional.java:178)
at io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onScopeClosed(ObservationHandler.java:154)
at io.micrometer.observation.SimpleObservation.lambda$notifyOnScopeClosed$6(SimpleObservation.java:210)
at java.base/java.util.ArrayDeque$DescendingIterator.forEachRemaining(ArrayDeque.java:772)
at io.micrometer.observation.SimpleObservation.notifyOnScopeClosed(SimpleObservation.java:210)
at io.micrometer.observation.SimpleObservation.access$100(SimpleObservation.java:35)
at io.micrometer.observation.SimpleObservation$SimpleScope.close(SimpleObservation.java:251)
at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:110)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:132)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.mock.web.MockFilterChain.doFilter(MockFilterChain.java:132)
at org.springframework.test.web.servlet.MockMvc.perform(MockMvc.java:201)
at com.example.bravetracing.BraveTracingApplicationTests.testCallable(BraveTracingApplicationTests.java:31)
This failure occurs on the main thread. When closing a scope, it popped update scope 1311562833 which was pushed by the main thread but it expected to find update scope 361238228 that was pushed by Thread-2. It looks like the CorrelationFlushScope that is being closed "belongs" to Thread-2 but it being closed on main.
@ruben-garciapariente Can you please open a Micrometer tracing issue for this? If you comment here with a link to it, we can subscribe and provide any input that's needed from the Spring Boot side of things.