Micronaut 2: Http client read timeouts errors

[dstepanov]

Not sure exactly what is going on but getting a lot of those when deployed. I saw there was some issue regarding HTTP2 but this the same code as in 1.3. I have tried different stuff but cannot reproduce locally.

i.m.h.c.e.ReadTimeoutException: Read Timeout
	at i.m.h.c.e.ReadTimeoutException.<clinit>(ReadTimeoutException.java:26)
	at i.m.h.c.n.DefaultHttpClient.lambda$null$35(DefaultHttpClient.java:1152)
	at i.r.i.o.f.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103)
	at i.m.r.r.RxInstrumentedSubscriber.onError(RxInstrumentedSubscriber.java:66)
	at i.r.i.o.f.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139)
	at i.r.i.o.f.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170)
	at i.r.i.s.ScheduledRunnable.run(ScheduledRunnable.java:66)
	at i.r.i.s.ScheduledRunnable.call(ScheduledRunnable.java:57)
	at j.u.c.FutureTask.run(FutureTask.java:264)
	at j.u.c.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at j.u.c.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at j.u.c.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(Thread.java:834)

[graemerocher]

Ok, little bit hard to provide a solution without an example that reproduces the issue 😢

[marianozunino]

Having the same issue. It only happens when I the app runs in a pod.

Project that is causing the problem: https://github.com/forbi/slow-mn

[graemerocher]

@FORBI do you have steps to reproduce for that app?

[dstepanov]

@graemerocher Is it possible this commit 1f370c4 caused something like this?

[graemerocher]

@dstepanov Could be. If we had a way to reproduce the issue then we could try do a git bisect or revert the commit and see if it is the cause

[marianozunino]

@FORBI do you have steps to reproduce for that app?

Deploy the app to k8s and hit the endpoint between 5-10 times.

[dstepanov]

@graemerocher With enabled logging, I see log full of messages:

Discarded inbound message EmptyLastHttpContent that reached at the tail of the pipeline. Please check your pipeline configuration.
Discarded message pipeline : [LoggingHandler#0, idle-state, http-server-codec, flow-control-handler, http-keep-alive-handler, http-compressor, http-decompressor, http-streams-codec, chunk-writer, micronaut-http-decoder, micronaut-http-encoder, websocket-upgrade-handler, micronaut-inbound-handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x4229cf2d, L:/100.96.42.204:8080 - R:/100.96.42.67:43418].

Possible solutions https://stackoverflow.com/questions/15242793/netty-pipeline-warning

[dstepanov]

It looks like it happens on the second request, first passes.

[dstepanov]

More info:

Jul 8, 2020 @ 09:48:14.496 nioEventLoopGroup-3-3 Read timeout at io.micronaut.http.client.netty.DefaultHttpClient.lambda$null$35(DefaultHttpClient.java:1152) (probably occured before CONNECT)

Jul 8, 2020 @ 09:48:14.494 nioEventLoopGroup-3-3 [id: 0x3bed0818] CONNECT: client request connected to host
Jul 8, 2020 @ 09:48:14.493 nioEventLoopGroup-3-3 Incoming HTTP Server Request

Multiple "Discarded inbound message" + "Discarded message pipeline" on nioEventLoopGroup-3-2 and nioEventLoopGroup-3-3

Jul 8, 2020 @ 09:47:13.489 nioEventLoopGroup-3-3 [id: 0x3bed0818] REGISTERED - incoming client request

multiple server + client requests

To me, it looks like pipeline error is blocking threads that are used for server and client processing.

Is it possible to have separate pools for the server and clients?

[graemerocher]

From the logs this looks like it is sending a file back since chunked writer is in the pipeline. That may help narrow down things down

[dstepanov]

It's not a file just a JSON request/response

[graemerocher]

You could try set micronaut.server.thread-selection: IO which runs all server requests on the IO thread pool.

You could also replace DefaultExecutorSelector with a new bean that runs on the executor service of your choice so yes it is possible to alter the behaviour. Still that doesn't get us closer to the root of the problem, I will hopefully get time soon to look at @FORBI's example

[graemerocher]

Unfortunately @FORBI's instructions to reproduce were not particularly helpful. His example application seems to require setup and fails with Unexpected error occurred: Failed to inject value for parameter [typeOfSrvE] of class: uy.com.antel.pi.debttlk.service.DebtFinder out of the box. Maybe if someone can provide a useful set of steps to reproduce this issue we can take a look.

[dstepanov]

I suspect the problem is related to how k8s (running inside AWS for us) is sending HTTP requests to the Micronaut server.
Simple hello-world with logging might produce the same Netty errors as I posted, maybe using a different HTTP client would also trigger the problem.

Unfortunately @FORBI's instructions to reproduce were not particularly helpful. His example application seems to require setup and fails with Unexpected error occurred: Failed to inject value for parameter [typeOfSrvE] of class: uy.com.antel.pi.debttlk.service.DebtFinder out of the box. Maybe if someone can provide a useful set of steps to reproduce this issue we can take a look.

I think you can delete typeOfSrvE