[
https://issues.apache.org/jira/browse/GEODE-1583?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15348862#comment-15348862
]
Dan Smith commented on GEODE-1583:
----------------------------------
Looking at the stack, and the logs for this issue, it looks like maybe the
client is disconnecting by sending the wrong flag or something. The test closes
the cache on the client with keepAlive=false, which is supposed to cause the
server to clean up the clients queue. However, the test fails because there is
still a CacheClientProxy present on the server.
In the logs, we can see that the client health monitor stops watching this
client, but the CacheClientProxy remains. It even logs a message saying
"Keeping proxy for durable client named test39630_client for 60 seconds" which
makes me think it got a close connection request from the client, but decided
to keep the proxy anyway.
{noformat}
[vm_0][info 2016/06/24 08:52:23.867 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] Before CCP states:
[CacheClientProxy[identity(cc2-rh6(28071:loner):51817:28b21c83,connection=1,durableAttributes=DurableClientAttributes[id=test39630_client;
timeout=60]); port=51819; primary=true; version=GFE 9.0; paused=true;
alive=false; connected=true; isMarkedForRemoval=false] ]
[vm_0][info 2016/06/24 08:52:23.867 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] Before CHM states: size = 1 {cc2-rh6(28071:loner):51817:28b21c83,
{[host name=/10.118.33.92 host ip=10.118.33.92 client port=51817 client member
id=cc2-rh6(28071:loner):51817:28b21c83, 2]}}
[vm_0][info 2016/06/24 08:52:23.867 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] Got result: null
[vm_0] from
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$5.run
with 0 args on object: "Loggiog CCCP and ServerConnetcion state" (took 0 ms)
[vm_2][info 2016/06/24 08:52:23.868 PDT <RMI TCP Connection(22)-10.118.33.92>
tid=0x8e7] Received method:
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$$Lambda$70/529615275.run
with 0 args on object:
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$$Lambda$70/529615275@2e083615
[vm_2][info 2016/06/24 08:52:23.868 PDT <RMI TCP Connection(22)-10.118.33.92>
tid=0x8e7] GemFireCache[id = 800029409; isClosing = true; isShutDownAll =
false; created = Fri Jun 24 08:52:23 PDT 2016; server = false; copyOnRead =
false; lockLease = 120; lockTimeout = 60]: Now closing.
[vm_2][info 2016/06/24 08:52:23.869 PDT <RMI TCP Connection(22)-10.118.33.92>
tid=0x8e7] Destroying connection pool CacheServerTestUtil
[vm_0][info 2016/06/24 08:52:23.873 PDT <ServerConnection on port 22853 Thread
0> tid=0x1dcb] CacheClientNotifier: Keeping proxy for durable client named
test39630_client for 60 seconds
CacheClientProxy[identity(cc2-rh6(28071:loner):51817:28b21c83,connection=1,durableAttributes=DurableClientAttributes[id=test39630_client;
timeout=60]); port=51819; primary=true; version=GFE 9.0].
[vm_2][info 2016/06/24 08:52:23.876 PDT <RMI TCP Connection(22)-10.118.33.92>
tid=0x8e7] Got result: null
[vm_2] from
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$$Lambda$70/529615275.run
with 0 args on object:
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$$Lambda$70/529615275@2e083615
(took 8 ms)
[info 2016/06/24 08:52:23.877 PDT <Test worker> tid=0xa] Pausing for 1000 ms...
[vm_0][info 2016/06/24 08:52:24.878 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] Received method:
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$5.run
with 0 args on object: "Loggiog CCCP and ServerConnetcion state"
[vm_0][info 2016/06/24 08:52:24.878 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] after CCP states:
[CacheClientProxy[identity(cc2-rh6(28071:loner):51817:28b21c83,connection=1,durableAttributes=DurableClientAttributes[id=test39630_client;
timeout=60]); port=51819; primary=true; version=GFE 9.0; paused=true;
alive=false; connected=false; isMarkedForRemoval=false] ]
[vm_0][info 2016/06/24 08:52:24.878 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] after CHM states: size = 0
[vm_0][info 2016/06/24 08:52:24.878 PDT <RMI TCP Connection(17)-10.118.33.92>
tid=0x5d] Got result: null
[vm_0] from
com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$5.run
with 0 args on object: "Loggiog CCCP and ServerConnetcion state" (took 0 ms)
{noformat}
> CI failure: DurableClientSimpleDUnitTest.testSimpleDurableClient2
> -----------------------------------------------------------------
>
> Key: GEODE-1583
> URL: https://issues.apache.org/jira/browse/GEODE-1583
> Project: Geode
> Issue Type: Bug
> Components: client queues
> Reporter: Hitesh Khamesra
> Labels: CI
>
> https://brazil.gemstone.com:8080/job/Geode_develop_DistributedTests/2986/testReport/com.gemstone.gemfire.internal.cache.tier.sockets/DurableClientSimpleDUnitTest/testSimpleDurableClient2/
> com.gemstone.gemfire.test.dunit.RMIException: While invoking
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$6.run
> in VM 0 running on Host timor.gemstone.com with 4 VMs
> Stacktrace
> com.gemstone.gemfire.test.dunit.RMIException: While invoking
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$6.run
> in VM 0 running on Host timor.gemstone.com with 4 VMs
> at com.gemstone.gemfire.test.dunit.VM.invoke(VM.java:389)
> at com.gemstone.gemfire.test.dunit.VM.invoke(VM.java:355)
> at com.gemstone.gemfire.test.dunit.VM.invoke(VM.java:293)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase.verifySimpleDurableClient(DurableClientTestCase.java:294)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase.testSimpleDurableClient2(DurableClientTestCase.java:224)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:112)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:56)
> at
> org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66)
> at
> org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at
> org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.messaging.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
> at
> org.gradle.messaging.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
> at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
> at
> org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at
> org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
> at
> org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
> at
> org.gradle.messaging.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:360)
> at
> org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54)
> at
> org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: java.lang.AssertionError: Event never occurred after 50000 ms:
> [CacheClientProxy[identity(timor(15095:loner):33719:1b2e0973,connection=1,durableAttributes=DurableClientAttributes[id=testSimpleDurableClient2_client_gem_CacheServerTestUtil;
> timeout=300]); port=33721; primary=true; version=GFE 9.0; paused=true;
> alive=true; connected=false; isMarkedForRemoval=false]Stack trace for
> 'CacheClientProxy[identity(timor(15095:loner):33719:1b2e0973,connection=1,durableAttributes=DurableClientAttributes[id=testSimpleDurableClient2_client_gem_CacheServerTestUtil;
> timeout=300]); port=33721; primary=true; version=GFE 9.0]'
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:502)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.CacheClientProxy$MessageDispatcher.waitForResumption(CacheClientProxy.java:2957)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.CacheClientProxy$MessageDispatcher.run(CacheClientProxy.java:2563)
> ] CHM state: size = 0
> at org.junit.Assert.fail(Assert.java:88)
> at com.gemstone.gemfire.test.dunit.Wait.waitForCriterion(Wait.java:185)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase.checkNumberOfClientProxies(DurableClientTestCase.java:1659)
> at
> com.gemstone.gemfire.internal.cache.tier.sockets.DurableClientTestCase$6.run2(DurableClientTestCase.java:297)
> at
> com.gemstone.gemfire.cache30.CacheSerializableRunnable.run(CacheSerializableRunnable.java:60)
> at sun.reflect.GeneratedMethodAccessor365.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at hydra.MethExecutor.executeObject(MethExecutor.java:268)
> at
> com.gemstone.gemfire.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:82)
> at sun.reflect.GeneratedMethodAccessor337.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:497)
> at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:323)
> at sun.rmi.transport.Transport$1.run(Transport.java:200)
> at sun.rmi.transport.Transport$1.run(Transport.java:197)
> at java.security.AccessController.doPrivileged(Native Method)
> at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
> at
> sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$95(TCPTransport.java:683)
> at java.security.AccessController.doPrivileged(Native Method)
> at
> sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
> ... 3 more
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
