Vincenzo Galluccio created CAMEL-18027:
------------------------------------------
Summary: camel-netty -
Key: CAMEL-18027
URL: https://issues.apache.org/jira/browse/CAMEL-18027
Project: Camel
Issue Type: Bug
Components: camel-netty
Affects Versions: 3.16.0, 3.14.2
Reporter: Vincenzo Galluccio
Fix For: 3.14.3, 3.17.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)
