[
https://issues.apache.org/jira/browse/CAMEL-18027?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Claus Ibsen resolved CAMEL-18027.
---------------------------------
Resolution: Fixed
> 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
> Assignee: Claus Ibsen
> 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)
