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.

Sign up for GitHub

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

Jump to bottom

SLEngine closed already #1828

Closed
AlexieKA opened this issue Sep 28, 2021 · 20 comments · Fixed by #2140
Closed

SLEngine closed already #1828

AlexieKA opened this issue Sep 28, 2021 · 20 comments · Fixed by #2140
Assignees
@violetagg
Labels
type/bug A general bug
Milestone
1.0.18

Comments

@AlexieKA
Copy link

AlexieKA commented Sep 28, 2021 •
edited

Our application is sending a large number of messages in parallel over HTTPS. Below is the HTTP client creation code (kotlin):

var httpClient = ReactorHttpClient.create(
        ConnectionProvider.create(
            params.connectionPoolName,
            params.connectionPoolSize.toInt()
        )
    )
 
httpClient = httpClient
    .option(ChannelOption.CONNECT_TIMEOUT_MILLIS, params.connectionTimeout.toInt())
    .doOnConnected { connection ->
        connection.addHandlerLast(ReadTimeoutHandler(params.readTimeout, TimeUnit.MILLISECONDS))
        connection.addHandlerLast(WriteTimeoutHandler(params.writeTimeout, TimeUnit.MILLISECONDS))
    }
    .wiretap(true)

httpClient = httpClient.secure { sslProvider ->
    sslProvider.sslContext(ssl)
}


val connector = ReactorClientHttpConnector(httpClient)

val webClient = WebClient.builder()
    .clientConnector(connector)
    .codecs { codecsConfigurer ->
        codecsConfigurer.defaultCodecs().maxInMemorySize(params.inputBufferSize)
    }
    .build()

Source code for sending:

return client.post().uri(url)
    .bodyValue(body ?: "")
    .accept(params.acceptContent)
    .acceptCharset(Charset.forName(params.acceptCharset))
    .retrieve()
    .toEntity(resultType)
    .onErrorMap {
        transformException(it)
    }

We faced with a floating-issue that mainly occurs with high load:

2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-7, L:/ - R:] Outbound error happened
io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:860)
	at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:799)
	at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:780)
	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.invokeFlush(AbstractChannelHandlerContext.java:742)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
	at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125)
	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 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
	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.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
	at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2664)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2400)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103)
	at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2731)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
	at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
	at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	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)
2021-09-21 18:31:11.143 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-7, L:/ - R:] The connection observed an error
io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
	at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:860)
	at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:799)
	at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:780)
	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.invokeFlush(AbstractChannelHandlerContext.java:742)
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
	at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125)
	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 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
	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.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
	at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2664)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2400)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103)
	at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2731)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068)
	at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFu

Extended logs for the problem channel below (real IP and URL are replaced):

