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). Please check.

Expected behavior
No IllegalArgumentExceptions should appear in the logs.

Additional context
See micrometer-metrics/micrometer#3792

The issue disappears with Spring Security 6.0.2.

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]

[jzheaux]

Thanks for the report, @lukasherman. I've checked in a fix, and the SNAPSHOT build should be available in about 20 minutes. Are you able to use that build to see if you can still reproduce the error?

[flutia]

I was having the same issue, and it's not reproduced in the new build. Thanks :)