You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@camel.apache.org by "Claus Ibsen (Jira)" <ji...@apache.org> on 2022/05/10 05:31:00 UTC
[jira] [Updated] (CAMEL-18027) camel-netty (producer) wrongly closes client channels
[ https://issues.apache.org/jira/browse/CAMEL-18027?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Claus Ibsen updated CAMEL-18027:
--------------------------------
Fix Version/s: 3.18.0
(was: 3.17.0)
> camel-netty (producer) wrongly closes client channels
> -----------------------------------------------------
>
> Key: CAMEL-18027
> URL: https://issues.apache.org/jira/browse/CAMEL-18027
> Project: Camel
> Issue Type: Bug
> Components: camel-netty
> Affects Versions: 3.14.2, 3.16.0
> Reporter: Vincenzo Galluccio
> Priority: Minor
> Fix For: 3.14.4, 3.18.0
>
>
> The Camel Netty component (NettyProducer) is wrongly closing TCP/IP client channels when the {{requestTimeout}} option is configured.
> See logs:
>
> {code:java}
> 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)
> {code}
>
> 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]
>
> {code: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);
> }
> }
> }
> {code}
>
--
This message was sent by Atlassian Jira
(v8.20.7#820007)