WebClient request level timeout Throws Operator called default onErrorDropped

2
votes

We are using Spring Reactive WebClient to make http calls. It uses JettyClientHttpConnector underneath. To set request level timeouts we use The Mono timeout API.

If there is no response from the server, the mono times out, but it also throws 

Operator called default onErrorDropped java.lang.InterruptedException

After few instances of this error we get insufficient thread issue in jetty connection pool. 

java.lang.IllegalStateException: Insufficient configured threads: required=200 \u003c max=200 for QueuedThreadPool[HttpClient@49e4c2d5]@687d1782{STARTED,8\u003c=199\u003c=200,i=1,q=0}[ReservedThreadExecutor@3eaa0b62{s=0/1,p=0}]

We suspect due to onErrorDropped exception, the connections are not getting released. How to make sure the connection resources are getting released after the Mono timeout?

Dependency

org.springframework:spring-webflux:jar:5.1.4.RELEASE
org.springframework.boot:spring-boot-starter-jetty:jar:2.1.2.RELEASE
org.springframework.cloud:spring-cloud-stream-reactive:jar:2.2.0.M1

WebClient config

WebClient.Builder.clone()
.clientConnector(new JettyClientHttpConnector(new HttpClient())).build();

Client call


URI request = UriComponentsBuilder
.fromUriString("foo")
.path("/path")
.build();

return webClient.put()
   .uri(request)
   .body(BodyInserters.fromObject(fooBar))
   .retrieve()
   .onStatus(HttpStatus::isError, clientResponse -> 
 clientResponse.toEntity(String.class)
                .map(body -> new RunTimeException(body.toString())))
   .bodyToMono(Foo2.class)
   .timeout(Duration.ofMillis(100))
   .retry(3, retryError -> retryError instanceof TimeoutException);

Exception

Mono Timeout:-

java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 500ms in 'lift' (and no fallback has been configured)

reactor.core.publisher.Operators         : Operator called default onErrorDropped java.lang.InterruptedException: null
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998) ~[na:1.8.0_192]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) ~[na:1.8.0_192]
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231) ~[na:1.8.0_192]
        at org.eclipse.jetty.io.ManagedSelector.doStart(ManagedSelector.java:106) ~[jetty-io-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:262) ~[jetty-io-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[jetty-client-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:250) ~[jetty-client-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.springframework.http.client.reactive.JettyClientHttpConnector.connect(JettyClientHttpConnector.java:98) ~[spring-web-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
        at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:103) ~[spring-webflux-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) [spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) [spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1505) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) [spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onNext(MonoSubscribeOn.java:143) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) [spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1505) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:61) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.Mono.subscribe(Mono.java:3695) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:123) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.async.TraceCallable.call(TraceCallable.java:70) [spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_192]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_192]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_192]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_192]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_192]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_192]

reactor.core.scheduler.Schedulers        : Scheduler worker in group main failed with an uncaught exception java.lang.InterruptedException: null
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:998) ~[na:1.8.0_192]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) ~[na:1.8.0_192]
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231) ~[na:1.8.0_192]
        at org.eclipse.jetty.io.ManagedSelector.doStart(ManagedSelector.java:106) ~[jetty-io-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:262) ~[jetty-io-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[jetty-client-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:138) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:108) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:250) ~[jetty-client-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[jetty-util-9.4.14.v20181114.jar!/:9.4.14.v20181114]
        at org.springframework.http.client.reactive.JettyClientHttpConnector.connect(JettyClientHttpConnector.java:98) ~[spring-web-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
        at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:103) ~[spring-webflux-5.1.4.RELEASE.jar!/:5.1.4.RELEASE]
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) ~[spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) ~[spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1505) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) ~[spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onNext(MonoSubscribeOn.java:143) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96) ~[spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1505) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:61) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.Mono.subscribe(Mono.java:3695) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:123) ~[reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37) [reactor-core-3.2.5.RELEASE.jar!/:3.2.5.RELEASE]
        at org.springframework.cloud.sleuth.instrument.async.TraceCallable.call(TraceCallable.java:70) ~[spring-cloud-sleuth-core-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_192]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_192]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_192]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_192]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_192]
        at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_192]
1
javaspring-webfluxembedded-jettyproject-reactor
you should define timeouts for webclient docs.spring.io/spring/docs/current/spring-framework-reference/… – Toerktumlare
@ThomasAndolf We want to set timeout per request level, setting the timeout at the client level removes that flexibility. – Amit Senapati
Mono#timeout has nothing to do with the webclient connection. Webclient timeouts work on a tcp level, while Mono#timeout works on a emitting level. – Toerktumlare

1 Answers

1
votes

That category of errors (onXxxDropped) represents "protocol errors", where a signal is received that doesn't comply to the Reactive Streams spec. Here an onError signal (the InterruptedException) is received after another onError (the timeout).

I'm not sure what causes the interruption (jetty or webflux), and whether or not the root cause can be fixed in the WebClient, but you could register a global hook to change the default onErrorDropped behavior (see Hooks#onErrorDropped(Consumer)).

Alternatively, you can register a local hook on the problematic Flux with the following (un-supported) piece of code:

Flux<T> doubleErroringFlux;
Consumer<Throwable> droppedErrorConsumer = ...;
Flux<T> fluxToUser = doubleErroringFlux
    .subscriberContext(Context.of("reactor.onErrorDropped.local",
    droppedErrorConsumer);
fluxToUse.subscribe(); //or pass down the method, or whatever