[ https://issues.apache.org/jira/browse/GEODE-2876?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16007345#comment-16007345 ]
ASF subversion and git services commented on GEODE-2876: -------------------------------------------------------- Commit f88141cfce57adef3171380db1c13bf1e61aaa1d in geode's branch refs/heads/develop from [~jinmeiliao] [ https://git-wip-us.apache.org/repos/asf?p=geode.git;h=f88141c ] GEODE-2876: add logging and testing to diagnose test failure > CI Failure: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest#testMultipleGfshClientToOneServer > ------------------------------------------------------------------------------------------------------------------------- > > Key: GEODE-2876 > URL: https://issues.apache.org/jira/browse/GEODE-2876 > Project: Geode > Issue Type: Bug > Components: gfsh, management > Reporter: Jared Stewart > > ConcurrentDeployDUnitTest is failing due to a parsing error. > {noformat} > Error > java.lang.AssertionError: An exception occurred during asynchronous > invocation. > Stacktrace > java.lang.AssertionError: An exception occurred during asynchronous > invocation. > at > org.apache.geode.test.dunit.AsyncInvocation.checkException(AsyncInvocation.java:148) > at > org.apache.geode.test.dunit.AsyncInvocation.await(AsyncInvocation.java:341) > at > org.apache.geode.test.dunit.AsyncInvocation.await(AsyncInvocation.java:364) > at > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest.testMultipleGfshClientToOneServer(ConcurrentDeployDUnitTest.java:67) > 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.RunAfters.evaluate(RunAfters.java:27) > at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) > at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) > at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) > 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.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.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.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.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.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.MessageHub$Handler.run(MessageHub.java:377) > 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: org.junit.ComparisonFailure: expected:<[OK]> but was:<[ERROR]> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) > at > sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) > at > sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) > at > org.apache.geode.test.dunit.rules.GfshShellConnectionRule.executeAndVerifyCommand(GfshShellConnectionRule.java:231) > at > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest.loopThroughDeployAndUndeploys(ConcurrentDeployDUnitTest.java:90) > at > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest.lambda$testMultipleGfshClientToOneServer$6cbf4f0f$1(ConcurrentDeployDUnitTest.java:63) > 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:245) > at > org.apache.geode.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:73) > at sun.reflect.GeneratedMethodAccessor44.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:346) > 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 > Standard Output > [vm3] [info 2017/04/30 09:25:29.042 UTC <RMI TCP > Connection(15)-67.195.81.146> tid=0x1e] Received method: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@4f861772 > [vm3] [info 2017/04/30 09:25:29.043 UTC <RMI TCP > Connection(15)-67.195.81.146> tid=0x1e] Got result: null > [vm3] from > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@4f861772 > (took 0 ms) > [vm2] [info 2017/04/30 09:25:29.044 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@527317cd > [vm2] [info 2017/04/30 09:25:29.045 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: null > [vm2] from > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@527317cd > (took 0 ms) > [vm1] [info 2017/04/30 09:25:29.047 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@3d8e128e > [vm1] [info 2017/04/30 09:25:29.048 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: null > [vm1] from > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@3d8e128e > (took 0 ms) > [vm0] [info 2017/04/30 09:25:29.049 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@3306e715 > [vm0] [info 2017/04/30 09:25:29.049 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: null > [vm0] from > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1.run > with 0 args on object: > org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$1@3306e715 > (took 0 ms) > [locator] [info 2017/04/30 09:25:29.082 UTC <Geode Membership View Creator> > tid=0x31] View Creator is processing 4 requests for the next membership view > [locator] [info 2017/04/30 09:25:29.083 UTC <Geode Membership View Creator> > tid=0x31] received new view: View[asf902(10966:locator)<ec><v0>:32769|6] > members: [asf902(10966:locator)<ec><v0>:32769] shutdown: > [asf902(VM1:14531)<v5>:32771, asf902(Manager:14467)<v4>:32770] > [locator] old view is: View[asf902(10966:locator)<ec><v0>:32769|5] members: > [asf902(10966:locator)<ec><v0>:32769, asf902(Manager:14467)<v4>:32770{lead}, > asf902(VM1:14531)<v5>:32771] > [locator] [info 2017/04/30 09:25:29.083 UTC <Geode Membership View Creator> > tid=0x31] Peer locator received new membership view: > View[asf902(10966:locator)<ec><v0>:32769|6] members: > [asf902(10966:locator)<ec><v0>:32769] shutdown: > [asf902(VM1:14531)<v5>:32771, asf902(Manager:14467)<v4>:32770] > [locator] [info 2017/04/30 09:25:29.084 UTC <Geode Membership View Creator> > tid=0x31] no recipients for new view aside from myself > [vm0] [info 2017/04/30 09:25:30.373 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.test.dunit.rules.LocatorServerStartupRule$$Lambda$46/1396795996.call > with 0 args on object: > org.apache.geode.test.dunit.rules.LocatorServerStartupRule$$Lambda$46/1396795996@49992b21 > [vm1] [info 2017/04/30 09:25:30.905 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$38/1902651587.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$38/1902651587@3497f87a > [vm1] Command result for <connect --locator=localhost[46165]>: > [vm1] ?[34m _________________________ __ > [vm1] / _____/ ______/ ______/ /____/ / > [vm1] / / __/ /___ /_____ / _____ / > [vm1] / /__/ / ____/ _____/ / / / / > [vm1] /______/_/ /______/_/ /_/ 1.2.0-SNAPSHOT > [vm1] ?[0m > [vm1] ?[36mMonitor and Manage Apache Geode?[0m > [vm1] Connecting to Locator at [host=localhost, port=46165] .. > [vm1] Connecting to Manager at [host=asf902.gq1.ygridcore.net, port=22392] .. > [vm1] Successfully connected to: [host=asf902.gq1.ygridcore.net, port=22392] > [vm1] [info 2017/04/30 09:25:31.170 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: null > [vm1] from > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$38/1902651587.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$38/1902651587@3497f87a > (took 263 ms) > [vm2] [info 2017/04/30 09:25:31.183 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$51/1947212534.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$51/1947212534@29748334 > [vm2] Command result for <connect --locator=localhost[46165]>: > [vm2] ?[34m _________________________ __ > [vm2] / _____/ ______/ ______/ /____/ / > [vm2] / / __/ /___ /_____ / _____ / > [vm2] / /__/ / ____/ _____/ / / / / > [vm2] /______/_/ /______/_/ /_/ 1.2.0-SNAPSHOT > [vm2] ?[0m > [vm2] ?[36mMonitor and Manage Apache Geode?[0m > [vm2] Connecting to Locator at [host=localhost, port=46165] .. > [vm2] Connecting to Manager at [host=asf902.gq1.ygridcore.net, port=22392] .. > [vm2] Successfully connected to: [host=asf902.gq1.ygridcore.net, port=22392] > [vm2] [info 2017/04/30 09:25:31.442 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: null > [vm2] from > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$51/1947212534.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$51/1947212534@29748334 > (took 258 ms) > [vm3] [info 2017/04/30 09:25:31.452 UTC <RMI TCP > Connection(15)-67.195.81.146> tid=0x1e] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$13/1429357537.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$13/1429357537@7ad8e1c3 > [vm3] Command result for <connect --locator=localhost[46165]>: > [vm3] ?[34m _________________________ __ > [vm3] / _____/ ______/ ______/ /____/ / > [vm3] / / __/ /___ /_____ / _____ / > [vm3] / /__/ / ____/ _____/ / / / / > [vm3] /______/_/ /______/_/ /_/ 1.2.0-SNAPSHOT > [vm3] ?[0m > [vm3] ?[36mMonitor and Manage Apache Geode?[0m > [vm3] Connecting to Locator at [host=localhost, port=46165] .. > [vm3] Connecting to Manager at [host=asf902.gq1.ygridcore.net, port=22392] .. > [vm3] Successfully connected to: [host=asf902.gq1.ygridcore.net, port=22392] > [vm3] [info 2017/04/30 09:25:32.540 UTC <RMI TCP > Connection(15)-67.195.81.146> tid=0x1e] Got result: null > [vm3] from > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$13/1429357537.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$13/1429357537@7ad8e1c3 > (took 1087 ms) > [vm2] [info 2017/04/30 09:25:32.556 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$61/411841575.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$61/411841575@5558005d > [vm3] [info 2017/04/30 09:25:32.559 UTC <RMI TCP > Connection(15)-67.195.81.146> tid=0x1e] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$29/1360279604.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$29/1360279604@39d4793e > [vm1] [info 2017/04/30 09:25:32.562 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Received method: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$48/554206614.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$48/554206614@997c3f2 > [vm2] Command result for <deploy > --jar=/tmp/junit7686983196763397747/jar1.jar>: > [vm2] Could not parse command string. deploy > --jar=/tmp/junit7686983196763397747/jar1.jar > [vm3] Command result for <deploy > --jar=/tmp/junit7686983196763397747/jar1.jar>: > [vm3] Could not parse command string. deploy > --jar=/tmp/junit7686983196763397747/jar1.jar > [vm1] Command result for <deploy > --jar=/tmp/junit7686983196763397747/jar1.jar>: > [vm1] Could not parse command string. deploy > --jar=/tmp/junit7686983196763397747/jar1.jar > [vm2] [info 2017/04/30 09:25:32.762 UTC <RMI TCP Connection(1)-67.195.81.146> > tid=0x1b] Got result: EXCEPTION_OCCURRED > [vm2] org.junit.ComparisonFailure: expected:<[OK]> but was:<[ERROR]> > [vm2] at > sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) > [vm2] at > sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) > [vm2] at > sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) > [vm2] at > org.apache.geode.test.dunit.rules.GfshShellConnectionRule.executeAndVerifyCommand(GfshShellConnectionRule.java:231) > [vm2] at > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest.loopThroughDeployAndUndeploys(ConcurrentDeployDUnitTest.java:90) > [vm2] at > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest.lambda$testMultipleGfshClientToOneServer$f4ef8eee$1(ConcurrentDeployDUnitTest.java:64) > [vm2] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > [vm2] at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > [vm2] at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [vm2] at java.lang.reflect.Method.invoke(Method.java:498) > [vm2] at hydra.MethExecutor.executeObject(MethExecutor.java:245) > [vm2] at > org.apache.geode.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:73) > [vm2] at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) > [vm2] at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > [vm2] at java.lang.reflect.Method.invoke(Method.java:498) > [vm2] at > sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:346) > [vm2] at sun.rmi.transport.Transport$1.run(Transport.java:200) > [vm2] at sun.rmi.transport.Transport$1.run(Transport.java:197) > [vm2] at java.security.AccessController.doPrivileged(Native Method) > [vm2] at sun.rmi.transport.Transport.serviceCall(Transport.java:196) > [vm2] at > sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568) > [vm2] at > sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826) > [vm2] at > sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683) > [vm2] at java.security.AccessController.doPrivileged(Native Method) > [vm2] at > sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682) > [vm2] at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > [vm2] at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > [vm2] at java.lang.Thread.run(Thread.java:745) > [vm2] from > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$61/411841575.run > with 0 args on object: > org.apache.geode.management.internal.cli.commands.ConcurrentDeployDUnitTest$$Lambda$61/411841575@5558005d > (took 205 ms) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.15#6346)