[ https://issues.apache.org/jira/browse/CAMEL-10301?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Claus Ibsen updated CAMEL-10301: -------------------------------- Fix Version/s: 2.18.0 > NullPointerException in Netty4 component's ClientChannelHandler causes async > processor to wait forever > ------------------------------------------------------------------------------------------------------ > > Key: CAMEL-10301 > URL: https://issues.apache.org/jira/browse/CAMEL-10301 > Project: Camel > Issue Type: Bug > Components: camel-netty4 > Affects Versions: 2.17.2 > Reporter: Alex Cheng > Fix For: 2.18.0 > > > When sending messages using camel netty4 component, in a rare case, a > NullPointerException thrown in {{ClientChannelHandler}} caused > {{org.apache.camel.impl.DefaultAsyncProcessorAwaitManager}} to wait forever. > From the stacktrace, the NPE occurred in line 116 of {{channelInactive}} > method and the {{exchange}} is null. > {code} > boolean doneUoW = exchange.getUnitOfWork() == null; > {code} > From {{getExchange}} method, it looks like it cannot get {{NettyCamelState}} > from {{NettyProducer}}. In {{NettyProducer}}'s {{process}} method, it's > possible that a Netty channel is closed before line > {code} > putState(channel, new NettyCamelState(producerCallback, exchange)); > {code} > is executed, which triggers {{channelInactive}} and causes the NPE. > So the flow looks like below: > 1) Netty channel opened in {{NettyProducer}} > 2) Before {{putState}} is invoked, the channel is closed > 3) {{channelInactive}} method in {{ClientChannelHandler}} is called and > throws NPE, the worker thread dies > 4) {{NettyProducer}} not mark the async processor as done > In line 303 of {{NettyProducer}}, it simply returns if the channel future is > not success, but the {{ClientChannelHandler#exceptionCaught}} won't do any > thing if {{exchange}} is null and will never run again as the worker thread > already died. > {code} > if (!channelFuture.isSuccess()) { > // no success then exit, (any exception has been handled > by ClientChannelHandler#exceptionCaught) > return; > } > {code} > The potential fix would be: > 1) Add null check in {{ClientChannelHandler}}'s {{channelInactive}} method > 2) Call {{producerCallback.done(false)}} in {{NettyProducer}}'s {{process}} > method when channel future is not success. This should be safe as > {{AsyncCallback}}'s {{done}} method can be called multiple times. > Note, 2.18.0 version changed some implementation details of {{NettyProducer}} > but still has the same issue. > Stacktrace: > {code} > 2016-09-08 00:26:11,843 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Pool[active=0, idle=0] > 2016-09-08 00:26:11,843 | DEBUG [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Created new TCP client > bootstrap connecting to 172.25.0.100:15050 with options: > Bootstrap(BootstrapConfig(group: NioEventLoopGroup, channelFactory: > NioSocketChannel.class, options: {SO_KEEPALIVE=true, TCP_NODELAY=true, > SO_REUSEADDR=true, CONNECT_TIMEOUT_MILLIS=10000}, handler: > org.apache.camel.component.netty4.DefaultClientInitializerFactory@297c237, > resolver: io.netty.resolver.DefaultAddressResolverGroup@6eb474f1)) > 2016-09-08 00:26:11,843 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Waiting for operation to > complete AbstractBootstrap$PendingRegistrationPromise@637319e7(incomplete) > for 10000 millis > 2016-09-08 00:26:11,844 | TRACE [NettyClientTCPWorker] > o.a.c.c.netty4.DefaultClientInitializerFactory : Using request timeout 5000 > millis > 2016-09-08 00:26:11,844 | TRACE [NettyClientTCPWorker] > o.a.c.c.netty4.DefaultClientInitializerFactory : Created ChannelPipeline: > DefaultChannelPipeline{(DefaultClientInitializerFactory#0 = > org.apache.camel.component.netty4.DefaultClientInitializerFactory), > (decoder-0 = xxx), (encoder-0 = > org.apache.camel.component.hl7.HL7MLLPNettyEncoder), (timeout = > io.netty.handler.timeout.ReadTimeoutHandler), (handler = > org.apache.camel.component.netty4.handlers.ClientChannelHandler)} > 2016-09-08 00:26:11,845 | DEBUG [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Creating connector to > address: 172.25.0.100:15050 > 2016-09-08 00:26:11,845 | TRACE [NettyClientTCPWorker] > org.apache.camel.component.netty4.NettyProducer : Channel open: [id: > 0x40064baa, L:/172.25.0.103:55662 - R:/172.25.0.100:15050] > 2016-09-08 00:26:11,845 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Created channel: [id: > 0x40064baa, L:/172.25.0.103:55662 - R:/172.25.0.100:15050] > 2016-09-08 00:26:11,845 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : activateObject channel: > [id: 0x40064baa, L:/172.25.0.103:55662 - R:/172.25.0.100:15050] -> {} > 2016-09-08 00:26:11,845 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Validating channel: [id: > 0x40064baa, L:/172.25.0.103:55662 - R:/172.25.0.100:15050] -> true > 2016-09-08 00:26:11,845 | TRACE [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Got channel from pool [id: > 0x40064baa, L:/172.25.0.103:55662 ! R:/172.25.0.100:15050] > 2016-09-08 00:26:11,847 | TRACE [NettyClientTCPWorker] > org.apache.camel.component.netty4.NettyProducer : Channel closed: [id: > 0x40064baa, L:/172.25.0.103:55662 ! R:/172.25.0.100:15050] > 2016-09-08 00:26:11,848 | TRACE [NettyClientTCPWorker] > org.apache.camel.component.netty4.NettyProducer : Exception caught at > Channel: [id: 0x40064baa, L:/172.25.0.103:55662 ! R:/172.25.0.100:15050] > java.lang.NullPointerException: null > at > org.apache.camel.component.netty4.handlers.ClientChannelHandler.channelInactive(ClientChannelHandler.java:116) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75) > at > io.netty.handler.timeout.ReadTimeoutHandler.channelInactive(ReadTimeoutHandler.java:146) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:360) > at > io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:325) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1314) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:886) > at > io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:735) > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:400) > at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:401) > at > io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:805) > at java.lang.Thread.run(Thread.java:745) > 2016-09-08 00:26:11,848 | DEBUG [NettyClientTCPWorker] > org.apache.camel.component.netty4.NettyProducer : Closing channel as an > exception was thrown from Netty > java.lang.NullPointerException: null > at > org.apache.camel.component.netty4.handlers.ClientChannelHandler.channelInactive(ClientChannelHandler.java:116) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75) > at > io.netty.handler.timeout.ReadTimeoutHandler.channelInactive(ReadTimeoutHandler.java:146) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:360) > at > io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:325) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:216) > at > io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1314) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:237) > at > io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:223) > at > io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:886) > at > io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:735) > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:400) > at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:401) > at > io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:805) > at java.lang.Thread.run(Thread.java:745) > 2016-09-08 00:26:11,850 | DEBUG [-threads-1855599236)] > org.apache.camel.component.netty4.NettyProducer : Channel: [id: 0x40064baa, > L:/172.25.0.103:55662 ! R:/172.25.0.100:15050] writing body: [77, ..., 13] > 2016-09-08 00:26:11,850 | TRACE [-threads-1855599236)] > o.a.camel.impl.DefaultAsyncProcessorAwaitManager : Waiting for asynchronous > callback before continuing for exchangeId: > ID-5533912dbb9f-37752-1473294183111-0-2373 -> > Exchange[ID-5533912dbb9f-37752-1473294183111-0-2373] > 2016-09-08 00:26:11,850 | TRACE [NettyClientTCPWorker] > org.apache.camel.component.netty4.NettyProducer : Operation complete > DefaultChannelPromise@7395de5d(failure: > java.nio.channels.ClosedChannelException) > {code} -- This message was sent by Atlassian JIRA (v6.3.4#6332)