[ 
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:     (was: 2.18.0)
                   2.19.0
                   2.18.1

> 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.19.0, 2.18.1
>
>
> 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)

Reply via email to