Using micrometer-tracing-bridge-{} breaks OAuth2/JWT validation

[singhbaljit]

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.

[spalberg]

It's exactly the same for us. The error appeared after upgrading spring boot from 3.1.0 to 3.1.1.

[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.

[jzheaux]

This may be a duplicate of #13415

[spalberg]

Seems to work using https://github.com/spring-projects/spring-boot/releases/tag/v3.1.2

[singhbaljit]

Working again for me with v3.1.2 as well.