2021-09-21 18:31:07.560 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4] Created a new pooled channel, now: 12 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:07.560 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.tcp.SslProvider        | [id:4798c8f4] SSL enabled using engine sun.security.ssl.SSLEngineImpl@65dfb1cb and SNI DST_NAME:9704
2021-09-21 18:31:07.561 - DEBUG| TID =  | reactor-http-epoll-132       | r.netty.transport.TransportConfig    | [id:4798c8f4] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:07.561 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4] REGISTERED
2021-09-21 18:31:07.561 - DEBUG| TID =  | reactor-http-epoll-132       | r.netty.transport.TransportConnector | [id:4798c8f4] Connecting to [DST_NAME/DST_IP:2].
2021-09-21 18:31:07.561 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4] CONNECT: DST_NAME/DST_IP:2
2021-09-21 18:31:07.566 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Registering pool release on close event for channel
2021-09-21 18:31:07.566 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel connected, now: 13 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:07.569 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] ACTIVE
2021-09-21 18:31:07.590 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:07.591 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:07.591 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:08.555 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:09.554 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:10.565 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:10.579 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:10.580 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS)
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}, [connected])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}, [connected])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [configured])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [configured])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1638B
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_sent])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_sent])
2021-09-21 18:31:10.581 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:10.661 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ: 642B
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Received response (auto-read:false) : [Content-Type=application/json;charset=utf-8, Pragma=no-cache, Cache-Control=no-store, content-length=515]
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_received])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_received])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.channel.FluxReceive    | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-1, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Received last HTTP packet
2021-09-21 18:31:10.662 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:10.662 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 10 active connections, 4 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] USER_EVENT: SslCloseCompletionEvent(SUCCESS)
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] READ COMPLETE
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 11 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.663 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.664 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:10.664 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1494B
2021-09-21 18:31:10.664 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:10.664 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:10.664 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-2, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:10.665 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:10.665 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 10 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 10 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1553B
2021-09-21 18:31:10.675 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:10.676 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:10.676 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-3, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:10.676 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:10.676 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.676 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.676 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.676 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.677 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.677 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.677 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:10.677 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 9 active connections, 2 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1636B
2021-09-21 18:31:10.878 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:10.879 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:10.879 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:10.879 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:10.879 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.879 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:10.879 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.880 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:10.880 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.880 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:10.880 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:10.880 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.103 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.104 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:11.104 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1621B
2021-09-21 18:31:11.104 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:11.104 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:11.104 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-5, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:11.105 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:11.105 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.118 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1623B
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:11.119 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-6, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:11.119 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.119 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:11.120 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1626B
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:11.142 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:11.143 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-7, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:11.143 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:11.143 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.160 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.160 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.160 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.160 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1728B
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:11.161 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:11.161 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-8, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:11.162 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:11.162 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 9 active connections, 0 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Added decoder [WriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, ReadTimeoutHandler, WriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Handler is being applied: {uri=https://DST_NAME:9704/url/, method=POST}
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [request_prepared])
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 189B
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] WRITE: 1633B
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.http.client.HttpClient | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] FLUSH
2021-09-21 18:31:11.166 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientOperations | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Outbound error happened
2021-09-21 18:31:11.166 - WARN | TID =  | reactor-http-epoll-132       | r.n.http.client.HttpClientConnect    | [id:4798c8f4-9, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] The connection observed an error
2021-09-21 18:31:11.167 - TRACE| TID =  | reactor-http-epoll-132       | r.netty.channel.ChannelOperations    | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Disposing ChannelOperation from a channel
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [response_completed])
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: ReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (WriteTimeoutHandler = io.netty.handler.timeout.WriteTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | reactor.netty.ReactorNetty           | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Removed handler: WriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.loggingHandler = reactor.netty.transport.logging.ReactorNettyLoggingHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] onStateChange(POST{uri=/url/, connection=PooledConnection{channel=[id: 0x4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2]}}, [disconnecting])
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.DefaultPooledConnectionProvide | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Releasing channel
2021-09-21 18:31:11.167 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel cleaned, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
2021-09-21 18:31:11.339 - DEBUG| TID =  | reactor-http-epoll-132       | r.n.r.PooledConnectionProvider       | [id:4798c8f4, L:/SRC_IP:1 - R:DST_NAME/DST_IP:2] Channel acquired, now: 8 active connections, 1 inactive connections and 0 pending acquire requests.
...
etc

In my opinion, the following situation occurs:

  • Our application initiates a TLS connection and sends data (line 1-47 in the extended log)
  • Then the recipient closes the TLS session by sending a close_notify message (line 48-49), but the TCP connection does not close;
  • As a result, netty considers this channel active and acquire this channel for sending other messages. It causes an error because the TLS session is already closed.

Expected Behavior

The channel is not acquired if the session is closed.

Actual Behavior

The channel is acquired (many times) for closed session.

Steps to Reproduce

  • Initiates a TLS connection and sends data;
  • Then the recipient closes the TLS session by sending a close_notify message, but the TCP connection does not close;
  • As a result, netty considers this channel active and acquire this channel for sending other messages. It causes an error because the TLS session is already closed.

Possible Solution

Disable connection pool:

var httpClient = ReactorHttpClient.newConnection()

Your Environment

  • Reactor version(s) used:

org.springframework.boot:spring-boot-starter-reactor-netty:2.5.4
| | --- io.projectreactor.netty:reactor-netty-http:1.0.10
| | +--- io.netty:netty-codec-http:4.1.66.Final -> 4.1.67.Final
| | +--- io.netty:netty-codec-http2:4.1.66.Final -> 4.1.67.Final
| | +--- io.netty:netty-resolver-dns:4.1.66.Final -> 4.1.67.Final
| | +--- io.netty:netty-resolver-dns-native-macos:4.1.66.Final -> 4.1.67.Final
| | +--- io.netty:netty-transport-native-epoll:4.1.66.Final -> 4.1.67.Final
| | +--- io.projectreactor.netty:reactor-netty-core:1.0.10
| | --- io.projectreactor:reactor-core:3.4.9 (*)

  • JVM version (java -version): java11-runtime-11.0.10+9
@AlexieKA AlexieKA added status/need-triage A new issue that still need to be evaluated as a whole type/bug A general bug labels Sep 28, 2021
@violetagg
Copy link
Member

