camel-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Alex Cheng (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CAMEL-10301) NullPointerException in Netty4 component's ClientChannelHandler causes async processor to hang
Date Thu, 08 Sep 2016 21:20:20 GMT
Alex Cheng created CAMEL-10301:
----------------------------------

             Summary: NullPointerException in Netty4 component's ClientChannelHandler causes
async processor to hang
                 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


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)

Mime
View raw message