Dan Smith created GEODE-4077:
--------------------------------
Summary: HASlowReceiverDUnitTest.testSlowClient fails
intermittently
Key: GEODE-4077
URL: https://issues.apache.org/jira/browse/GEODE-4077
Project: Geode
Issue Type: Bug
Components: client queues
Reporter: Dan Smith
This test is failing intermittently in precheckin with revision
fa2687c76a5fd93d968449a40450c28e8814ee58.
{noformat}
org.apache.geode.test.dunit.RMIException: While invoking
org.apache.geode.internal.cache.ha.HASlowReceiverDUnitTest$$Lambda$355/783772242.run
in VM 3 running on Host fbaa7686d027 with 4 VMs
at org.apache.geode.test.dunit.VM.invoke(VM.java:393)
at org.apache.geode.test.dunit.VM.invoke(VM.java:363)
at org.apache.geode.test.dunit.VM.invoke(VM.java:308)
at
org.apache.geode.internal.cache.ha.HASlowReceiverDUnitTest.testSlowClient(HASlowReceiverDUnitTest.java:252)
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:498)
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:114)
at
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:57)
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.GeneratedMethodAccessor341.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at
org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
at
org.gradle.internal.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.GeneratedMethodAccessor340.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at
org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:147)
at
org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:129)
at
org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
at
org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
at
org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:46)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.geode.cache.NoSubscriptionServersAvailableException:
org.apache.geode.cache.NoSubscriptionServersAvailableException: Primary
discovery failed.
at
org.apache.geode.cache.client.internal.QueueManagerImpl.getAllConnections(QueueManagerImpl.java:190)
at
org.apache.geode.cache.client.internal.PoolImpl.getRedundantNames(PoolImpl.java:1073)
at
org.apache.geode.internal.cache.ha.HASlowReceiverDUnitTest$2.done(HASlowReceiverDUnitTest.java:224)
at org.apache.geode.test.dunit.Wait.waitForCriterion(Wait.java:171)
at
org.apache.geode.internal.cache.ha.HASlowReceiverDUnitTest.checkRedundancyLevel(HASlowReceiverDUnitTest.java:232)
at
org.apache.geode.internal.cache.ha.HASlowReceiverDUnitTest.lambda$testSlowClient$bb17a952$2(HASlowReceiverDUnitTest.java:252)
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:498)
at hydra.MethExecutor.executeObject(MethExecutor.java:244)
at
org.apache.geode.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:70)
at sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
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$0(TCPTransport.java:683)
at java.security.AccessController.doPrivileged(Native Method)
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
... 3 more
Caused by: org.apache.geode.cache.NoSubscriptionServersAvailableException:
Primary discovery failed.
at
org.apache.geode.cache.client.internal.QueueManagerImpl$ConnectionList.setPrimaryDiscoveryFailed(QueueManagerImpl.java:1351)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverPrimary(QueueManagerImpl.java:965)
at
org.apache.geode.cache.client.internal.QueueManagerImpl$RedundancySatisfierTask.run2(QueueManagerImpl.java:1467)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1326)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
... 3 more
{noformat}
I'm wondering of GEODE-3637 changed the timing of this test, but looking at the
logs it looks like maybe this is expected? The test is trying to cause the
server to disconnect the client by having a sleep in the client cache listener.
In the failed run, the client is disconnected.
{noformat}
[warn 2017/12/09 00:29:32.356 UTC <Test worker> tid=0x16] Client
identity(172.17.0.5(193:loner):37262:a854ad38,connection=1 is a slow receiver.
{noformat}
The client tries to reconnect. However, it appears there is some logic on the
server side to block new connections from the client while the servers are
destroying the clients queue. So the client gets an exception.
{noformat}
[vm3] [info 2017/12/09 00:29:32.369 UTC
<queueTimer-HASlowRecieverDUnitTestPool> tid=0x884] SubscriptionManager
redundancy satisfier - redundant endpoint has been lost. Attempting to recover.
[vm3] [warn 2017/12/09 00:29:32.372 UTC
<queueTimer-HASlowRecieverDUnitTestPool> tid=0x884] Cache Client Updater Thread
on fbaa7686d027(178)<v274>:32771 port 28357 (localhost:28357): Caught
following exception while attempting to create a server-to-client communication
socket and will exit:
org.apache.geode.cache.client.ServerRefusedConnectionException: <null inet_addr
hostname><ec>:28357 refused connection: java.lang.Exception: This client is
blacklisted by server
{noformat}
I think this is why the test gets an exception. The test is directly calling an
internal API to check the redundancy of the client pool. But that call throws
an exception, because the client was unable to contact any servers.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
