Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already #2499

Closed
amit84g opened this issue Sep 21, 2022 · 6 comments · Fixed by #2518
Closed

io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already #2499

amit84g opened this issue Sep 21, 2022 · 6 comments · Fixed by #2518
Assignees
Labels
type/bug A general bug
Milestone

Comments

@amit84g
Copy link

amit84g commented Sep 21, 2022

reactor-netty: 1.0.23
Spring Boot: 2.7.2

Expected Behavior

Actual Behavior: Getting below exception under heavy load:

++++++++++++++++++++
io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:860) ~[netty-handler-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:799) ~[netty-handler-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:780) ~[netty-handler-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.flush(CombinedChannelDuplexHandler.java:531) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:356) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:808) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306) ~[netty-transport-4.1.79.Final.jar!/:4.1.79.Final]
at reactor.netty.http.HttpOperations.lambda$send$0(HttpOperations.java:123) ~[reactor-netty-0.9.11.RELEASE.jar!/:0.9.11.RELEASE]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:125) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Mono.subscribe(Mono.java:4397) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:147) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxConcatIterable.subscribe(FluxConcatIterable.java:60) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2664) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:152) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2400) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2731) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) [reactor-core-3.4.21.jar!/:3.4.21]
at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:442) [reactor-netty-0.9.11.RELEASE.jar!/:0.9.11.RELEASE]
at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:518) [reactor-netty-0.9.11.RELEASE.jar!/:0.9.11.RELEASE]
at reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.run(PooledConnectionProvider.java:633) [reactor-netty-0.9.11.RELEASE.jar!/:0.9.11.RELEASE]
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:391) [netty-transport-classes-epoll-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.79.Final.jar!/:4.1.79.Final]
at java.lang.Thread.run(Thread.java:750) [na:1.8.0_345]
++++++++++++++++++++

Steps to Reproduce

new ReactorClientHttpConnector(
HttpClient.create()
.tcpConfiguration(
client ->
client.doOnConnected(
conn ->
conn.addHandlerLast(
new ReadTimeoutHandler(
readTimeOut))
.addHandlerLast(
new WriteTimeoutHandler(
writeTimeout)))

Possible Solution

Your Environment

  • Reactor version(s) used: reactor-netty: 1.0.23
  • Other relevant libraries versions (eg. netty, ...): Spring Boot: 2.7.2
  • JVM version (java -version):
  • OS and version (eg. uname -a):
@amit84g amit84g added status/need-triage A new issue that still need to be evaluated as a whole type/bug A general bug labels Sep 21, 2022
@pderop pderop removed the status/need-triage A new issue that still need to be evaluated as a whole label Sep 22, 2022
@pderop pderop self-assigned this Sep 22, 2022
@pderop
Copy link
Member

pderop commented Sep 22, 2022

this issue is a duplicate from #2498.
let's keep this issue opened for the moment, but please follow #2498.

@amit84g
Copy link
Author

amit84g commented Sep 22, 2022

@pderop : This is not a duplicate issue. May be it seemed like one but it is different. We are facing this during heavy load.
We have default fixed connection pool.
HttpClient.create()

@pderop
Copy link
Member

pderop commented Sep 22, 2022

I tend to think that the issue is similar to the other #2498, because in both cases, the http client is involved and is getting the SslClosedEngineException. I'm currently investigating.

so, like in the other issue, can you indicate the following:

  • can you tell if the the server is using a kind of configured keep alive/idle timeout (a delay the server will wait for another HTTP request before closing the connection) ?
  • can you provide a tcpdump when the SslClosedEngineException is happening ?
  • can you provide more debug logs at around the time you are observing the exceptions

thanks.

@pderop pderop added the for/user-attention This issue needs user attention (feedback, rework, etc...) label Sep 27, 2022
@anmol1vw13
Copy link

anmol1vw13 commented Sep 28, 2022

Hi @pderop,
I'm facing this issue with negligible load.

Stack:
spring-boot-starter-parent 2.5.3
spring-boot-starter-webflux 2.5.6

Error: The connection observed an error io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already

Here's the trace

[id:31e016c9-2, L:/x.xx.xxx.xx:56499 - R:xxx.payu.in/xy.xyy.xyyy.xyy:443] The connection observed an error
io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
    at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:861)
    at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:800)
    at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:781)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742)
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
    at io.netty.handler.logging.LoggingHandler.flush(LoggingHandler.java:304)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:742)
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.flush(CombinedChannelDuplexHandler.java:531)
    at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125)
    at io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:356)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:808)
    at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025)
    at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306)
    at reactor.netty.http.HttpOperations.lambda$send$0(HttpOperations.java:128)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:125)
    at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:90)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
    at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.request(ScopePassingSpanSubscriber.java:76)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
    at org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onSubscribe(ScopePassingSpanSubscriber.java:69)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4338)
    at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:147)
    at reactor.core.publisher.FluxConcatIterable.subscribe(FluxConcatIterable.java:60)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:424)
    at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:654)
    at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.run(DefaultPooledConnectionProvider.java:287)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
    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(Unknown Source)

