reactor-netty
reactor-netty copied to clipboard
reactor
Connection has been closed BEFORE response, while sending request body
Periodically, some of the client requests are failing to complete the request/response cycle.
Following are the components which are involved in the entire request processing. Client (Source Application) --> Proxy Application --> Target (Destination Application) Client application invokes the API in Proxy application. This application creates new HTTP client connection with Target destination
Issue is happening between Proxy Application --> Target (Destination Application)
Proxy Application, uses Sprint boot with Netty reactor to forward the request to Target application
As per the logs collected, thread is waiting/blocked and not reading the response data from queue and when the time crosses more than 20 secs, Target application is terminating the connection as there is no activity on that thread/request. Due to which, Client gets failed response with Connection has been closed BEFORE response, while sending request body
Here is the code snippet:
public Mono<ResponseEntity<byte[]>> sendRequest(ProxyRequest proxyRequest) {
var key = TokenService.getKey(server.getHost(), server.getPort());
logEntity.setDomainAndPort(key);
var token = tokenService.getByKey(key);
log.debug("Sending the request to tenant: '{}'", key);
return client
.method(proxyRequest.getMethod())
.uri(destinationUri(proxyRequest, server))
.headers(h -> h.setBearerAuth(token.getAccessToken()))
.headers(h -> h.addAll(proxyRequest.getHeaders()))
.body(BodyInserters.fromResource(new InputStreamResource(proxyRequest.getBody())))
.exchangeToMono(this::clientResponse)
.retryWhen(retrySpec)
.doOnError(e -> log.error("Failed to send the request to server: '{}' with error",
server.getHost(), e))
.subscribeOn(Schedulers.parallel());
}
Expected Behavior
Request should have completed as expected
Actual Behavior
Request fails with following error
"boundedElastic-18" #423 daemon prio=5 os_prio=0 cpu=35.42ms elapsed=337.37s allocated=1343K defined_classes=0 tid=0x00007f9ce0003900 nid=0x5eb in Object.wait() [0x00007f9d136fd000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait([email protected]/Native Method)
- waiting on <no object reference available>
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.fillReadBuffer(NioEndpoint.java:1318)
- locked <0x0000000682ba0c30> (a java.util.concurrent.Semaphore)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.read(NioEndpoint.java:1219)
at org.apache.coyote.http11.Http11InputBuffer.fill(Http11InputBuffer.java:781)
at org.apache.coyote.http11.Http11InputBuffer$SocketInputBuffer.doRead(Http11InputBuffer.java:1187)
at org.apache.coyote.http11.filters.ChunkedInputFilter.readBytes(ChunkedInputFilter.java:283)
at org.apache.coyote.http11.filters.ChunkedInputFilter.fill(ChunkedInputFilter.java:324)
at org.apache.coyote.http11.filters.ChunkedInputFilter.parseChunkHeader(ChunkedInputFilter.java:354)
at org.apache.coyote.http11.filters.ChunkedInputFilter.doRead(ChunkedInputFilter.java:135)
at org.apache.coyote.http11.Http11InputBuffer.doRead(Http11InputBuffer.java:238)
at org.apache.coyote.Request.doRead(Request.java:636)
at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:312)
at org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:624)
at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:367)
at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:132)
at org.springframework.web.util.ContentCachingRequestWrapper$ContentCachingInputStream.read(ContentCachingRequestWrapper.java:281)
at java.nio.channels.Channels$ReadableByteChannelImpl.read([email protected]/Channels.java:387)
- locked <0x00000006807db790> (a java.lang.Object)
at org.springframework.core.io.buffer.DataBufferUtils$ReadableByteChannelGenerator.accept(DataBufferUtils.java:992)
at org.springframework.core.io.buffer.DataBufferUtils$ReadableByteChannelGenerator.accept(DataBufferUtils.java:968)
at reactor.core.publisher.FluxGenerate.lambda$new$1(FluxGenerate.java:58)
at reactor.core.publisher.FluxGenerate$$Lambda$3161/0x00007f9e67d1b240.apply(Unknown Source)
at reactor.core.publisher.FluxGenerate$GenerateSubscription.slowPath(FluxGenerate.java:271)
at reactor.core.publisher.FluxGenerate$GenerateSubscription.request(FluxGenerate.java:213)
at reactor.core.publisher.FluxUsing$UsingFuseableSubscriber.request(FluxUsing.java:320)
at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.request(Operators.java:2330)
at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.request(FluxConcatMapNoPrefetch.java:339)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.requestUpstream(FluxSubscribeOn.java:131)
at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.onSubscribe(FluxSubscribeOn.java:124)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.onSubscribe(FluxConcatMapNoPrefetch.java:164)
at reactor.core.publisher.FluxLimitRequest$FluxLimitRequestSubscriber.onSubscribe(FluxLimitRequest.java:132)
at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
at reactor.core.publisher.InternalFluxOperator.subscribe(InternalFluxOperator.java:68)
at reactor.core.publisher.FluxSubscribeOn$SubscribeOnSubscriber.run(FluxSubscribeOn.java:194)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:84)
at reactor.core.scheduler.WorkerTask.call(WorkerTask.java:37)
at java.util.concurrent.FutureTask.run([email protected]/FutureTask.java:264)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run([email protected]/ScheduledThreadPoolExecutor.java:304)
at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1136)
at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:635)
at java.lang.Thread.run([email protected]/Thread.java:840)
Stack trace at application
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:137)
at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55)
at reactor.core.publisher.Mono.subscribe(Mono.java:4576)
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:205)
at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:229)
at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:279)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.maybeOnError(FluxConcatMapNoPrefetch.java:327)
at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.onNext(FluxConcatMapNoPrefetch.java:212)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
at reactor.core.publisher.SinkManyEmitterProcessor.drain(SinkManyEmitterProcessor.java:476)
at reactor.core.publisher.SinkManyEmitterProcessor$EmitterInner.drainParent(SinkManyEmitterProcessor.java:620)
at reactor.core.publisher.FluxPublish$PubSubInner.request(FluxPublish.java:874)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
at reactor.core.publisher.FluxConcatMapNoPrefetch$FluxConcatMapNoPrefetchSubscriber.request(FluxConcatMapNoPrefetch.java:337)
at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
at reactor.core.publisher.Operators$DeferredSubscription.request(Operators.java:1742)
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:196)
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:205)
at reactor.netty.http.client.HttpClientConnect$HttpObserver.onUncaughtException(HttpClientConnect.java:417)
at reactor.netty.ReactorNetty$CompositeConnectionObserver.onUncaughtException(ReactorNetty.java:715)
at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onUncaughtException(DefaultPooledConnectionProvider.java:225)
at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onUncaughtException(DefaultPooledConnectionProvider.java:478)
at reactor.netty.http.client.HttpClientOperations.onInboundClose(HttpClientOperations.java:341)
at reactor.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:73)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418)
at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:412)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:377)
at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:410)
at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:412)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:377)
at io.netty.handler.ssl.SslHandler.channelInactive(SslHandler.java:1191)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1352)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:850)
at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:811)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:405)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:840)
Suppressed: java.lang.Exception: #block terminated with an error
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:104)
at reactor.core.publisher.Mono.block(Mono.java:1779)
at c.x.y.p.core.ServerManagerImpl$UpstreamClientImpl.sendRequest(ServerManagerImpl.java:180)
at c.x.y.p.core.ServerManagerImpl.forward(ServerManagerImpl.java:81)
at c.x.y.p.controller.BaseController.process(BaseController.java:45)
at jdk.internal.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:258)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:191)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:986)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:891)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:195)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.security.web.ObservationFilterChainDecorator$AroundFilterObservation$SimpleAroundFilterObservation.lambda$wrap$1(ObservationFilterChainDecorator.java:340)
at org.springframework.security.web.ObservationFilterChainDecorator.lambda$wrapSecured$0(ObservationFilterChainDecorator.java:82)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:128)
at org.springframework.security.web.access.intercept.AuthorizationFilter.doFilter(AuthorizationFilter.java:101)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:126)
at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:120)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:131)
at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:85)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:100)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:179)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:181)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.oauth2.server.resource.web.authentication.BearerTokenAuthenticationFilter.doFilterInternal(BearerTokenAuthenticationFilter.java:128)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.authentication.preauth.AbstractPreAuthenticatedProcessingFilter.doFilter(AbstractPreAuthenticatedProcessingFilter.java:154)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:82)
at org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:69)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:62)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:227)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:240)
at org.springframework.security.web.ObservationFilterChainDecorator$AroundFilterObservation$SimpleAroundFilterObservation.lambda$wrap$0(ObservationFilterChainDecorator.java:323)
at org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:224)
at org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:137)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:233)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:191)
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
at org.springframework.web.servlet.handler.HandlerMappingIntrospector.lambda$createCacheFilter$3(HandlerMappingIntrospector.java:243)
at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74)
at org.springframework.security.config.annotation.web.configuration.WebMvcSecurityConfiguration$CompositeFilterChainProxy.doFilter(WebMvcSecurityConfiguration.java:238)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:362)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:278)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:114)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at jdk.internal.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:359)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:216)
at jdk.proxy2/jdk.proxy2.$Proxy160.doFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:116)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:732)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:398)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:903)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1769)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1189)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:658)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: reactor.netty.http.client.PrematureCloseException: Connection has been closed BEFORE response, while sending request body
Your Environment
Spring boot -> 3.5.6 reactor-netty -> 1.3.0-M7
Any help is highly appreciated. We were trying to narrow down the issue from last 2 weeks but couldn't narrow down with the logs we have.
If you'd like us to spend some time investigating, please take the time to provide a complete, minimal, verifiable sample (something that we can unzip attached to this issue or git clone, build, and deploy) that reproduces the problem.
Hello @violetagg : It is very hard for me to get the sample which can reproduce the issue. Is there anyway, i can narrow down the issue? I'm looking for how to get more information on what's happening under the hood by enabling some specific loggers. Please help us here
Hello @violetagg
Here are the logs for failed & successful request. Could you please guide me how to interpret the logs? We've removed connection pooling as well and creating new HTTP request always to understand the behavior
Failed Request Logs:
- As this request didn't do anything after connected state, server automatically closed after 20 seconds I'm unable to get the logs what happened in the 20 seconds of inactivity. Maybe, this helps in track down the issue
[7a2d8bf5-1, L:/10.100.100.10:33594 ! R:server.xx.com/100.00.000.00:443] The connection observed an error
[7a2d8bf5-1, L:/10.100.100.10:33594 ! R:server.xx.com/100.00.000.00:443] onStateChange([response_incomplete], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x7a2d8bf5, L:/10.100.100.10:33594 ! R:server.xx.com/100.00.000.00:443]}})
[7a2d8bf5, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443] onStateChange([connected], SimpleConnection{channel=[id: 0x7a2d8bf5, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443]})
[7a2d8bf5-1, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443] Handler is being applied: {uri=https://server.xx.com/relativeurl?MessageId=7c1e522f-d2c5-1fd0-aabf-208ca1de8201&QueueId=A9194856BA7F78CC&QualityOfService=ExactlyOnce, method=POST}
[7a2d8bf5-1, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443] onStateChange([configured], GET{uri=/, connection=SimpleConnection{channel=[id: 0x7a2d8bf5, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443]}})
[7a2d8bf5-1, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443] onStateChange([request_prepared], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x7a2d8bf5, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443]}})
[7a2d8bf5, L:/10.100.100.10:33594 - R:server.xx.com/100.00.000.00:443] Connected new channel
[7a2d8bf5] Connecting to [server.xx.com/100.00.000.00:443].
[7a2d8bf5] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[7a2d8bf5] SSL enabled using engine SSLEngine[hostname=server.xx.com, port=443, Session(1760554680743|SSL_NULL_WITH_NULL_NULL)] and SNI server.xx.com/<unresolved>:443
Successful Request Logs:
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Disposing ChannelOperation from a channel
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([response_completed], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([disconnecting], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[0e74d5dd, L:/110.100.100.10:42152 ! R:server.xx.com/100.00.000.00:443] onStateChange([disconnecting], SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 ! R:server.xx.com/100.00.000.00:443]})
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Received last HTTP packet
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Content-Length: <filtered>
Date: <filtered>
Server: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([response_received], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([request_sent], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([connected], SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]})
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Handler is being applied: {uri=https://server.xx.com/relativeurl?MessageId=2ba4b65d-094d-1fd0-aabf-5327dd4a4f75&QueueId=757A70724F897B4F&QualityOfService=ExactlyOnce, method=POST}
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([configured], GET{uri=/, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd-1, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] onStateChange([request_prepared], POST{uri=/relativeurl, connection=SimpleConnection{channel=[id: 0x0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443]}})
[0e74d5dd, L:/110.100.100.10:42152 - R:server.xx.com/100.00.000.00:443] Connected new channel
[0e74d5dd] Connecting to [server.xx.com/100.00.000.00:443].
[0e74d5dd] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[0e74d5dd] SSL enabled using engine SSLEngine[hostname=server.xx.com, port=443, Session(1760555434029|SSL_NULL_WITH_NULL_NULL)] and SNI server.xx.com/<unresolved>:443
I also see following stack trace frequently in my logs. Hope this is not problematic
java.lang.Exception: ChannelOperation terminal stack
at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:501)
at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:821)
at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:115)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1519)
at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1377)
at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1428)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:501)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:399)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:840)
Hello @violetagg : Our system processes around 7 million transactions on a daily basis and one observation is, when two transactions are executed on same thread (thread id is same from both logs) and the second one is getting failed. Is there any way, we can block the thread for one request. Not sure if i'm asking right question
@yssprasad Definitely it seems some blocking issue, will you be able to make a local test with Blockhound enabled? In a thread dump we are interested in Reactor Netty threads and whether they are blocked (typically their name starts with reactor-netty-...)
Added Blockhound and i was able to get following errors but they are happening at different times than the issue timings So, i don't think this is the cause
reactor.blockhound.BlockingOperationError: Blocking call! java.io.RandomAccessFile#readBytes
at java.base/java.io.RandomAccessFile.readBytes(RandomAccessFile.java)
at java.base/java.io.RandomAccessFile.read(RandomAccessFile.java:405)
at java.base/java.io.RandomAccessFile.readFully(RandomAccessFile.java:469)
at java.base/java.util.zip.ZipFile$Source.readFullyAt(ZipFile.java:1516)
at java.base/java.util.zip.ZipFile$ZipFileInputStream.initDataOffset(ZipFile.java:923)
at java.base/java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:939)
at java.base/java.util.zip.ZipFile$ZipFileInflaterInputStream.fill(ZipFile.java:456)
at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:158)
at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:263)
at java.base/java.net.URLConnection.guessContentTypeFromStream(URLConnection.java:1507)
at java.base/sun.net.www.protocol.jar.JarURLConnection.getContentType(JarURLConnection.java:222)
at com.typesafe.config.impl.Parseable$ParseableURL.reader(Parseable.java:536)
at com.typesafe.config.impl.Parseable.rawParseValue(Parseable.java:233)
at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:180)
at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:309)
at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:738)
at com.typesafe.config.impl.Parseable$ParseableResources.rawParseValue(Parseable.java:701)
at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:180)
at com.typesafe.config.impl.Parseable.parseValue(Parseable.java:174)
at com.typesafe.config.impl.Parseable.parse(Parseable.java:301)
at com.typesafe.config.impl.ConfigImpl$2.call(ConfigImpl.java:423)
at com.typesafe.config.impl.ConfigImpl$2.call(ConfigImpl.java:418)
at com.typesafe.config.impl.ConfigImpl$LoaderCache.getOrElseUpdate(ConfigImpl.java:66)
at com.typesafe.config.impl.ConfigImpl.computeCachedConfig(ConfigImpl.java:93)
at com.typesafe.config.impl.ConfigImpl.unresolvedReference(ConfigImpl.java:418)
at com.typesafe.config.impl.ConfigImpl.access$300(ConfigImpl.java:34)
at com.typesafe.config.impl.ConfigImpl$1.call(ConfigImpl.java:411)
at com.typesafe.config.impl.ConfigImpl$1.call(ConfigImpl.java:408)
at com.typesafe.config.impl.ConfigImpl$LoaderCache.getOrElseUpdate(ConfigImpl.java:66)
at com.typesafe.config.impl.ConfigImpl.computeCachedConfig(ConfigImpl.java:93)
at com.typesafe.config.impl.ConfigImpl.defaultReference(ConfigImpl.java:408)
at com.typesafe.config.ConfigFactory.defaultReference(ConfigFactory.java:371)
at com.datastax.oss.driver.internal.core.config.typesafe.DefaultProgrammaticDriverConfigLoaderBuilder.lambda$static$0(DefaultProgrammaticDriverConfigLoaderBuilder.java:46)
at com.datastax.oss.driver.internal.core.config.typesafe.DefaultProgrammaticDriverConfigLoaderBuilder.lambda$build$2(DefaultProgrammaticDriverConfigLoaderBuilder.java:253)
at com.datastax.oss.driver.internal.core.config.typesafe.DefaultDriverConfigLoader$SingleThreaded.reload(DefaultDriverConfigLoader.java:333)
at com.datastax.oss.driver.internal.core.config.typesafe.DefaultDriverConfigLoader$SingleThreaded.reloadInBackground(DefaultDriverConfigLoader.java:360)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:162)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
at io.netty.channel.DefaultEventLoop.run(DefaultEventLoop.java:54)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:840)
and in the thread dump, do you have blocked threads with name reactor-netty-...?
and in the thread dump, do you have blocked threads with name
reactor-netty-...?
No @violetagg . Nothing related to reactor netty
I also see following stack trace frequently in my logs. Hope this is not problematic
java.lang.Exception: ChannelOperation terminal stack at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:501) at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:821) at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:115) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1519) at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1377) at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1428) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:501) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:399) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:840)
@violetagg : I see this error actually on the same thread/connection number. This is with connection pooling enabled. Any pointers to look for?
Hello @violetagg : Adding to above, here is the full log of connection state in the application Lifetime of the connection is 40 seconds Please let me know if you could provide me the pointers where I could check?
From my observation, in the last connection, only headers are sent and not the request body. So, I've implemented Retry mechanism for the exception and it was able to send the request to server without any issues with new connection number
Oct 21, 2025 @ 19:15:25.193 [06dc9cef] Created a new pooled channel, now: 1 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:25.194 [06dc9cef] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:25.194 [06dc9cef] SSL enabled using engine SSLEngine[hostname=server.xx.com, port=443, Session(1761092125193|SSL_NULL_WITH_NULL_NULL)] and SNI server.xx.com/<unresolved>:443
Oct 21, 2025 @ 19:15:25.203 [06dc9cef] Connecting to [server.xx.com/IP2:443].
Oct 21, 2025 @ 19:15:25.246 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel connected, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:25.246 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Registering pool release on close event for channel
Oct 21, 2025 @ 19:15:25.297 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:25.297 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL1?MessageId=3755a692-491f-1fd0-abdb-86869be2c3ed&QueueId=9A016B84252B384A&QualityOfService=ExactlyOnce, method=POST}
Oct 21, 2025 @ 19:15:25.297 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [configured])
Oct 21, 2025 @ 19:15:25.297 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:25.297 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}, [connected])
Oct 21, 2025 @ 19:15:25.297 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:25.446 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Content-Length: <filtered>
Date: <filtered>
Server: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:25.446 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:25.446 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:25.446 [06dc9cef-1, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:25.446 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:26.210 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:26.210 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:26.210 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL2, method=POST}
Oct 21, 2025 @ 19:15:27.029 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:27.030 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:27.102 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Content-Length: <filtered>
Date: <filtered>
Server: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:27.102 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:27.102 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:27.102 [06dc9cef-2, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:27.102 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:30.285 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:30.286 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL3, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:30.286 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:30.286 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL3?MessageId=06c73b0c-b9af-1fd0-abdb-86f8ecc12eca&QueueId=1043EB5A17C2655B&QualityOfService=ExactlyOnce, method=POST}
Oct 21, 2025 @ 19:15:30.286 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL3, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:30.427 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL3, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:30.427 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:30.427 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:30.427 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:30.427 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:30.427 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL3, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:30.427 [06dc9cef-3, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:30.428 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL3, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:30.428 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:30.428 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:36.287 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:36.287 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:36.287 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL2?MessageId=097fc973-4910-1fe0-abdb-8758dfb01a79&QueueId=29C27132045EE500&QualityOfService=ExactlyOnce, method=POST}
Oct 21, 2025 @ 19:15:36.288 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:36.288 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:36.437 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:36.437 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:36.437 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:36.437 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Content-Length: <filtered>
Date: <filtered>
Server: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:36.437 [06dc9cef-4, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:36.438 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:36.438 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:36.438 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:36.438 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:36.438 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:38.200 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:38.201 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL2?MessageId=097fc973-4910-1fe0-abdb-8792b21b3a83&QueueId=FD1F584C027F41C4&QualityOfService=ExactlyOnce, method=POST}
Oct 21, 2025 @ 19:15:38.201 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:38.201 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:38.201 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:38.343 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Content-Length: <filtered>
Date: <filtered>
Server: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:38.343 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:38.343 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:38.343 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:38.343 [06dc9cef-5, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:38.344 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:38.344 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:38.344 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:38.344 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:38.344 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:43.474 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 2 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:43.474 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:43.474 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL4, method=POST}
Oct 21, 2025 @ 19:15:43.475 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 21, 2025 @ 19:15:43.475 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 21, 2025 @ 19:15:43.619 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 21, 2025 @ 19:15:43.619 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Set-Cookie: <filtered>
Strict-Transport-Security: <filtered>
Oct 21, 2025 @ 19:15:43.620 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel cleaned, now: 1 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:43.620 [06dc9cef-6, L:/IP1:32838 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
Oct 21, 2025 @ 19:15:43.620 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Releasing channel
Oct 21, 2025 @ 19:15:45.027 [06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443] Channel acquired, now: 1 active connections, 0 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:15:45.027 [06dc9cef-7, L:/IP1:32838 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 21, 2025 @ 19:15:45.027 [06dc9cef-7, L:/IP1:32838 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL4, method=POST}
Oct 21, 2025 @ 19:16:05.140 [06dc9cef-7, L:/IP1:32838 ! R:server.xx.com/IP2:443] Channel closed, now: 0 active connections, 1 inactive connections 0 pending acquire requests.
Oct 21, 2025 @ 19:16:05.141 [06dc9cef-7, L:/IP1:32838 ! R:server.xx.com/IP2:443] The connection observed an error
Oct 21, 2025 @ 19:16:05.141 [06dc9cef-7, L:/IP1:32838 ! R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL4, connection=PooledConnection{channel=[id: 0x06dc9cef, L:/IP1:32838 ! R:server.xx.com/IP2:443]}}, [response_incomplete])
I also see following stack trace frequently in my logs. Hope this is not problematic
java.lang.Exception: ChannelOperation terminal stack at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:501) at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:821) at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:115) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1519) at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1377) at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1428) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:530) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:469) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1357) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:868) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:501) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:399) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:998) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:840)@violetagg : I see this error actually on the same thread/connection number. This is with connection pooling enabled. Any pointers to look for?
This is just a trace at the end of the request/response, no issues with this one
This looks similar to https://github.com/reactor/reactor-netty/issues/3889, but there we can see the event loop blocked by Spring Framework while here you say that there is nothing in the thread dump. Can you enable the wiretap like this:
.wiretap("reactor.netty", LogLevel.DEBUG, AdvancedByteBufFormat.SIMPLE) so that we can see whether we started to send the body.
Hello @violetagg : Here is the log with .wiretap("reactor.netty", LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL)
As I mentioned earlier, Request headers were sent but the body was not sent for the failed requests.
Following log contains two requests on the same connection from the pool (I've removed the headers & body for compliance purposes and not to expose the data. Also modified server name, urls and IP addresses).
2b7aefd3-6 --> Successful request/response
2b7aefd3-7 --> Failed request
Oct 22, 2025 @ 11:15:21.065 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 22, 2025 @ 11:15:21.065 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Channel cleaned, now: 0 active connections, 1 inactive connections 0 pending acquire requests.
Oct 22, 2025 @ 11:15:23.344 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL1, method=POST}
Oct 22, 2025 @ 11:15:23.344 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Channel acquired, now: 1 active connections, 0 inactive connections 0 pending acquire requests.
Oct 22, 2025 @ 11:15:23.344 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 22, 2025 @ 11:15:23.344 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:23.344 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 4634B POST /URL1 HTTP/1.1
host: server.xx.com
accept: */*
----All Request headers are sent. Removed for compliance purposes
Content-Type: text/xml;charset=UTF-8
Oct 22, 2025 @ 11:15:23.345 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 2B
Oct 22, 2025 @ 11:15:23.345 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 5B ff9
Oct 22, 2025 @ 11:15:23.345 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 4089B ----Body Part1. Removed for compliance purposes
Oct 22, 2025 @ 11:15:23.345 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:23.533 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 2B
Oct 22, 2025 @ 11:15:23.533 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 1466B ----Body Part2. Removed for compliance purposes
Oct 22, 2025 @ 11:15:23.533 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:23.533 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 5B 5ba
Oct 22, 2025 @ 11:15:23.534 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:23.534 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] Added encoder [reactor.left.responseTimeoutHandler] at the beginning of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.loggingHandler, reactor.left.httpCodec, reactor.left.responseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
Oct 22, 2025 @ 11:15:23.534 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 5B 0
Oct 22, 2025 @ 11:15:23.534 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [request_sent])
Oct 22, 2025 @ 11:15:23.606 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [response_received])
Oct 22, 2025 @ 11:15:23.606 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 202
----All Response headers. Removed for compliance purposes
Strict-Transport-Security: <filtered>
Oct 22, 2025 @ 11:15:23.606 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] READ: 636B HTTP/1.1 202
----All Response headers. Removed for compliance purposes
Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] Received last HTTP packet
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [response_completed])
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL1, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [disconnecting])
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Disposing ChannelOperation from a channel
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Releasing channel
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] READ COMPLETE
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Channel cleaned, now: 0 active connections, 1 inactive connections 0 pending acquire requests.
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3-6, L:/IP1:51638 - R:server.xx.com/IP2:443] [terminated=false, cancelled=false, pending=0, error=null]: subscribing inbound receiver
Oct 22, 2025 @ 11:15:23.607 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Removed handler: reactor.left.responseTimeoutHandler, 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)}
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443] Channel acquired, now: 1 active connections, 0 inactive connections 0 pending acquire requests.
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] Handler is being applied: {uri=https://server.xx.com/URL2?MessageId=1179e9f6-1ab6-1fd0-abec-49fc12ba7152&QueueId=8F85F66886C97D63&QualityOfService=ExactlyOnce, method=POST}
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 3505B POST /URL2?MessageId=1179e9f6-1ab6-1fd0-abec-49fc12ba7152&QueueId=8F85F66886C97D63&QualityOfService=ExactlyOnce HTTP/1.1
host: server.xx.com
accept: */*
transfer-encoding: chunked
----All Request headers are sent. Removed for compliance purposes
Content-Type: text/xml;charset=utf-8
Oct 22, 2025 @ 11:15:24.279 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:44.333 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] READ COMPLETE
Oct 22, 2025 @ 11:15:44.334 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] Channel closed, now: 0 active connections, 1 inactive connections 0 pending acquire requests.
Oct 22, 2025 @ 11:15:44.334 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] INACTIVE
Oct 22, 2025 @ 11:15:44.334 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
Oct 22, 2025 @ 11:15:44.335 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] The connection observed an error
Oct 22, 2025 @ 11:15:44.335 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 ! R:server.xx.com/IP2:443]}}, [response_incomplete])
Oct 22, 2025 @ 11:15:44.338 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] UNREGISTERED
@yssprasad Is it possible to take a tcpdump?
Hello, I was doing the analysis together with @yssprasad. The tcpdump for the outgoing traffic is not really helpful as we don't see the contents due to the SSL encryption. We did make a capture for the incoming request. The incoming request came in full and at the same time (both headers and body).
@YurZir Please can you elaborate, which incoming request was received in full. See the log below
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] onStateChange(POST{uri=/URL2, connection=PooledConnection{channel=[id: 0x2b7aefd3, L:/IP1:51638 - R:server.xx.com/IP2:443]}}, [request_prepared])
Oct 22, 2025 @ 11:15:24.278 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] WRITE: 3505B POST /URL2?MessageId=1179e9f6-1ab6-1fd0-abec-49fc12ba7152&QueueId=8F85F66886C97D63&QualityOfService=ExactlyOnce HTTP/1.1
host: server.xx.com
accept: */*
transfer-encoding: chunked
----All Request headers are sent. Removed for compliance purposes
Content-Type: text/xml;charset=utf-8
Oct 22, 2025 @ 11:15:24.279 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] FLUSH
Oct 22, 2025 @ 11:15:44.333 [2b7aefd3-7, L:/IP1:51638 - R:server.xx.com/IP2:443] READ COMPLETE
Oct 22, 2025 @ 11:15:44.334 [2b7aefd3-7, L:/IP1:51638 ! R:server.xx.com/IP2:443] Channel closed, now: 0 active connections, 1 inactive connections 0 pending acquire requests.
Hello @violetagg : Could you please let me know how to make sure that, reactor netty also logs all the logs with same correlation id of our application. We are using MDC and setting correlation id but the logs which are written from reactors library is logged with some other id. This is becoming very difficult to analyze the issue. Is there any way, we can set the same correlation id to the connection or any other way?
@yssprasad By default there is no MDC in the Reactor Netty logs. You can enable this following the suggestions in this comment https://github.com/reactor/reactor-netty/issues/3919#issuecomment-3302788760
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
Hello @violetagg,
Am working with Siva on this issue. As discussed earlier, we got the TCP dump and attaching the compressed TCP dump here. Please review and let us know.
ConnectionIssueTCPDump.pcap.zip
Thanks Alekhya
@alekhyaravilla Can you please specify the ports of the Spring Cloud Gateway http client and the target service? The exception is Connection has been closed BEFORE response, while sending request body which means that something happens with the connection between Spring Cloud Gateway http client and the target service. So I need information for the connection 2 from the flow below:
client -> Spring Cloud Gateway -> target service
connection 1 connection 2
- client is connecting to default https port (8443)
- our application (spring cloud gateway) is also connecting to target server's default https port (8443)
Please let me know if you require any further information
@yssprasad the provided tcp dump contains information only for connection 1 and not connection 2 that I need
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
We are actively working on getting the tcp dump. We are dependent on another team to give us the requested information, hence it is taking time.Also this time around being the Thanksgiving break, it is taking even longer.
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
We shall soon share the requested information. This being holiday season, it is taking even longer.
The team confirmed that they will provide TCP Dump early next week. We should be able to share the TCP Dump by end of next week. Thanks!!