Micronaut-core: HTTP read timeout from declarative client

[ashish-sharma09]

The issue seems to be with Micronaut declarative http clients where they start erroring out with io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout when several concurrent requests are in play (more than 20 seems to reproduce issue consistently) using the clients.
This seem to only happen (wierdly) when a declarative client is used in conjunction with Micronaut security, Micronaut HttpClientFilter and Controller.

Initially we thought that the issue is exactly as reported here: https://github.com/micronaut-projects/micronaut-core/issues/2905 but trying out the workaround suggested in this post does not fix the issue for us.

Task List

• [x] Steps to reproduce provided
• [x] Stacktrace (if present) provided
• [x] Example that reproduces the problem uploaded to Github
• [x] Full description of the issue provided (see below)

Steps to Reproduce

Please see and run StatusIntegationSpec test at: https://github.com/ashish-sharma09/micronaut-http to reproduce the issue

1. Run from command line ./gradlew test -debug to see stacktrace (provided below) being produced.
2. Import into IDE of your choice and run test StatusIntegrationSpec (We used Intellij)
3. If StatusIntegrationSpec test is run with CONCURRENT_REQUESTS_COUNT(field defined in the test) value as 20 the issue is reproduced reliably (we have verified on two different machines) whereas a value with 10 or less makes the test pass.

Stacktrace:

io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout at io.micronaut.http.client.exceptions.ReadTimeoutException.<clinit>(ReadTimeoutException.java:26) at io.micronaut.http.client.DefaultHttpClient.lambda$null$29(DefaultHttpClient.java:1090) at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103) at io.micronaut.reactive.rxjava2.RxInstrumentedSubscriber.onError(RxInstrumentedSubscriber.java:83) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)

Expected Behaviour

Referring to the repo provided:
Test should pass with no error being thrown ie all responses from Status endpoint should return 200.

Actual Behaviour

Referring to the repo provided:
When status endpoint is hit with 20 concurrent requests, the http client fails with ReadTimeout error.

Environment Information

• Operating System: MacOS Catalina 10.15.4
• Micronaut Version: 1.3.4
• JDK Version: 1.8

Example Application

• https://github.com/ashish-sharma09/micronaut-http

[graemerocher]

This is caused by using blocking code within Netty's event loop. The following commit resolves the issue in your application:

https://github.com/graemerocher/micronaut-http/commit/5d2f0724051acc173f3178c0e112cc69cda0a451

Key message: don't block the event loop

[ashish-sharma09]

@graemerocher thanks for your inputs. However I want to keep my application synchronous which is why it is not non-blocking in my example. What you have essentially done is made it non-blocking completely. As per my understanding (https://docs.micronaut.io/1.3.4/guide/index.html#reactiveServer) the controller in my application should be executed on IO thread which removes the possibility of blocking the event loop.

Can you point me in the correct direction if I am missing something here?

[graemerocher]

you can do that in controllers, but filters which return a publisher you need to run the operation in a different thread if you block

[graemerocher]

Alternatively you can switch to a server that is more designed for blocking. Such as Jetty/Tomcat/etc. see https://github.com/micronaut-projects/micronaut-servlet

[ashish-sharma09]

Sure, I get you now. Many thanks for your help. Sorry to raise this as a bug without realising the mistake.

[ashish-sharma09]

you can do that in controllers, but filters which return a publisher you need to run the operation in a different thread if you block

I cannot use HttpClientFilter in Micronaut with a blocking Controller even if I do not block the filter. Are you saying then only solution is to switch to a blocking server as suggested above?

[graemerocher]

What I am saying is inside your HttpClientFilter you were performing a blocking operation. You can do this, however if you do so you need to offload the work to a separate thread pool. So instead of:

   public Publisher<? extends HttpResponse<?>> doFilter(MutableHttpRequest<?> request, ClientFilterChain chain) {
        return chain.proceed(request.bearerAuth(tokenIssuer.retrieveToken().getAccessToken()));
    }

Where you are blocking on retrieveToken() you would need to do:

   public Publisher<? extends HttpResponse<?>> doFilter(MutableHttpRequest<?> request, ClientFilterChain chain) {
       return Flowable.fromCallable(() -> tokenIssuer.retrieveToken() )
                                .subscribeOn(Schedulers.io())
                                .map(res -> chain.proceed(request.bearerAuth(res.getAccessToken())));
    }

This is because filters need to be able to work in either scenario (blocking or non-blocking) since they can match a controller that blocks or a controller that doesn't.

If you or your team are uncomfortable with this and don't want to think about blocking vs non-blocking operations my recommendation is you consider a server that is designed around the thread per request model and not the event loop model like Micronaut's support for Jetty, Tomcat or Undertow.

[ashish-sharma09]

@graemerocher thanks for your swift responses, I have tried both ways as you suggested but the issue still seem to persist. See my branches here:

non-blocking-httpfilter
https://github.com/ashish-sharma09/micronaut-http/commit/265effb7a74fad90a600038a0e002be63622c6e4

non-blocking-auth-client
https://github.com/ashish-sharma09/micronaut-http/commit/ab31185095445d2665734d402ded2da194ba2bb0

We do not mind non-blocking code for http client filter and respective http clients as long as it works for us.

[dstepanov]

@ashish-sharma09 I was curious about what is wrong because we have a lot of blocking calls.

There is another problem in your example: AuthValidator is making a client call and then execution of the request continues in the http client's thread pool, next call is requestValidator.isValid which is blocking it and in the end, you end up with all http client threads blocked, no thread left to receive and send the response which would unblock it.

The solution is to add .subscribeOn or .observeOn in AuthValidator, but if you have a blocking filter running on Schedulers.io() adding .subscribeOn(Schedulers.io()) in AuthValidator will block io pool.

[ashish-sharma09]

thks @dstepanov it makes sense. I expected controller to not run on the event loop thread as it is a blocking controller, but it does so because of AuthValidator as you pointed out. The issue seems to go away with non-blocking auth client and filter and offloading AuthValidator (and Controller as a result) processing on a separate thread pool using .observeOn. See here:
https://github.com/ashish-sharma09/micronaut-http/commit/b3edd1709d90ae17491153fc6695403664ab1ece

Many thanks again for pointing out important points and mistakes here @graemerocher and @dstepanov 👍

As I see in the documentation of latest Micronaut version (we use 1.3.4) though that the design has changed around it and even blocking controller runs on event loop thread. However one can choose to run on separate pool using ExecuteOn. Am I right in saying that there has been major shift in the design between 1.3.x and 2.x.x version of Micronaut around this?