The web client bean that is used is as shown below

@Bean
    public WebClient apiClient() {
        HttpClient httpClient = HttpClient.create()
            .wiretap("reactor.netty.http.client.HttpClient", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)
            .responseTimeout(Duration.of(5, ChronoUnit.SECONDS));

        return WebClient.builder()
            .clientConnector(new ReactorClientHttpConnector(httpClient))
            .build();
    }

A sample API call using webclient

String data = apiClient.post().uri(url)
            .contentType(MediaType.APPLICATION_FORM_URLENCODED)
            .body(BodyInserters.fromFormData(formData))
            .retrieve()
            .bodyToMono(String.class)
            .block();

I know there are a lot of threads around this lately, but none of them have a solution.

@pderop
Copy link
Member

pderop commented Sep 28, 2022

Hi @anmol1vw13 ,

Please create a new issue that describes your use case and we will process it. Also ensure you upgraded to the latest release versions for Reactor/Spring”

thanks.

@pderop
Copy link
Member

pderop commented Sep 30, 2022

@amit84g,

Hi,

So, the exception reported means that the client is writing to a connection which has been previously invalidated by the server which has previously sent a TLS close_notify to the client (the server may send a close_notify at anytime, for whatever reasons, this means the server is about the close the connection).

I don't know what is your exact use case, you did not provide traces or tcpdump, so I can't tell when the close_notify has been received. Now, we are about to merge the #2518 PR, which normally avoids SslClosedEngineException: SSLEngine closed already exception.

But in case a close_notify is received by the client while the request is being written, or while the response is still pending and waited for, then you will get a PrematureCloseException, or an AbortedException.

I don't know if this may help in your use case, but if the server sends a close_notify because it is closing an inactive connection using a keep-alive timer, then you can work around by using a maxIdleTime on the Reactor Netty's connection pool to be less than the value on the server (check here).
So, until the PR is available in next version, you may investigate if the server is configured using a keep-alive timer which closes client connections on inactivity. And if it's the case, then you can try to apply the work around of using a lower idle timer on the reactor-netty http client.

pderop added a commit that referenced this issue Sep 30, 2022
#2518)

When a TLS close_notify is received and when the close_notify ack is replied, then the Netty SslHandler just does not close the channel. Instead of that, in that case it fires a SslCloseCompletionEvent.SUCCESS event down the pipeline, and the closing of the channel is left to other handlers.

And since the TLS RFC states that the party receiving a close_notify MUST respond with a close_notify alert of its own and close down the connection immediately, let's do this in Reactor-Netty.

This patch won't avoid AbortedExceptions or PrematureCloseException exceptions in case a close_notify is being received while a request is being written, or while a response is waited for, but it may address some of the pain highlighted by #2498, #2499, and #2509; and may avoid SslClosedEngineException: SSLEngine closed already " exceptions.
@violetagg violetagg added this to the 1.0.24 milestone Sep 30, 2022
@violetagg violetagg removed the for/user-attention This issue needs user attention (feedback, rework, etc...) label Sep 30, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/bug A general bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants