Micronaut 4.x.x ResponseClosedException happend at OAuth 2.0

HiroVodka commented 5 months ago

Expected Behavior

Authentication with Oauth2.0 should be no problem with the functionality provided by micronaut However, since the major version of micronaut is 4.x.x, errors occur very rarely during authentication.

Actual Behaviour

This error occurs when requesting the POST /oauth/token endpoint for Oauth authentication

io.micronaut.http.client.exceptions.ResponseClosedException Connection closed before response was received
Copy
(Most recent call first)
at
io.micronaut.http.client.netty.DefaultHttpClient$BaseHttpResponseHandler.channelInactive(DefaultHttpClient.java:2094)
Copy filepath
35 non-project frames
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
Copy filepath
at
io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
Copy filepath
at
io.netty.handler.codec.MessageAggregator.channelInactive(MessageAggregator.java:441)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
Copy filepath
at
io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
Copy filepath
at
io.netty.handler.codec.http.HttpContentDecoder.channelInactive(HttpContentDecoder.java:235)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
Copy filepath
at
io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418)
Copy filepath
at
io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
Copy filepath
at
datadog.trace.instrumentation.netty41.client.HttpClientResponseTracingHandler.channelInactive(HttpClientResponseTracingHandler.java:92)
Copy filepath
at
io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
Copy filepath
at
io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
Copy filepath
at
io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
Copy filepath
at
io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
Copy filepath
at
io.netty.handler.codec.http2.AbstractHttp2StreamChannel$Http2ChannelUnsafe$2.run(AbstractHttp2StreamChannel.java:791)
Copy filepath
at
io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
Copy filepath
at
io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
Copy filepath
at
io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
Copy filepath
at
io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
Copy filepath
at
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
Copy filepath
at
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)
Copy filepath
at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
Copy filepath
at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Copy filepath
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Copy filepath
at
java.lang.Thread.run(Thread.java:840)
Copy filepath

Also, whenever an error occurs, this WARN is logged

java.net.SocketException: 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.
java.net.SocketException Connection reset
Copy
(Most recent call first)
14 non-project frames
at
sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
Copy filepath
at
sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
Copy filepath
at
io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:255)
Copy filepath
at
io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
Copy filepath
at
io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:357)
Copy filepath
at
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
Copy filepath
at
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
Copy filepath
at
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
Copy filepath
at
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
Copy filepath
at
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
Copy filepath
at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
Copy filepath
at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
Copy filepath
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Copy filepath
at
java.lang.Thread.run(Thread.java:840)

Steps To Reproduce

Reproduction method unknown

In our environment, it happens very rarely when a user authenticates.

Environment Information

Kotlin jvm: 1.9.23
micronaut version: 4.3.6

Example Application

No response

Version

4.3.6

sdelamo commented 5 months ago

do you have a sample app? are you using Micronaut Security?

tmalinakis-vng commented 3 months ago

Hello, we are facing the same issue when interacting with a JWKS endpoint after upgrading to Micronaut 4.5.0. We've tried disabling the http-client to revert to the previous nimbus behaviour but now are getting

java.net.SocketException: Closed by interrupt
    at java.base/java.net.Socket$SocketInputStream.read(Unknown Source)
    at java.base/sun.security.ssl.SSLSocketInputRecord.read(Unknown Source)
    at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(Unknown Source)
    at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(Unknown Source)
    at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(Unknown Source)
    at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(Unknown Source)
    at java.base/java.io.BufferedInputStream.fill(Unknown Source)
    at java.base/java.io.BufferedInputStream.read1(Unknown Source)
    at java.base/java.io.BufferedInputStream.implRead(Unknown Source)
    at java.base/java.io.BufferedInputStream.read(Unknown Source)
    at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
    at java.base/sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
    at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getInputStream(Unknown Source)
    at com.nimbusds.jose.util.DefaultResourceRetriever.getInputStream(DefaultResourceRetriever.java:366)
    at com.nimbusds.jose.util.DefaultResourceRetriever.retrieveResource(DefaultResourceRetriever.java:269)
    at io.micronaut.security.token.jwt.signature.jwks.ResourceRetrieverJwksClient.lambda$load$0(ResourceRetrieverJwksClient.java:65)
    at reactor.core.publisher.MonoCallable$MonoCallableSubscription.request(MonoCallable.java:137)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171)
    at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189)
    at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
    at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:48)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4568)
    at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126)
    at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$3(PropagatedContext.java:211)
    at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)
    at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)
    at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$4(PropagatedContext.java:228)
    at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$4(PropagatedContext.java:228)
    at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
    at java.base/java.lang.VirtualThread.run(Unknown Source)

