[CAMEL-10301] NullPointerException in Netty4 component's ClientChannelHandler causes async processor to wait forever - ASF JIRA

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Later
Affects Version/s: 2.17.2
Fix Version/s: Future
Component/s: camel-netty4
Labels:
None

Estimated Complexity:
Advanced

Description

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.

boolean doneUoW = exchange.getUnitOfWork() == null;

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

putState(channel, new NettyCamelState(producerCallback, exchange));

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.

if (!channelFuture.isSuccess()) {
                    // no success then exit, (any exception has been handled by ClientChannelHandler#exceptionCaught)
                    return;
                }

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:

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)

NullPointerException in Netty4 component's ClientChannelHandler causes async processor to wait forever

Details

Description

Attachments

Activity

People

Dates