Describe the bug
I'm using Spring Security (reactive, v6.1.1). Adding the micrometer-tracing-bridge-otel or micrometer-tracing-bridge-brave dependency breaks the OAuth2 resource server. I also have the Hooks.enableAutomaticContextPropagation() per this guide.
2023-06-26T22:59:19.199-04:00 ERROR 96867 --- [ctor-http-nio-3] reactor.core.publisher.Operators : Operator called default onErrorDropped
java.lang.AssertionError: Observation <{name=spring.security.filterchains(security filterchain before), error=org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: , context=name='spring.security.filterchains', contextualName='security filterchain before', error='org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: ', lowCardinalityKeyValues=[spring.security.filterchain.position='4', spring.security.filterchain.size='9', spring.security.reached.filter.name='AuthenticationWebFilter', spring.security.reached.filter.section='before'], highCardinalityKeyValues=[], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=-1.0E-9, duration(nanos)=-1.0, startTimeNanos=60545232013441}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@6af5a3e3'], parentObservation={name=http.server.requests(http delete), error=org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: , context=name='http.server.requests', contextualName='http delete', error='org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: ', lowCardinalityKeyValues=[exception='AuthenticationServiceException', method='DELETE', outcome='SERVER_ERROR', status='500', uri='UNKNOWN'], highCardinalityKeyValues=[http.url='/api/bad-request'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=-1.0E-9, duration(nanos)=-1.0, startTimeNanos=60545219139591}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@6f51d0ed'], parentObservation=null}}> to which we're restoring is not the same as the one set as this scope's parent observation <{name=http.server.requests(http delete), error=org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: , context=name='http.server.requests', contextualName='http delete', error='org.springframework.security.authentication.AuthenticationServiceException: An error occurred while attempting to decode the Jwt: ', lowCardinalityKeyValues=[exception='AuthenticationServiceException', method='DELETE', outcome='SERVER_ERROR', status='500', uri='UNKNOWN'], highCardinalityKeyValues=[http.url='/api/bad-request'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=-1.0E-9, duration(nanos)=-1.0, startTimeNanos=60545219139591}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@6f51d0ed'], parentObservation=null}> . Most likely a manually created Observation has a scope opened that was never closed. This may lead to thread polluting and memory leaks
at io.micrometer.observation.contextpropagation.ObservationThreadLocalAccessor.restore(ObservationThreadLocalAccessor.java:148)
at io.micrometer.observation.contextpropagation.ObservationThreadLocalAccessor.restore(ObservationThreadLocalAccessor.java:32)
at io.micrometer.context.DefaultContextSnapshot$DefaultScope.resetThreadLocalValue(DefaultContextSnapshot.java:144)
To Reproduce
My security configuration:
@EnableWebFluxSecurity
@EnableReactiveMethodSecurity
class AuthConfig {
@Bean
JwtIssuerReactiveAuthenticationManagerResolver authenticationManagerResolver(
@Value("${auth.issuerUrl}") final String authIssuerUrl) {
return new JwtIssuerReactiveAuthenticationManagerResolver(authIssuerUrl);
}
@Bean
SecurityWebFilterChain securityWebFilterChain(
final ServerHttpSecurity httpSecurity,
final JwtIssuerReactiveAuthenticationManagerResolver authenticationManagerResolver) {
httpSecurity.authorizeExchange(exchange -> exchange
.anyExchange().authenticated());
httpSecurity.oauth2ResourceServer(resourceServer -> resourceServer
.authenticationManagerResolver(authenticationManagerResolver));
return httpSecurity.build();
}
}
Expected behavior
Using the tracing library should not break Spring Security.
Comment From: spalberg
It's exactly the same for us. The error appeared after upgrading spring boot from 3.1.0 to 3.1.1.
Comment From: wallind
MOST IMPORTANTLY; I can corroborate that reverting from 3.1.1 back to 3.1.0 (as described by @spalberg here) did resolve the issue for me. So if you came here just looking for a fix, that's your fix.
I suspect I'm hitting this same issue. It presents itself a bit different and it's in our test suite, but it looks to be very similar (also downgrading made it go away):
2023-06-28T18:13:32.336-04:00 WARN [trace=none,span=none,user=none] 22596 --- [ @coroutine#257] i.m.o.c.ObservationThreadLocalAccessor : Observation <{name=command _REDACTED_(null), error=null, context=name='command _REDACTED_', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[command='_REDACTED_'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=-1.0E-9, duration(nanos)=-1.0, startTimeNanos=1156463022593600}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@5530539e'], parentObservation={name=command _REDACTED_(null), error=null, context=name='command _REDACTED_', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[command='_REDACTED_'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=0.023789, duration(nanos)=2.3789E7, startTimeNanos=1156463016970500}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@78e1a5ac'], parentObservation={name=command _REDACTED_(null), error=null, context=name='command _REDACTED_', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[command='_REDACTED_'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=0.0756402, duration(nanos)=7.56402E7, startTimeNanos=1156462965132400}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@268d56ef'], parentObservation=null}}}> to which we're restoring is not the same as the one set as this scope's parent observation <{name=command _REDACTED_(null), error=null, context=name='command _REDACTED_', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[command='_REDACTED_'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=0.0238147, duration(nanos)=2.38147E7, startTimeNanos=1156463016970500}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@78e1a5ac'], parentObservation={name=command _REDACTED_(null), error=null, context=name='command _REDACTED_', contextualName='null', error='null', lowCardinalityKeyValues=[], highCardinalityKeyValues=[command='_REDACTED_'], map=[class io.micrometer.core.instrument.LongTaskTimer$Sample='SampleImpl{duration(seconds)=0.0756629, duration(nanos)=7.56629E7, startTimeNanos=1156462965132400}', class io.micrometer.core.instrument.Timer$Sample='io.micrometer.core.instrument.Timer$Sample@268d56ef'], parentObservation=null}}> . Most likely a manually created Observation has a scope opened that was never closed. This may lead to thread polluting and memory leaks
Exception in thread "reactor-tcp-nio-2 @coroutine#257" kotlinx.coroutines.CoroutinesInternalError: Fatal exception in coroutines machinery for CancellableContinuation(DispatchedContinuation[Dispatchers.Unconfined, Continuation at com._REDACTED_._REDACTED_.common.pipeline.SuspendablePipelinr$suspendableSend$handleCommand$1.invokeSuspend(SuspendablePipelinr.kt:61)@5250735b]){Completed}@59ee7d7a. Please read KDoc to 'handleFatalException' method and report this incident to maintainers
at kotlinx.coroutines.DispatchedTask.handleFatalException(DispatchedTask.kt:144)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:115)
at kotlinx.coroutines.EventLoop.processUnconfinedEvent(EventLoop.common.kt:69)
at kotlinx.coroutines.DispatchedTaskKt.resumeUnconfined(DispatchedTask.kt:245)
at kotlinx.coroutines.DispatchedTaskKt.dispatch(DispatchedTask.kt:161)
at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:397)
at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl(CancellableContinuationImpl.kt:431)
at kotlinx.coroutines.CancellableContinuationImpl.resumeImpl$default(CancellableContinuationImpl.kt:420)
at kotlinx.coroutines.CancellableContinuationImpl.resumeWith(CancellableContinuationImpl.kt:328)
at kotlinx.coroutines.reactive.AwaitKt$awaitOne$2$1.onComplete(Await.kt:278)
at reactor.core.publisher.StrictSubscriber.onComplete(StrictSubscriber.java:123)
at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
NOTE I've subbed in _REDACTED_ to avoid leaking private domain implementation details, but by and large this is the strack trace...and it does bottom out at a Spring Security related org.springframework.security.test.context.support.ReactorContextTestExecutionListener which makes me think it's either related to or the same thing as the OP.
Comment From: jzheaux
This may be a duplicate of #13415
Comment From: spalberg
Seems to work using https://github.com/spring-projects/spring-boot/releases/tag/v3.1.2
Comment From: singhbaljit
Working again for me with v3.1.2 as well.