tmalinakis-vng commented 3 months ago

Worth noting that this issue happens much more reliably with the Nimbus implementation. Not sure if the root cause is the same. Looks like the Publisher is cancelled for some reason?

We have rolled back to Micronaut 4.4.3 for now where we are not facing this issue.

graemerocher commented 3 months ago

do you have steps to reproduce?

yibo-long commented 1 week ago

I have a hypothesis as we are supporting multiple jwks for the authentication. If micronaut security already used one jwks to authenticate the request, it will cancel other jwks fetching, thus ends up with this error log.

yibo-long commented 1 week ago

Here is a sample code to reproduce it: https://github.com/yibo-long/micronaut-http-client-failure

It requires having 3 cognito pools to have a more reproducible state. Tested with 2 pools and could only get the error logs sparsely.

Steps:

Setup 3 cognito pools from us-west-2, and provide env vars as POOL_1,POOL_2, and POOL_3.
./gradlew run
Run curl: `curl -X GET -H "authorization: \<token from POOL_1>" http://localhost:8080/test

Notice error logs as below:

10:45:24.484 [virtual-executor4] ERROR i.m.s.t.j.s.j.ResourceRetrieverJwksClient - Exception loading JWK from xxx
java.net.SocketException: Closed by interrupt
at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1106)
at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:489)
at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(SSLSocketInputRecord.java:483)
at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:70)
at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1461)
at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1066)
at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:291)
at java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:347)
at java.base/java.io.BufferedInputStream.implRead(BufferedInputStream.java:420)
at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:399)
at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:827)
at java.base/sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:759)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1690)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1599)
at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java:223)
at com.nimbusds.jose.util.DefaultResourceRetriever.getInputStream(DefaultResourceRetriever.java:366)
at com.nimbusds.jose.util.DefaultResourceRetriever.retrieveResource(DefaultResourceRetriever.java:269)
at io.micronaut.security.token.jwt.signature.jwks.ResourceRetrieverJwksClient.lambda$load$0(ResourceRetrieverJwksClient.java:65)
at reactor.core.publisher.MonoCallable$MonoCallableSubscription.request(MonoCallable.java:137)
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.trySchedule(MonoSubscribeOn.java:189)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.onSubscribe(MonoSubscribeOn.java:134)
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:48)
at reactor.core.publisher.Mono.subscribe(Mono.java:4576)
at reactor.core.publisher.MonoSubscribeOn$SubscribeOnSubscriber.run(MonoSubscribeOn.java:126)
at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$3(PropagatedContext.java:211)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)
at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$4(PropagatedContext.java:228)
at io.micronaut.core.propagation.PropagatedContext.lambda$wrap$4(PropagatedContext.java:228)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
at java.base/java.lang.VirtualThread.run(VirtualThread.java:309)

Based on the above hypothesis, I checked micronaut-security code, but this doesn't seem to be picking up the first passed verification: https://github.com/micronaut-projects/micronaut-security/blob/422601f7ffb003e2f332965550bdbcd48e2bf84b/security-jwt/src/main/java/io/micronaut/security/token/jwt/nimbus/NimbusReactiveJsonWebTokenSignatureValidator.java#L46-L49

micronaut-projects / micronaut-security