Details
-
Bug
-
Status: Resolved
-
Minor
-
Resolution: Fixed
-
3.14.2, 3.16.0
-
None
Description
The Camel Netty component (NettyProducer) is wrongly closing TCP/IP client channels when the requestTimeout option is configured.
See logs:
2022-04-21 15:21:46.410 INFO 18420 --- [ main] o.a.c.component.netty.NettyComponent : Creating shared NettyConsumerExecutorGroup with 17 threads 2022-04-21 15:21:46.683 DEBUG 18420 --- [ main] o.a.camel.component.netty.NettyProducer : Created NettyProducer pool[maxTotal=1, minIdle=100, maxIdle=100, minEvictableIdleDuration=PT-0.001S] -> GenericObjectPool [maxTotal=1, blockWhenExhausted=true, maxWaitDuration=PT-0.001S, lifo=true, fairness=false, testOnCreate=false, testOnBorrow=true, testOnReturn=false, testWhileIdle=true, durationBetweenEvictionRuns=PT30S, numTestsPerEvictionRun=3, minEvictableIdleTimeDuration=PT-0.001S, softMinEvictableIdleTimeDuration=PT-0.001S, evictionPolicy=org.apache.commons.pool2.impl.DefaultEvictionPolicy@580d3612, closeLock=java.lang.Object@5b0039aa, closed=false, evictionLock=java.lang.Object@52bf5065, evictor=org.apache.commons.pool2.impl.BaseGenericObjectPool$Evictor@263cece5, evictionIterator=null, factoryClassLoader=java.lang.ref.WeakReference@1730f396, oname=org.apache.commons.pool2:type=GenericObjectPool,name=pool, creationStackTrace=java.lang.Exception [...] , borrowedCount=0, returnedCount=0, createdCount=0, destroyedCount=0, destroyedByEvictorCount=0, destroyedByBorrowValidationCount=0, activeTimes=StatsStore [[]], size=100, index=0], idleTimes=StatsStore [[]], size=100, index=0], waitTimes=StatsStore [[]], size=100, index=0], maxBorrowWaitDuration=PT0S, swallowedExceptionListener=null, factoryType=null, maxIdle=100, minIdle=0, factory=org.apache.camel.component.netty.NettyProducer$NettyProducerPoolableObjectFactory@4d2745b3, allObjects={}, createCount=0, idleObjects=[], abandonedConfig=null] 2022-04-21 15:51:11.502 TRACE 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : Pool[active=0, idle=0] 2022-04-21 15:51:11.504 DEBUG 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : Created new TCP client bootstrap connecting to localhost:19001 with options: Bootstrap(BootstrapConfig(group: NioEventLoopGroup, channelFactory: ReflectiveChannelFactory(NioSocketChannel.class), options: {SO_KEEPALIVE=true, SO_REUSEADDR=true, TCP_NODELAY=true, CONNECT_TIMEOUT_MILLIS=2000}, handler: org.apache.camel.component.netty.DefaultClientInitializerFactory@624ce9ff, resolver: io.netty.resolver.DefaultAddressResolverGroup@6e4616a3)) 2022-04-21 15:51:11.505 TRACE 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : Requested channel: AbstractBootstrap$PendingRegistrationPromise@270856c0(incomplete) 2022-04-21 15:51:11.505 TRACE 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : activateObject channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(incomplete) 2022-04-21 15:51:11.505 TRACE 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : Validating connecting channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(incomplete) -> true 2022-04-21 15:51:11.505 TRACE 18420 --- [roducerTemplate] o.a.camel.component.netty.NettyProducer : Got channel request from pool AbstractBootstrap$PendingRegistrationPromise@270856c0(incomplete) 2022-04-21 15:51:11.509 DEBUG 18420 --- [ClientTCPWorker] .a.c.c.n.DefaultClientInitializerFactory : Client SSL handler configured and added to the ChannelPipeline: io.netty.handler.ssl.SslHandler@735dd507 2022-04-21 15:51:11.509 TRACE 18420 --- [ClientTCPWorker] .a.c.c.n.DefaultClientInitializerFactory : Using request timeout 5000 millis 2022-04-21 15:51:11.509 TRACE 18420 --- [ClientTCPWorker] .a.c.c.n.DefaultClientInitializerFactory : Created ChannelPipeline: DefaultChannelPipeline{(DefaultClientInitializerFactory#0 = org.apache.camel.component.netty.DefaultClientInitializerFactory), (ssl = io.netty.handler.ssl.SslHandler), (decoder-0 = io.netty.handler.codec.LengthFieldBasedFrameDecoder), (decoder-1 = util.SharableByteArrayDecoder), (encoder-0 = io.netty.handler.codec.LengthFieldPrepender), (encoder-1 = io.netty.handler.codec.bytes.ByteArrayEncoder), (timeout = io.netty.handler.timeout.ReadTimeoutHandler), (handler = org.apache.camel.component.netty.handlers.ClientChannelHandler)} 2022-04-21 15:51:11.511 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Channel open finished with AbstractBootstrap$PendingRegistrationPromise@270856c0(success) 2022-04-21 15:51:11.511 DEBUG 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Creating connector to address: localhost:19001 2022-04-21 15:51:11.511 DEBUG 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Channel: [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] writing body: OMITTED 2022-04-21 15:51:11.517 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Channel open: [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] 2022-04-21 15:51:11.637 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Operation complete DefaultChannelPromise@1835894c(success) 2022-04-21 15:51:11.642 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Message received: OMITTED 2022-04-21 15:51:11.642 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Removing timeout channel as we received message 2022-04-21 15:51:11.642 DEBUG 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Channel: [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] received body: OMITTED 2022-04-21 15:51:11.643 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Putting channel back to pool [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] 2022-04-21 15:51:11.643 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : passivateObject channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(success) 2022-04-21 15:51:11.645 DEBUG 18420 --- [nio-8087-exec-5] eHttpServletFilter$AsyncExceptionHandler : handling on complete for async event 2022-04-21 15:51:16.770 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : activateObject channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(success) 2022-04-21 15:51:16.771 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : reset the request timeout as we activate the channel 2022-04-21 15:51:16.771 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : Validating channel: [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] -> true 2022-04-21 15:51:16.771 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : passivateObject channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(success) 2022-04-21 15:51:21.771 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Exception caught at Channel: [id: 0x80278f7c, L:/127.0.0.1:61770 - R:localhost/127.0.0.1:19001] io.netty.handler.timeout.ReadTimeoutException: null 2022-04-21 15:51:21.772 DEBUG 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Closing channel as an exception was thrown from Netty io.netty.handler.timeout.ReadTimeoutException: null 2022-04-21 15:51:21.772 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyHelper : Channel closed: [id: 0x80278f7c, L:/127.0.0.1:61770 ! R:localhost/127.0.0.1:19001] 2022-04-21 15:51:21.773 TRACE 18420 --- [ClientTCPWorker] o.a.camel.component.netty.NettyProducer : Channel closed: [id: 0x80278f7c, L:/127.0.0.1:61770 ! R:localhost/127.0.0.1:19001] 2022-04-21 15:51:46.773 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : activateObject channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(success) 2022-04-21 15:51:46.773 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : reset the request timeout as we activate the channel 2022-04-21 15:51:46.773 TRACE 18420 --- [ns-pool-evictor] o.a.camel.component.netty.NettyProducer : Destroying channel request: AbstractBootstrap$PendingRegistrationPromise@270856c0(success)
The offending code seems to be: https://github.com/apache/camel/blob/main/components/camel-netty/src/main/java/org/apache/camel/component/netty/NettyProducer.java
@Override public void activateObject(PooledObject<ChannelFuture> p) throws Exception { ChannelFuture channelFuture = p.getObject(); LOG.trace("activateObject channel request: {}", channelFuture); if (channelFuture.isSuccess() && producer.getConfiguration().getRequestTimeout() > 0) { LOG.trace("reset the request timeout as we activate the channel"); Channel channel = channelFuture.channel(); ChannelHandler handler = channel.pipeline().get("timeout"); if (handler == null) { ChannelHandler timeout = new ReadTimeoutHandler(producer.getConfiguration().getRequestTimeout(), TimeUnit.MILLISECONDS); channel.pipeline().addBefore("handler", "timeout", timeout); } } }