ObservationWebFilterChainDecorator cancel signal triggers Observation::start

[oemergenc]

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:
micrometer-metrics/tracing#357

[Hiosdra]

Hi, any progress with this? 🥹

[jzheaux]

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

[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 micrometer-metrics/tracing#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 5dce82c) solves the issues in our tests.