@AlexieKA Is the connection closed at some point or it stays always opened?

@AlexieKA
Copy link
Author

AlexieKA commented Oct 1, 2021 •
edited

@AlexieKA Is the connection closed at some point or it stays always opened?

The connection is closed later and the errors end.

@violetagg violetagg removed the status/need-triage A new issue that still need to be evaluated as a whole label Oct 6, 2021
@violetagg violetagg added this to the 1.0.x Backlog milestone Oct 6, 2021
@leejegirl
Copy link

leejegirl commented Feb 12, 2022 •
edited

@violetagg Hi, I have a question about this.
Is same issue being occurred on below configuration?

HttpClient httpClient = HttpClient.create()
                    .option(ChannelOption.SO_KEEPALIVE, true);

ReactorClientHttpConnector reactorClientHttpConnector = new ReactorClientHttpConnector(httpClient);

webClient = WebClient.builder().clientConnector(reactorClientHttpConnector).build();

image

I just configured SO_KEEPALIVE and I faced below logs.
(I removed the post url)

org.springframework.web.reactive.function.client.WebClientRequestException: SSLEngine closed already; nested exception is io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
        at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141)
        Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
        *__checkpoint ⇢ Request to POST [DefaultWebClient]
Original Stack Trace:
                at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141)
                at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55)
                at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
                at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
                at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222)
                at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222)
                at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222)
                at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93)
                at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204)
                at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
                at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:225)
                at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:274)
                at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:415)
                at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:251)
                at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
                at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
                at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:100)
                at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
                at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:190)
                at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:194)
                at reactor.netty.http.client.HttpClientConnect$HttpObserver.onUncaughtException(HttpClientConnect.java:384)
                at reactor.netty.ReactorNetty$CompositeConnectionObserver.onUncaughtException(ReactorNetty.java:664)
                at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onUncaughtException(DefaultPooledConnectionProvider.java:201)
                at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onUncaughtException(DefaultPooledConnectionProvider.java:449)
                at reactor.netty.http.client.HttpClientOperations.onOutboundError(HttpClientOperations.java:580)
                at reactor.netty.channel.ChannelOperations.onError(ChannelOperations.java:254)
                at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
                at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
                at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
                at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onError(MonoIgnoreElements.java:84)
                at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onError(Operators.java:2063)
                at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
                at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:142)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127)
                at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
                at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
                at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
                at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
                at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
                at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)
                at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
                at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:147)
                at reactor.core.publisher.FluxConcatIterable.subscribe(FluxConcatIterable.java:60)
                at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
                at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
                at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
                at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2664)
                at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150)
                at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2400)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
                at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103)
                at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2731)
                at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194)
                at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068)
                at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115)
                at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
                at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
                at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
                at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
                at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:424)
                at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:671)
                at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.run(DefaultPooledConnectionProvider.java:269)
                at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
                at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
                at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
                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(Thread.java:829)
Caused by: io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
        at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:858)
        at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:797)
        at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:778)
        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 reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127)
        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
        at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
        at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
        at reactor.core.publisher.FluxConcatIterable$ConcatIterableSubscriber.onComplete(FluxConcatIterable.java:147)
        at reactor.core.publisher.FluxConcatIterable.subscribe(FluxConcatIterable.java:60)
        at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
        at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
        at reactor.core.publisher.Operators$MonoInnerProducerBase.complete(Operators.java:2664)
        at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:180)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150)
        at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2400)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169)
        at reactor.core.publisher.MonoSingle$SingleSubscriber.doOnRequest(MonoSingle.java:103)
        at reactor.core.publisher.Operators$MonoInnerProducerBase.request(Operators.java:2731)
        at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194)
        at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068)
        at reactor.core.publisher.MonoSingle$SingleSubscriber.onSubscribe(MonoSingle.java:115)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96)
        at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
        at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
        at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
        at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:424)
        at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:671)
        at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.run(DefaultPooledConnectionProvider.java:269)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
        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(Thread.java:829)

@hamadodene
Copy link

We have the same issue:
https://github.com/diennea/carapaceproxy/blob/master/carapace-server/src/main/java/org/carapaceproxy/core/Listeners.java
Do we have a workaround to fix this problem?

