Micronaut-core: Regression: HTTP client read timeout since 1.3.1

[esocode]

I just noticed that since 1.3.1 HTTP clients always cause read timeouts, at least when talking with a micronaut server (haven't tried other cases). When using 1.3.0 or earlier the code behaves as expected. Maybe caused by #2763? That seems to be the main change to HttpClient in 1.3.1. Client timeout setting has no effect on this problem.

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

1. Checkout example server and client (see links at the end)
2. run server with gradlew run
3. run client with gradlew run -> will cause read timeout exception although server received call and replied
4. change Micronaut version to 1.3.0 or lower in client gradle.properties -> client behaves as expected

Expected Behaviour

Client should receive result from server.

Actual Behaviour

read timeout exception:

Caused by: 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:1091)
        at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103)
        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)

Environment Information

• Operating System: Windows 10
• Micronaut Version: >= 1.3.1
• JDK Version: 8

Example Application

https://github.com/esocode/micronaut-http-server-test
https://github.com/esocode/micronaut-http-client-test

[esocode]

I just tried the just released 1.3.3, it shows the same effect. But I then also tried to invoke the service call from another Thread through a TaskScheduler and then it works without problems. So it seems that the problem only occurs when using an HTTP client on the main application thread. So far I had also been mainly using my clients from scheduled code which may be a reason why I didn't notice the problem earlier.

After reverting my apps to 1.3.0 I could use them as before but also noticed that read timeout exception occurred occasionally when I changed the control (and execution) flow during debugging. So maybe the core of the problem already exists in 1.3.0. I developed most of the HTTP communication part while still being on 1.2.x and don't recall any occurrence of read timeouts then (although I cannot rule them out).

[ghost]

Reproduced the same thing. Also tracked it down to a change between 1.3.0 and 1.3.1. Thanks for reporting this @esocode

[graemerocher]

This can be worked around in 1.3.3 by using event listeners instead. Example:

@Singleton
public class Application {

    @Inject
    private ServiceClient service;

    public static void main(final String[] args) {
        Micronaut.run(Application.class);
    }

    @EventListener
    void runApp(StartupEvent startupEvent) throws MalformedURLException {
        System.out.println(
            "*********************************************************");
        System.out.println(
            "ID of 'Test': " + service.getIdForName("Test").blockingGet());
    }
}

[esocode]

For me this is not really fixed. During the startup/injection phase I need to query data from a remote service. I'm doing that through an HttpClient from a bean that is initialized by Micronaut. Up to Micronaut 1.3.0 that worked without problems. But since 1.3.1 and still with 1.3.4 the remote call causes the ReadTimeoutException during startup.

[graemerocher]

Provide an example that reproduces the issue

[esocode]

I have updated the master branch of the client project to demonstrate the problem during bean initialization (server is unchanged):
https://github.com/esocode/micronaut-http-client-test

If the micronaut version is >= 1.3.1 the problem occurs. With 1.3.0 it works. Any hint for a workaround would be appreciated.

[graemerocher]

A workaround is to change the constructor to:

public ServiceBean(ObjectMapper objectMapper, Service service)

[graemerocher]

Think to fix this we need to make sure that jackson is initialized when @Client instances are injected

[esocode]

Can I do that manually somehow as a workaround?

[esocode]

Sorry, overlooked your workaround

[adam-yorwerth]

We're experiencing the same issue - happy to take the workaround suggested by @graemerocher for now.

Any eta on a fix?

[adam-yorwerth]

@graemerocher we actually just tried both workarounds and neither seems to fix the issue for us.

[esocode]

What do you mean with both workarounds? The workaround is to inject ObjectMapper in the constructor of your service (or any other @Contextbean) to ensure that Jackson is already initialized. In my case this workaround still works with 1.3.6.

[graemerocher]

Will take another look in 2.0.1

[volnei]

Same problem here with 2.0 after call any client for second time.

I'm using micronaut 2.0.0 and need to disable jackson due to another issue...

io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout
    at io.micronaut.http.client.exceptions.ReadTimeoutException.<clinit>(ReadTimeoutException.java:26)
    at io.micronaut.http.client.netty.DefaultHttpClient.lambda$null$35(DefaultHttpClient.java:1152)
    at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103)
    at io.micronaut.reactive.rxjava2.RxInstrumentedSubscriber.onError(RxInstrumentedSubscriber.java:66)
    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.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)

[graemerocher]

@volnei do you have an example that reproduces the issue?

[graemerocher]

I ask because I believe your problem is different

[anilbolat]

I also use Micronaut 2.0.0 and have the same issue when I call my client for second time...

[graemerocher]

@anilbolat Please provide an example that reproduces the issue

[volnei]

@graemerocher, yes!

https://github.com/volnei/bugreport

Steps to reproduce:

• Run both projects locally (gateway will run at 8086 and worker run at 8087)
• Call http://localhost:8086/worker

To reproduce the error, call multiple times quicly.

I'm using:

OS:           Mac OS X 10.15.5 x86_64

openjdk 11.0.2 2019-01-15
OpenJDK Runtime Environment 18.9 (build 11.0.2+9)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.2+9, mixed mode)

Gradle 6.5.1
------------------------------------------------------------

Build time:   2020-06-30 06:32:47 UTC
Revision:     66bc713f7169626a7f0134bf452abde51550ea0a

[graemerocher]

@volnei you are performing blocking operations on the netty event loop which is the default for Micronaut 2.0 (see the upgrading section on changes to the threading model https://docs.micronaut.io/latest/guide/index.html#upgrading)

Your problem can be fixed with the following change ( or even better just don't block):

---
 .../main/java/gateway/WorkerController.java   |  3 ++
diff --git a/gateway/src/main/java/gateway/WorkerController.java b/gateway/src/main/java/gateway/WorkerController.java
index d5cc164..b578643 100644
--- a/gateway/src/main/java/gateway/WorkerController.java
+++ b/gateway/src/main/java/gateway/WorkerController.java
@@ -2,12 +2,15 @@ package gateway;

 import io.micronaut.http.annotation.*;
 import io.micronaut.http.HttpResponse;
+import io.micronaut.scheduling.TaskExecutors;
+import io.micronaut.scheduling.annotation.ExecuteOn;

 import java.util.Map;

 import javax.inject.Inject;

 @Controller("/worker")
+@ExecuteOn(TaskExecutors.IO)
 public class WorkerController {
-- 

[volnei]

Thank you, i really didn't notice this change. Not a bug.

[graemerocher]

In the end I don't think this is fixable since you are essentially blocking the registration of any additional beans whilst the bean is bean is being constructed by using blockingGet in the constructor.

Our recommendation is to instead lazily initialization the value you need on first access rather than do it within the constructor that will likely cause deadlocks.