Bug 1322679

Summary: NullPointerException from HotRodDecoder when topology changed
Product: [JBoss] JBoss Data Grid 6 Reporter: Osamu Nagano <onagano>
Component: ServerAssignee: Tristan Tarrant <ttarrant>
Status: VERIFIED --- QA Contact: Martin Gencur <mgencur>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.6.0CC: jdg-bugs, mmiura, ttarrant, wfink
Target Milestone: ER1   
Target Release: 6.6.1   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On:    
Bug Blocks: 1309749, 1328307    

Description Osamu Nagano 2016-03-31 06:00:13 UTC
Description of problem:
When a topology change happened, NullPointerException is thrown from Hot Rod server.  Here is an example from attached server.log.

~~~
15:17:34,078 TRACE [org.infinispan.server.hotrod.HotRodDecoder] (HotRodServerWorker-2) Channel [id: 0x30cb8cd7, /192.168.1.1:27124 => /192.168.1.2:9920] became active
15:17:34,082 DEBUG [org.infinispan.server.hotrod.CacheDecodeContext] (HotRodServerWorker-2) Exception caught: java.lang.NullPointerException
        at org.infinispan.server.hotrod.HotRodDecoder.channelActive(HotRodDecoder.scala:279) [infinispan-server-hotrod-6.4.0.Final-redhat-4.jar:6.4.0.Final-redhat-4]
        at io.netty.channel.DefaultChannelHandlerContext.invokeChannelActive(DefaultChannelHandlerContext.java:216) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.DefaultChannelHandlerContext.fireChannelActive(DefaultChannelHandlerContext.java:202) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:756) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:445) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.access$100(AbstractChannel.java:375) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:419) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:370) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:353) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_45]
15:17:34,083 ERROR [org.infinispan.server.hotrod.CacheDecodeContext] (HotRodServerWorker-2) ISPN005009: Unexpected error before any request parameters read: java.lang.NullPointerException
        at org.infinispan.server.hotrod.HotRodDecoder.channelActive(HotRodDecoder.scala:279) [infinispan-server-hotrod-6.4.0.Final-redhat-4.jar:6.4.0.Final-redhat-4]
        at io.netty.channel.DefaultChannelHandlerContext.invokeChannelActive(DefaultChannelHandlerContext.java:216) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.DefaultChannelHandlerContext.fireChannelActive(DefaultChannelHandlerContext.java:202) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.DefaultChannelPipeline.fireChannelActive(DefaultChannelPipeline.java:756) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:445) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.access$100(AbstractChannel.java:375) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:419) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:370) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:353) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116) [netty-all-4.0.18.Final-redhat-1.jar:4.0.18.Final-redhat-1]
        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_45]
~~~

The connecting client receives HotRodClientException and InvalidResponseExceptions when it executes a get operation.  No stack trace is available.

  org.infinispan.client.hotrod.exceptions.HotRodClientException (wrapping java.lang.NullPointerException)
  org.infinispan.client.hotrod.exceptions.InvalidResponseException: Invalid message id. Expected 307707 and received 307540
  org.infinispan.client.hotrod.exceptions.InvalidResponseException: Invalid magic number. Expected 0xa1 and received 0x1c


Version-Release number of selected component (if applicable):
JDG 6.6.0 server and Java client.


How reproducible:
Highly reproducible in the customer's environment, especially when a new node joined.

Comment 3 Dan Berindei 2016-04-05 10:38:12 UTC
I didn't realize it could cause exceptions on the client as well, but I fixed the NullPointerException with ISPN-6442.