SSLEngine closed already

[dkulig]

I have a SpringBoot WebFlux app which Is talking to an external http server.
All looks good expect the fact that my tracing library is reporting SSLEngine closed already errors randomly after a request to my app is already finished.

javax.net.ssl.SSLException: SSLEngine closed already at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:837) at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:800) at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:781) at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:1886) at io.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1854) at

The weird thing is that this is happening 10 - 20 - 30 minutes after the request completes, I happens only periodically.

Gradle: io.projectreactor.netty:reactor-netty:0.9.2.RELEASE Gradle: io.projectreactor:reactor-core:3.3.1.RELEASE Gradle: io.projectreactor:reactor-test:3.3.1.RELEASE

Spring set-up:

    @Bean
    fun webClient(httpClient: HttpClient): WebClient = WebClient.builder()
        .clientConnector(ReactorClientHttpConnector(httpClient))
        .build()

    @Bean
    fun httpClient(tcpClient: TcpClient): HttpClient = HttpClient
        .from(tcpClient)
        .compress(true)

    @Bean
    fun tcpClient(@Value("\${app.httpClient.requestTimeoutMs}") httpRequestTimeout: Int): TcpClient =
        TcpClient.create(connectionProvider())
            .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, httpRequestTimeout)
            .doOnConnected { connection ->
                connection.addHandlerLast(ReadTimeoutHandler(httpRequestTimeout.toLong(), TimeUnit.MILLISECONDS))
                    .addHandlerLast(WriteTimeoutHandler(httpRequestTimeout.toLong(), TimeUnit.MILLISECONDS))
            }

    private fun connectionProvider(): ConnectionProvider {
        return ConnectionProvider.fixed(
            "fixed-tpc-connection-provider",
            DEFAULT_NETTY_MAX_CONNECTIONS,
            DEFAULT_NETTY_ACQUIRE_TIMEOUT_MS,
            Duration.ofSeconds(NETTY_CONNECTION_POOL_IDLE_TIMEOUT_SECONDS)
        )
    }

I use the custom connection provider because a NAT Gateway closes my open connections. This issue was also observed when using default WebClient settings.

Looking for any advice

[violetagg]

@dkulig Can you extract this piece of code into a project that can be used to reproduce the issue?

[andreisilviudragnea]

@dkulig Could you verify in your logs if the exception keeps showing up on the same Netty channel? The Netty channel id is the CHANNEL_ID placeholder in the following logger format r.n.http.client.HttpClientConnect - [id: <CHANNEL_ID>, L:/10.71.239.61:40838 - R:/34.231.233.38:443].

I think it is relevant that this error keeps showing up on the same Netty channel.

[andreisilviudragnea]

I have added the details of the Reactor operators which see this error. It looks like it simply bubbles up to the application code and is not handled in any way.

Caused by: javax.net.ssl.SSLException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:837)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Assembly trace from producer [reactor.core.publisher.MonoLift] :
	reactor.core.publisher.Mono.error(Mono.java:281)
	reactor.netty.FutureMono.from(FutureMono.java:53)
Error has been observed at the following site(s):
	|_         Mono.error ? at reactor.netty.FutureMono.from(FutureMono.java:53)
	|_       Mono.flatMap ? at reactor.netty.http.HttpOperations.send(HttpOperations.java:99)
	|_        Flux.concat ? at org.springframework.http.client.reactive.AbstractClientHttpRequest.doCommit(AbstractClientHttpRequest.java:135)
	|_          Flux.then ? at org.springframework.http.client.reactive.AbstractClientHttpRequest.doCommit(AbstractClientHttpRequest.java:135)
	|_       Mono.flatMap ? at org.springframework.http.codec.FormHttpMessageWriter.write(FormHttpMessageWriter.java:132)
	|_       Mono.flatMap ? at org.springframework.http.codec.multipart.MultipartHttpMessageWriter.write(MultipartHttpMessageWriter.java:188)
	|_         Mono.defer ? at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:429)
	|_        Mono.create ? at reactor.netty.resources.PooledConnectionProvider.acquire(PooledConnectionProvider.java:135)
	|_        Mono.create ? at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.subscribe(HttpClientConnect.java:284)
	|_         Mono.retry ? at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect.subscribe(HttpClientConnect.java:321)
	|_   Mono.flatMapMany ? at reactor.netty.http.client.HttpClientFinalizer.responseConnection(HttpClientFinalizer.java:85)
	|_          Flux.next ? at org.springframework.http.client.reactive.ReactorClientHttpConnector.connect(ReactorClientHttpConnector.java:112)
	|_   Mono.doOnRequest ? at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:105)
	|_    Mono.doOnCancel ? at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:106)
	|_           Mono.map ? at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.exchange(ExchangeFunctions.java:107)
	|_         checkpoint ? Request to POST null [DefaultWebClient]
	|_ Mono.switchIfEmpty ? at org.springframework.web.reactive.function.client.DefaultWebClient$DefaultRequestBodyUriSpec.lambda$exchange$0(DefaultWebClient.java:340)
	|_         Mono.defer ? at org.springframework.web.reactive.function.client.DefaultWebClient$DefaultRequestBodyUriSpec.exchange(DefaultWebClient.java:338)
	|_       Mono.flatMap ? at org.springframework.web.reactive.function.client.DefaultWebClient$DefaultResponseSpec.bodyToMono(DefaultWebClient.java:468)
Stack trace:
		at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:837)
		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:749)
		at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741)
		at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727)
		at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.flush(CombinedChannelDuplexHandler.java:533)
		at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125)
		at io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:358)
		at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749)
		at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741)
		at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727)

reactor-netty version: 0.9.2-RELEASE
spring-web version: 5.2.1-RELEASE
netty version: 4.1.43.Final

There is also a log which also suggests this exception is unhandled:

r.n.http.client.HttpClientConnect - [id: 0x5fc7ec9f, L:/10.71.239.61:40838 - R:/34.231.233.38:443] The connection observed an error
javax.net.ssl.SSLException: SSLEngine closed already

[violetagg]

All

If you are able to test this PR #1065 it will be great

Thanks

[violetagg]

The cases that may lead to this exception are:

1. There is an idle timeout on the target server. The connection may be acquired successfully from the pool, but meantime to be closed by the target server.
   With the PR above we will try to re-acquire a new connection in some cases, depending when the connection close happend.
   The connection pool may be configured with pool.maxIdleTime < targetServer max idle time + LIFO leasing strategy. This LIFO strategy will guarantee that if the first connection in the pool exceeds the idle timeout that all connections in the pool will be cleared as they also exceeds the idle timeout.
2. There is TCP keepalive time setting on the system. The connection may be acquired successfully from the pool, but meantime to be closed by the system because of that setting.
   With the PR above we will try to re-acquire a new connection in some cases, depending when the connection close happend.
   The connection pool may be configured with pool.maxLifeTime < TCP keepalive time + LIFO leasing strategy. This LIFO strategy will guarantee that if the first connection in the pool exceeds the life timeout that all connections in the pool will be cleared as they also exceeds the life timeout.

[violetagg]

The fix will be available in 0.9.7.RELEASE
Meanwhile it can be tested with 0.9.7.BUILD-SNAPSHOT

[brunoaduarte]

The fix will be available in 0.9.7.RELEASE
Meanwhile it can be tested with 0.9.7.BUILD-SNAPSHOT

Hi, the problem still occurs on 0.9.7.RELEASE

[violetagg]

@brunoaduarte Open a new issue and test with the latest available release. You may see the same exception but the reason to be different.