SEVERE: [880c7be0-1, L:/10.219.105.156:4089 - R:/161.53.180.19:54675] Error finishing response. Closing connection
io.netty.handler.ssl.SslClosedEngineException: SSLEngine closed already
        at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:858)
        at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:797)
        at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:778)
        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.invokeFlush(AbstractChannelHandlerContext.java:742)
        at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:728)
        at io.netty.channel.ChannelDuplexHandler.flush(ChannelDuplexHandler.java:127)
        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$then$3(HttpOperations.java:205)
        at reactor.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:100)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
        at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:255)
        at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4400)
        at reactor.netty.NettyOutbound.subscribe(NettyOutbound.java:336)
        at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:69)
        at reactor.netty.http.server.HttpServer$HttpServerHandle.onStateChange(HttpServer.java:962)
        at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:671)
        at reactor.netty.transport.ServerTransport$ChildObserver.onStateChange(ServerTransport.java:478)
        at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:560)
        at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:93)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:220)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
        at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at org.carapaceproxy.core.Listeners$2.channelRead(Listeners.java:256)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
        at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1371)
        at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1245)
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285)
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795)
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
        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(Thread.java:832)

@violetagg
Copy link
Member

@hamadodene Your issue is not the same because it happens on the server.
This issue is related to connection reuse on the client (connection pooling)
Please open a new issue where we will investigate your use case. Please provide reproducible example.

@leejegirl
Copy link

Hi,
Could you share the release schedule for this issue?

@violetagg
Copy link
Member

@leejegirl We will try for 1.0.17 but most probably 1.0.18.

If somebody wants to provide a PR with the fix, I'll be able to review it.

@leejegirl
Copy link

@violetagg
Sorry, I'm just waiting the fixed version because I don't have any resource and idea for this issue.

@leejegirl
Copy link

leejegirl commented Mar 7, 2022 •
edited

@violetagg, I have a question.
How to use the 'HttpClient.newConnection()'?
Is below code right?
(The webClient instance is been using as singleton)

public class WebClientBuilder {
    private static WebClient webClient;

    public static WebClient getWebClient() throws Exception {
        LOGGER.debug("getWebClient");

        if (webClient != null) {
            LOGGER.debug("webClient exist");
            return webClient;
        }
       
        HttpClient httpClient = HttpClient.create().newConnection()
                .option(ChannelOption.SO_KEEPALIVE, true);

        ReactorClientHttpConnector reactorClientHttpConnector = new ReactorClientHttpConnector(httpClient);

        LOGGER.debug("webClient was generated");

        webClient = WebClient.builder().clientConnector(reactorClientHttpConnector).build();

        return webClient;
    }
}

...
return WebClientBuilder.getWebClient()
                    .post()
                    .uri(url)
...

@violetagg
Copy link
Member

violetagg commented Mar 7, 2022 •
edited

@leejegirl It is described here https://projectreactor.io/docs/netty/release/reference/index.html#_connection_pool_2

HttpClient.newConnection() and not HttpClient.create().newConnection()

@leejegirl
Copy link

leejegirl commented Mar 7, 2022 •
edited

@violetagg Are they right?

HttpClient httpClient = HttpClient.newConnection().option(ChannelOption.SO_KEEPALIVE, true);

and

SslContext sslContext = SslContextBuilder
        .forClient()
        .sslProvider(SslProvider.JDK)
        .trustManager(InsecureTrustManagerFactory.INSTANCE)
        .build();

HttpClient httpClient = HttpClient.newConnection()
        .proxy(typeSpec -> typeSpec.type(ProxyProvider.Proxy.HTTP)
                .host(SystemConfigUtil.SMP_PROXY_HOST)
                .port(SystemConfigUtil.SMP_PROXY_PORT))
        .option(ChannelOption.SO_KEEPALIVE, true)
        .secure(sslContextSpec -> sslContextSpec.sslContext(sslContext));

And I have two more questions.

  1. Can I use together the newConnection() and ChannelOption.SO_KEEPALIVE?
  2. Webclient instance can be used as singleton, right? (Webclient instance does not need to be created for each http request.)

@leejegirl
Copy link

Im being confused by sample of https://projectreactor.io/docs/netty/release/reference/index.html#_connection_pool_2

@violetagg
Copy link
Member

Im being confused by sample of https://projectreactor.io/docs/netty/release/reference/index.html#_connection_pool_2

@leejegirl How can we improve the documentation so that it is less confusing?

@violetagg
Copy link
Member

@violetagg Are they right?

HttpClient httpClient = HttpClient.newConnection().option(ChannelOption.SO_KEEPALIVE, true);

yep

and

SslContext sslContext = SslContextBuilder
        .forClient()
        .sslProvider(SslProvider.JDK)
        .trustManager(InsecureTrustManagerFactory.INSTANCE)
        .build();

