java.lang.IllegalArgumentException: Context does not have an entry for key [class io.micrometer.core.instrument.Timer$Sample]

[lukasherman]

Describe the bug
During load test an IllegalArgumentException occurs randomly in the logs.

Environment
Spring Boot 3.0.6 WebFlux application

• Micrometer version: 1.10.6
• Micrometer registry: prometheus
• OS: Linux
• Java version: openjdk version "17.0.2" 2022-01-18, OpenJDK Runtime Environment (build 17.0.2+8-86), OpenJDK 64-Bit Server VM (build 17.0.2+8-86, mixed mode, sharing)

To Reproduce
Strack trace below occurs randomly in the logs, every 2-90 seconds, under web server load (150 requests/s). Not sure if it goes here, or Spring, or Netty. Please check.

Expected behavior
No IllegalArgumentExceptions should appear in the logs.

Additional context

2023-04-28T10:16:45.975Z ERROR 1 --- [or-http-epoll-2] reactor.core.publisher.Operators         : Operator called default onErrorDropped

java.lang.IllegalArgumentException: Context does not have an entry for key [class io.micrometer.core.instrument.Timer$Sample]
	at io.micrometer.observation.Observation$Context.getRequired(Observation.java:946) ~[micrometer-observation-1.10.6.jar!/:1.10.6]
	at io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.onStop(DefaultMeterObservationHandler.java:65) ~[micrometer-core-1.10.6.jar!/:1.10.6]
	at io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onStop(ObservationHandler.java:197) ~[micrometer-observation-1.10.6.jar!/:1.10.6]
	at io.micrometer.observation.SimpleObservation.lambda$notifyOnObservationStopped$0(SimpleObservation.java:281) ~[micrometer-observation-1.10.6.jar!/:1.10.6]
	at java.base/java.util.ArrayDeque$DescendingIterator.forEachRemaining(ArrayDeque.java:772) ~[na:na]
	at io.micrometer.observation.SimpleObservation.notifyOnObservationStopped(SimpleObservation.java:281) ~[micrometer-observation-1.10.6.jar!/:1.10.6]
	at io.micrometer.observation.SimpleObservation.stop(SimpleObservation.java:192) ~[micrometer-observation-1.10.6.jar!/:1.10.6]
	at org.springframework.security.web.server.ObservationWebFilterChainDecorator$AroundWebFilterObservation$SimpleAroundWebFilterObservation$ObservationReference.stop(ObservationWebFilterChainDecorator.java:407) ~[spring-security-web-6.0.3.jar!/:6.0.3]
	at org.springframework.security.web.server.ObservationWebFilterChainDecorator$AroundWebFilterObservation$SimpleAroundWebFilterObservation.stop(ObservationWebFilterChainDecorator.java:290) ~[spring-security-web-6.0.3.jar!/:6.0.3]
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.cancel(FluxPeekFuseable.java:445) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:207) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.cancel(FluxDoOnEach.java:113) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.core.publisher.Operators.terminate(Operators.java:1277) ~[reactor-core-3.5.5.jar!/:3.5.5]
	at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:481) ~[reactor-netty-core-1.1.6.jar!/:1.1.6]
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:403) ~[netty-transport-classes-epoll-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.91.Final.jar!/:4.1.91.Final]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

[marcingrzejszczak]

Wow, this is super strange. Do you observe such behaviour with micrometer 1.10.7-SNAPSHOT?

[xerx593]

[micrometer-observation-1.10.6.jar]

[marcingrzejszczak]

I saw which version they are using. I was wondering if maybe the problem is not there in snapshots.

[jonatan-ivanov]

I think this should be only possible if .start() was not called.

[lukasherman]

I will investigate further. Thanks for your feedback.

[elliebas]

Having the same issue. The exception started to appear after upgrade Spring Boot to 3.0.6 version and micrometer (micrometer-registry-prometheus) to 1.10.6 version.

[olivierboudet]

same here : the issue appears after upgrading spring boot to 3.0.6 from 3.0.4.

[bclozel]

The stacktrace suggests that this is a bug that has been introduced in Spring Security 6.0.3 in spring-projects/spring-security#12829 or spring-projects/spring-security#12849.

This seems to happen when HTTP clients disconnect before the response has been fully written to the network.

Can anyone confirm by rolling back to Spring Security 6.0.2 and see if this happens still?

[lukasherman]

Confirmed, there are no stack traces on Spring Security 6.0.2.

[marcingrzejszczak]

OK so let's close this then in favour of Spring Security

[bclozel]

@lukasherman could you open an issue against Spring Security please?