Describe the bug The ObservationWebFilterChainDecorator should not call start in an onCancel trigger when wrapping a WebFilterChain, see here: https://github.com/spring-projects/spring-security/blob/f91a51bab70d3f2105ab814576e22cf7a8c421e2/web/src/main/java/org/springframework/security/web/server/ObservationWebFilterChainDecorator.java#L343C11-L343C11

This issue was also discussed here: https://github.com/micrometer-metrics/tracing/issues/357

Comment From: Hiosdra

Hi, any progress with this? 🥹

Comment From: jzheaux

Thanks, @Hiosdra, for reporting this issue. It should be resolved in #14031.

Comment From: janekbettinger

Hi @jzheaux , is it on purpose that SimpleAroundWebFilterObservation#wrap(WebFilterChain) has swapped semantics compared to the corresponding method SimpleWebFilterObservation#wrap(WebFilterChain)? The first method triggers a start of the "after observation" even if a cancel or error signal is received. This might be intended, however, I'm currently investigating an issue where replacing start() with close() seems to help.

The behavior we sporadically observe looks quite similar to https://github.com/micrometer-metrics/tracing/issues/357 with Spring Boot 3.2.1 (spring-security-web:6.2.1, micrometer-observation:1.12.1) and WebFlux (reactor-core:3.6.1):

java.lang.IllegalStateException: Span wasn't started - an observation must be started (not only created)
    at io.micrometer.tracing.handler.TracingObservationHandler.getRequiredSpan(TracingObservationHandler.java:209)
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    *__checkpoint ⇢ ServerWebExchangeReactorContextWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.WebFilterChainProxy [DefaultWebFilterChain]
    *__checkpoint ⇢ HTTP GET "/an-endpoint" [ExceptionHandlingWebHandler]
Original Stack Trace:
    at io.micrometer.tracing.handler.TracingObservationHandler.getRequiredSpan(TracingObservationHandler.java:209)
    at io.micrometer.tracing.handler.DefaultTracingObservationHandler.onStop(DefaultTracingObservationHandler.java:50)
    at io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onStop(ObservationHandler.java:197)
    at io.micrometer.observation.SimpleObservation.lambda$notifyOnObservationStopped$0(SimpleObservation.java:268)
    at java.base/java.util.ArrayDeque$DescendingIterator.forEachRemaining(Unknown Source)
    at io.micrometer.observation.SimpleObservation.notifyOnObservationStopped(SimpleObservation.java:268)
    at io.micrometer.observation.SimpleObservation.stop(SimpleObservation.java:188)
    at org.springframework.security.web.server.ObservationWebFilterChainDecorator$PhasedObservation.close(ObservationWebFilterChainDecorator.java:763)
    at org.springframework.security.web.server.ObservationWebFilterChainDecorator$AroundWebFilterObservation$SimpleAroundWebFilterObservation.close(ObservationWebFilterChainDecorator.java:301)
    at org.springframework.security.web.server.ObservationWebFilterChainDecorator$AroundWebFilterObservation$SimpleAroundWebFilterObservation.lambda$wrap$3(ObservationWebFilterChainDecorator.java:366)

It fails to close the apparently unstarted "after observation" (this.after.close();) as it tries to stop it first. This should not happen as the close method stops only previously started observations. There seems to be a mismatch between this.phase (0 = initial / 1 = started / 2 = stopped / 3 = closed) and the actual state of the this.after observation. Besides of the code fragment mentioned in my question above, I haven't found anything suspicious, yet.

~UDPATE: Downgrading from spring-security-web:6.2.1 to 6.2.0 (i.e. without https://github.com/spring-projects/spring-security/commit/5dce82c48bc0b174838501c5a111b2de70822914) solves the issues in our tests.~