HttpClient httpClient = HttpClient.newConnection()
        .proxy(typeSpec -> typeSpec.type(ProxyProvider.Proxy.HTTP)
                .host(SystemConfigUtil.SMP_PROXY_HOST)
                .port(SystemConfigUtil.SMP_PROXY_PORT))
        .option(ChannelOption.SO_KEEPALIVE, true)
        .secure(sslContextSpec -> sslContextSpec.sslContext(sslContext));

yep

And I have two more questions.

  1. Can I use together the newConnection() and ChannelOption.SO_KEEPALIVE?

Please tell me the concrete use case that you have for SO_KEEPALIVE
You can find more about this option here https://projectreactor.io/docs/netty/release/reference/index.html#connection-timeout
Do you expect a network component that drops silently the connection?

  1. Webclient instance can be used as singleton, right? (Webclient instance does not need to be created for each http request.)

yep

@leejegirl
Copy link

I suggest to be added the sample for multi http request because I confused that I need to make HttpClient and create WebClient instance for each http request or not.

@violetagg
Copy link
Member

I suggest to be added the sample for multi http request because I confused that I need to make HttpClient and create WebClient instance for each http request or not.

@leejegirl Do you want to provide a PR?

@leejegirl
Copy link

I suggest to be added the sample for multi http request because I confused that I need to make HttpClient and create WebClient instance for each http request or not.

@leejegirl Do you want to provide a PR?

No, I don't ^^

@leejegirl
Copy link

@violetagg Are they right?

HttpClient httpClient = HttpClient.newConnection().option(ChannelOption.SO_KEEPALIVE, true);

yep

and

SslContext sslContext = SslContextBuilder
        .forClient()
        .sslProvider(SslProvider.JDK)
        .trustManager(InsecureTrustManagerFactory.INSTANCE)
        .build();

HttpClient httpClient = HttpClient.newConnection()
        .proxy(typeSpec -> typeSpec.type(ProxyProvider.Proxy.HTTP)
                .host(SystemConfigUtil.SMP_PROXY_HOST)
                .port(SystemConfigUtil.SMP_PROXY_PORT))
        .option(ChannelOption.SO_KEEPALIVE, true)
        .secure(sslContextSpec -> sslContextSpec.sslContext(sslContext));

yep

And I have two more questions.

  1. Can I use together the newConnection() and ChannelOption.SO_KEEPALIVE?

Please tell me the concrete use case that you have for SO_KEEPALIVE You can find more about this option here https://projectreactor.io/docs/netty/release/reference/index.html#connection-timeout Do you expect a network component that drops silently the connection?
@violetagg Yes, I do.

  1. Webclient instance can be used as singleton, right? (Webclient instance does not need to be created for each http request.)

yep

@violetagg violetagg modified the milestones: 1.0.x Backlog, 1.0.18 Mar 8, 2022
violetagg added a commit that referenced this issue Mar 8, 2022
@violetagg
[doc] Extend the example for disabling the connection pool
69716e7 
Show that with one and the same HttpClient instance, one can
initiate many requests that always will use a new connection.

Related to comment #1828 (comment)
@violetagg violetagg mentioned this issue Mar 8, 2022
Merged
@violetagg
Copy link
Member

@leejegirl I prepared a PR #2082 for extending the documentation with your suggestion. Please take a look.

violetagg added a commit that referenced this issue Mar 8, 2022
@violetagg
[doc] Extend the example for disabling the connection pool (#2082)
4ceaf84 
Show that with one and the same HttpClient instance, one can
initiate many requests that always will use a new connection.

Related to comment #1828 (comment)
@leejegirl
Copy link

@violetagg It's better. Thanks.

@violetagg violetagg self-assigned this Apr 4, 2022
violetagg added a commit that referenced this issue Apr 4, 2022
@violetagg
Do not return the connection to the pool in case SSLEngine has been c…
3b39aea 
…losed

Fixes #1828
@violetagg violetagg mentioned this issue Apr 4, 2022
Merged
@violetagg violetagg linked a pull request Apr 4, 2022 that will close this issue
Do not return the connection to the pool in case SSLEngine has been closed #2140
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@violetagg violetagg

Labels
type/bug A general bug
Projects
None yet
Milestone
1.0.18
Development

Successfully merging a pull request may close this issue.

Do not return the connection to the pool in case SSLEngine has been closed reactor/reactor-netty
4 participants
@violetagg @AlexieKA @leejegirl @hamadodene