@RequestScope cannot be used with HTTP client blocking requests

[graemerocher]

Discussed in #10883

^{Originally posted by BharathMC June 4, 2024}

Expected Behavior

Concurrent requests to micronaut service should work fine without any issues.

Actual Behaviour

I am facing issue with concurrent requests hitting micronaut service.

To simplify, I have made this application: I have exposed a GET method REST api, which calls external service REST API and returns HTTP 200.

When I run these in sequential, it works fine. But, when I run in concurrent fashion with just 2 threads, it fails with timeout exception after 200 requests.

Note: External REST API which is being called using HttpClient within micronaut service is not an issue. It has been tested with more than 20million requests with about 19k TPS and it is just GET api which returns json response.

Steps To Reproduce

Resource class

@Controller("/test")
@RequestScope
public class TestResource {

    @Inject
    @Client("client1")
    HttpClient myLocalhttpClient;


    @Get(uri = "/http", produces = MediaType.TEXT_PLAIN)
    public HttpResponse<?> testHttpClient() {
        String requestId = String.valueOf(UUID.randomUUID());
        System.out.println("received request "+requestId);
        String baseUri = "http://localhost:8082/health";

        URI builder = UriBuilder.of(baseUri).build();

        HttpRequest<?> request = HttpRequest.GET(baseUri)
                .accept(MediaType.APPLICATION_JSON_TYPE)
                .contentType(MediaType.APPLICATION_JSON_TYPE)
                .uri(builder);

        HttpResponse<String> response = myLocalhttpClient.toBlocking().exchange(request, String.class);
        String resBody = response.getBody().isPresent() ? response.getBody().get() : null;
        HttpStatus status = response.status();

        System.out.println("Response status= " + status);
        System.out.println("Response Body= " + resBody);
        System.out.println("received completed "+requestId);
        return HttpResponse.ok();
    }
}

Filter class

@ClientFilter(value = Filter.MATCH_ALL_PATTERN, serviceId = "client1")
public class MyClientFilter {

    public MyClientFilter() {

    }

    @RequestFilter
    @ExecuteOn(TaskExecutors.BLOCKING)
    public void filterRequest(MutableHttpRequest<?> request) {
        System.out.println("Inside MyClientFilter interceptor "+ request.getPath());
    }
}

application.properties

micronaut.http.services.client1.url=http://localhost
micronaut.http.services.client1.log-level=DEBUG
micronaut.http.services.client1.read-timeout=180s
micronaut.http.services.client1.read-idle-timeout=120s
micronaut.http.services.client1.connect-timeout=120s
micronaut.http.services.client1.num-of-threads=25

micronaut.http.services.client1.pool.enabled=true
micronaut.http.services.client1.pool.max-pending-acquires=128
micronaut.http.services.client1.pool.acquire-timeout=3m
micronaut.http.services.client1.pool.max-concurrent-http1-connections=512
micronaut.http.services.client1.pool.max-pending-connections=64

Exception after some requests (about 200 requests):

2024-06-04 16:52:29 [io-executor-thread-2] ERROR i.m.http.server.RouteExecutor - Unexpected error occurred: Connection closed before response was received
io.micronaut.http.client.exceptions.ResponseClosedException: Connection closed before response was received
	at io.micronaut.http.client.netty.DefaultHttpClient$BaseHttpResponseHandler.channelInactive(DefaultHttpClient.java:2073)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.netty.handler.codec.MessageAggregator.channelInactive(MessageAggregator.java:441)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.netty.handler.codec.http.HttpContentDecoder.channelInactive(HttpContentDecoder.java:235)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:411)
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:376)
	at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:328)
	at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.micronaut.http.client.netty.ConnectionManager$Pool$ConnectionHolder$3.channelInactive(ConnectionManager.java:1139)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.handler.logging.LoggingHandler.channelInactive(LoggingHandler.java:206)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
	at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:840)
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:103)
		at reactor.core.publisher.Flux.blockFirst(Flux.java:2704)
		at io.micronaut.http.client.netty.DefaultHttpClient$1.exchange(DefaultHttpClient.java:570)
		at io.micronaut.http.client.BlockingHttpClient.exchange(BlockingHttpClient.java:77)
		at io.micronaut.http.client.BlockingHttpClient.exchange(BlockingHttpClient.java:106)

Exception happens at

HttpResponse<String> response = myLocalhttpClient.toBlocking().exchange(request, String.class);

and

2024-06-04 16:55:29 [io-executor-thread-3] ERROR i.m.http.server.RouteExecutor - Unexpected error occurred: Read Timeout
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$exchangeImpl$28(DefaultHttpClient.java:1155)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94)
	at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:295)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280)
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419)
	at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162)
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271)
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	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:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
...
2024-06-04 16:55:50 [default-nioEventLoopGroup-1-11] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.timeout.ReadTimeoutException: null

Post stopping the incoming requests, these logs are printed continuously

2024-06-04 16:55:50 [default-nioEventLoopGroup-1-11] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.timeout.ReadTimeoutException: null

Thanks

Environment Information

JDK 17

Example Application

No response

Version

4.2.1

[graemerocher]

@BharathMC seems to be an issue with @RequestScope controllers only, removing this annotation and making it singleton works fine. We will look into it and thanks for the report

[BharathMC]

Got it. So, the issue is @requestScope is creating the bean for the HttpClient but it is not cleaning up the resources on completion of the request.

Which breaks the definition of @RequestScope : A CustomScope that creates a new bean for every HTTP request.

And this is the case with both blocking and non-blocking HttpClient usage.

We will wait for the bug fix.

Thanks

[graemerocher]

No the issue is that a new client is created and the shutdown down for each request. The contract for request scope is correct what is incorrect is the shutting down of the clients which should be held in a different scope it seems

[graemerocher]

Also FWIW why do you need RequestScope? In general it is an anti pattern

[BharathMC]

As the doc says :
@requestScope scope is a custom scope that indicates a new instance of the bean is created and associated with each HTTP request.

The problem with removing @requestScope and making it singleton, shares the thread objects (thread local vars).
We are using this for keeping each incoming requests isolated and all the data stored per request is kept in thread local variables. Basically thread safety. Each incoming request will have complex interception and the data needs to be maintained only for that thread and once the request is closed, we don't keep that info anymore. This is the same design we follow for SpringBoot and Helidon based libraries and as well and it works well, but facing issue with microanut framework. Either ways it is a bug.

So, it would be great if this issue gets fixed.

Thanks

[graemerocher]

we will fix it but in general it doesn't change that we regard ThreadLocal state is an anti-pattern. If you need a new object per request you can use @Prototype scope. Associating local object state with a thread increases memory for each thread and doesn't play well with virtual threads (scoped values hope to fix this but not JDK has these stable yet). Associating state with threads also doesn't work well with reactive or non-blocking use cases.

[BharathMC]

Thank you for fixing this quickly, @graemerocher.

Sure, meanwhile will explore @Prototype for scope till the fix is available to public as part of release.