Jared Stewart created GEODE-2871: ------------------------------------ Summary: CI Failure: org.apache.geode.management.internal.cli.commands.CommandOverHttpDUnitTest#testAlterUpdatesSharedConfig Key: GEODE-2871 URL: https://issues.apache.org/jira/browse/GEODE-2871 Project: Geode Issue Type: Bug Components: management Reporter: Jared Stewart
This test failed in the nightly build(https://builds.apache.org/blue/organizations/jenkins/Geode-nightly/detail/Geode-nightly/824/tests): {noformat} Error java.lang.AssertionError: Suspicious strings were written to the log during this run. Fix the strings or use IgnoredException.addIgnoredException to ignore. ----------------------------------------------------------------------- Found suspect string in log4j at line 584 [fatal 2017/05/03 17:42:29.785 UTC <qtp164580182-1202> tid=0x4b2] java.nio.channels.ClosedChannelException at org.eclipse.jetty.util.IteratingCallback.close(IteratingCallback.java:427) at org.eclipse.jetty.server.HttpConnection.onClose(HttpConnection.java:491) at org.eclipse.jetty.io.SelectorManager.connectionClosed(SelectorManager.java:345) at org.eclipse.jetty.io.ManagedSelector$2.run(ManagedSelector.java:442) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) at java.lang.Thread.run(Thread.java:745) Stacktrace java.lang.AssertionError: Suspicious strings were written to the log during this run. Fix the strings or use IgnoredException.addIgnoredException to ignore. ----------------------------------------------------------------------- Found suspect string in log4j at line 584 [fatal 2017/05/03 17:42:29.785 UTC <qtp164580182-1202> tid=0x4b2] java.nio.channels.ClosedChannelException at org.eclipse.jetty.util.IteratingCallback.close(IteratingCallback.java:427) at org.eclipse.jetty.server.HttpConnection.onClose(HttpConnection.java:491) at org.eclipse.jetty.io.SelectorManager.connectionClosed(SelectorManager.java:345) at org.eclipse.jetty.io.ManagedSelector$2.run(ManagedSelector.java:442) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) at java.lang.Thread.run(Thread.java:745) at org.junit.Assert.fail(Assert.java:88) at org.apache.geode.test.dunit.standalone.DUnitLauncher.closeAndCheckForSuspects(DUnitLauncher.java:385) at org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.cleanupAllVms(JUnit4DistributedTestCase.java:577) at org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.tearDownDistributedTestCase(JUnit4DistributedTestCase.java:523) at org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase.tearDown(JUnit4DistributedTestCase.java:509) at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source) 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.RunAfters.evaluate(RunAfters.java:33) at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) 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.junit.runners.Suite.runChild(Suite.java:128) at org.junit.runners.Suite.runChild(Suite.java:27) 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.rules.ExternalResource$1.evaluate(ExternalResource.java:48) at org.junit.rules.RunRules.evaluate(RunRules.java:20) 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) Standard Output [vm0] [info 2017/05/03 09:59:56.412 UTC <RMI TCP Connection(1)-67.195.81.186> 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@259f9806 [vm0] [info 2017/05/03 09:59:56.414 UTC <RMI TCP Connection(1)-67.195.81.186> 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@259f9806 (took 1 ms) [vm3] [info 2017/05/03 09:59:56.417 UTC <RMI TCP Connection(1)-67.195.81.186> 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@79e21bf0 [vm3] [info 2017/05/03 09:59:56.418 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] 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@79e21bf0 (took 0 ms) Previously run tests: [TestHeapDUnitTest, TestLocatorsDUnitTest, TestSubscriptionsDUnitTest, ClusterConfigurationServiceDUnitTest, ConfigCommandsDUnitTest] [vm0] [info 2017/05/03 09:59:56.432 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm0] [info 2017/05/03 09:59:56.496 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 63 ms) [vm3] [info 2017/05/03 09:59:56.524 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm3] [info 2017/05/03 09:59:56.600 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 75 ms) [setup] START TEST ConfigCommandsDUnitTest.testAlterRuntimeConfigOnAllMembers [vm0] [info 2017/05/03 09:59:56.634 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedCallable.call with 0 args on object: callable(setUpJmxManagerOnVm0) [vm0] distributed system properties: {name=Manager, http-service-port=21506, jmx-manager=true, jmx-manager-bind-address=penates.apache.org, jmx-manager-port=24052, mcast-port=0, log-level=info, disable-auto-reconnect=true, enable-cluster-configuration=false, jmx-manager-start=true, locators=localhost[55738], use-cluster-configuration=false} [vm0] [info 2017/05/03 09:59:57.284 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Startup Configuration: [vm0] ### GemFire Properties defined with api ### [vm0] disable-auto-reconnect=true [vm0] enable-cluster-configuration=false [vm0] http-service-port=21506 [vm0] jmx-manager=true [vm0] jmx-manager-bind-address=penates.apache.org [vm0] jmx-manager-port=24052 [vm0] jmx-manager-start=true [vm0] locators=localhost[55738] [vm0] log-level=info [vm0] mcast-port=0 [vm0] name=Manager [vm0] use-cluster-configuration=false [vm0] ### GemFire Properties using default values ### [vm0] ack-severe-alert-threshold=0 [vm0] ack-wait-threshold=15 [vm0] archive-disk-space-limit=0 [vm0] archive-file-size-limit=0 [vm0] async-distribution-timeout=0 [vm0] async-max-queue-size=8 [vm0] async-queue-timeout=60000 [vm0] bind-address= [vm0] cache-xml-file=cache.xml [vm0] cluster-configuration-dir= [vm0] cluster-ssl-ciphers=any [vm0] cluster-ssl-enabled=false [vm0] cluster-ssl-keystore= [vm0] cluster-ssl-keystore-password= [vm0] cluster-ssl-keystore-type= [vm0] cluster-ssl-protocols=any [vm0] cluster-ssl-require-authentication=true [vm0] cluster-ssl-truststore= [vm0] cluster-ssl-truststore-password= [vm0] conflate-events=server [vm0] conserve-sockets=true [vm0] delta-propagation=true [vm0] deploy-working-dir=/home/jenkins/jenkins-slave/workspace/Geode-nightly/geode-core/build/distributedTest/dunit/vm0 [vm0] disable-tcp=false [vm0] distributed-system-id=-1 [vm0] distributed-transactions=false [vm0] durable-client-id= [vm0] durable-client-timeout=300 [vm0] enable-network-partition-detection=true [vm0] enable-time-statistics=false [vm0] enforce-unique-host=false [vm0] gateway-ssl-ciphers=any [vm0] gateway-ssl-enabled=false [vm0] gateway-ssl-keystore= [vm0] gateway-ssl-keystore-password= [vm0] gateway-ssl-keystore-type= [vm0] gateway-ssl-protocols=any [vm0] gateway-ssl-require-authentication=true [vm0] gateway-ssl-truststore= [vm0] gateway-ssl-truststore-password= [vm0] groups= [vm0] http-service-bind-address= [vm0] http-service-ssl-ciphers=any [vm0] http-service-ssl-enabled=false [vm0] http-service-ssl-keystore= [vm0] http-service-ssl-keystore-password= [vm0] http-service-ssl-keystore-type= [vm0] http-service-ssl-protocols=any [vm0] http-service-ssl-require-authentication=false [vm0] http-service-ssl-truststore= [vm0] http-service-ssl-truststore-password= [vm0] jmx-manager-access-file= [vm0] jmx-manager-hostname-for-clients= [vm0] jmx-manager-http-port=21506 [vm0] jmx-manager-password-file= [vm0] jmx-manager-ssl-ciphers=any [vm0] jmx-manager-ssl-enabled=false [vm0] jmx-manager-ssl-keystore= [vm0] jmx-manager-ssl-keystore-password= [vm0] jmx-manager-ssl-keystore-type= [vm0] jmx-manager-ssl-protocols=any [vm0] jmx-manager-ssl-require-authentication=true [vm0] jmx-manager-ssl-truststore= [vm0] jmx-manager-ssl-truststore-password= [vm0] jmx-manager-update-rate=2000 [vm0] load-cluster-configuration-from-dir=false [vm0] locator-wait-time=0 [vm0] lock-memory=false [vm0] log-disk-space-limit=0 [vm0] log-file= [vm0] log-file-size-limit=0 [vm0] max-num-reconnect-tries=3 [vm0] max-wait-time-reconnect=60000 [vm0] mcast-address=239.192.81.1 [vm0] mcast-flow-control=1048576, 0.25, 5000 [vm0] mcast-recv-buffer-size=1048576 [vm0] mcast-send-buffer-size=65535 [vm0] mcast-ttl=32 [vm0] member-timeout=5000 [vm0] membership-port-range=32769-61000 [vm0] memcached-bind-address= [vm0] memcached-port=0 [vm0] memcached-protocol=ASCII [vm0] off-heap-memory-size= [vm0] redis-bind-address= [vm0] redis-password= [vm0] redis-port=0 [vm0] redundancy-zone= [vm0] remote-locators= [vm0] remove-unresponsive-client=false [vm0] roles= [vm0] security-client-accessor= [vm0] security-client-accessor-pp= [vm0] security-client-auth-init= [vm0] security-client-authenticator= [vm0] security-client-dhalgo= [vm0] security-log-file= [vm0] security-log-level=config [vm0] security-manager= [vm0] security-peer-auth-init= [vm0] security-peer-authenticator= [vm0] security-peer-verifymember-timeout=1000 [vm0] security-post-processor= [vm0] security-udp-dhalgo= [vm0] server-bind-address= [vm0] server-ssl-ciphers=any [vm0] server-ssl-enabled=false [vm0] server-ssl-keystore= [vm0] server-ssl-keystore-password= [vm0] server-ssl-keystore-type= [vm0] server-ssl-protocols=any [vm0] server-ssl-require-authentication=true [vm0] server-ssl-truststore= [vm0] server-ssl-truststore-password= [vm0] socket-buffer-size=32768 [vm0] socket-lease-time=60000 [vm0] ssl-ciphers=any [vm0] ssl-cluster-alias= [vm0] ssl-default-alias= [vm0] ssl-enabled-components= [vm0] ssl-gateway-alias= [vm0] ssl-jmx-alias= [vm0] ssl-keystore= [vm0] ssl-keystore-password= [vm0] ssl-keystore-type= [vm0] ssl-locator-alias= [vm0] ssl-protocols=any [vm0] ssl-require-authentication=true [vm0] ssl-server-alias= [vm0] ssl-truststore= [vm0] ssl-truststore-password= [vm0] ssl-web-alias= [vm0] ssl-web-require-authentication=false [vm0] start-dev-rest-api=false [vm0] start-locator= [vm0] statistic-archive-file= [vm0] statistic-sample-rate=1000 [vm0] statistic-sampling-enabled=true [vm0] tcp-port=0 [vm0] udp-fragment-size=60000 [vm0] udp-recv-buffer-size=1048576 [vm0] udp-send-buffer-size=65535 [vm0] user-command-packages= [vm0] [info 2017/05/03 09:59:57.504 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Starting membership services [vm0] [info 2017/05/03 09:59:57.617 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] JGroups channel created (took 112ms) [vm0] [info 2017/05/03 09:59:57.637 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GemFire P2P Listener started on /67.195.81.186:52886 [vm0] [info 2017/05/03 09:59:57.639 UTC <Geode Failure Detection Server thread 0> tid=0x2d] Started failure detection server thread on /67.195.81.186:53414. [vm0] [info 2017/05/03 09:59:57.655 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Attempting to join the distributed system through coordinator 67.195.81.186(24818:locator)<ec><v0>:32769 using address 67.195.81.186(Manager:4040):32770 [locator] [info 2017/05/03 09:59:57.666 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(Manager:4040):32770 [locator] [info 2017/05/03 09:59:57.967 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 09:59:57.968 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|18] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}] [locator] failure detection ports: 49214 53414 [vm0] [info 2017/05/03 09:59:57.971 UTC <unicast receiver,penates-16656> tid=0x29] received new view: View[67.195.81.186(24818:locator)<ec><v0>:32769|18] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}] [vm0] old view is: null [locator] [info 2017/05/03 09:59:57.980 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 09:59:57.980 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|18] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|17] members: [penates(24818:locator)<ec><v0>:32769] shutdown: [penates(24910)<v16>:32771, penates(24906)<v15>:32770] [vm0] [info 2017/05/03 09:59:57.980 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Finished joining (took 339ms). [locator] [info 2017/05/03 09:59:57.981 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|18] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}] [locator] [info 2017/05/03 09:59:57.982 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|18] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}] [locator] failure detection ports: 49214 53414 [locator] [info 2017/05/03 09:59:57.982 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(Manager:4040)<v18>:32770 > [vm0] [info 2017/05/03 09:59:57.982 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Starting DistributionManager 67.195.81.186(Manager:4040)<v18>:32770. (took 626 ms) [locator] [info 2017/05/03 09:59:57.982 UTC <View Message Processor> tid=0x3d] Admitting member <penates(Manager:4040)<v18>:32770>. Now there are 2 non-admin member(s). [vm0] [info 2017/05/03 09:59:57.986 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Initial (distribution manager) view = View[67.195.81.186(24818:locator)<ec><v0>:32769|18] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}] [vm0] [info 2017/05/03 09:59:57.986 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Admitting member <67.195.81.186(24818:locator)<ec><v0>:32769>. Now there are 1 non-admin member(s). [vm0] [info 2017/05/03 09:59:57.987 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Admitting member <67.195.81.186(Manager:4040)<v18>:32770>. Now there are 2 non-admin member(s). [locator] [info 2017/05/03 09:59:58.014 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(Manager:4040)<v18>:32770 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 09:59:58.022 UTC <P2P message reader for 67.195.81.186(24818:locator)<ec><v0>:32769 shared unordered uid=15 port=43107> tid=0x34] Member 67.195.81.186(24818:locator)<ec><v0>:32769 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 09:59:58.162 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] No locator(s) found with cluster configuration service [vm0] [info 2017/05/03 09:59:58.163 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Requesting cluster configuration [vm0] [info 2017/05/03 09:59:58.276 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Initializing region _monitoringRegion_67.195.81.186<v18>32770 [vm0] [info 2017/05/03 09:59:58.284 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Initialization of region _monitoringRegion_67.195.81.186<v18>32770 completed [vm0] [info 2017/05/03 09:59:58.545 UTC <pool-3-thread-1> tid=0x41] Initializing region _monitoringRegion_67.195.81.186<v0>32769 [vm0] [info 2017/05/03 09:59:58.557 UTC <pool-3-thread-1> tid=0x41] Region _monitoringRegion_67.195.81.186<v0>32769 requesting initial image from 67.195.81.186(24818:locator)<ec><v0>:32769 [vm0] [info 2017/05/03 09:59:58.567 UTC <pool-3-thread-1> tid=0x41] _monitoringRegion_67.195.81.186<v0>32769 is done getting image from 67.195.81.186(24818:locator)<ec><v0>:32769. isDeltaGII is false [vm0] [info 2017/05/03 09:59:58.568 UTC <pool-3-thread-1> tid=0x41] Initialization of region _monitoringRegion_67.195.81.186<v0>32769 completed [vm0] [info 2017/05/03 09:59:58.578 UTC <pool-3-thread-1> tid=0x41] Initializing region _notificationRegion_67.195.81.186<v0>32769 [vm0] [info 2017/05/03 09:59:58.580 UTC <pool-3-thread-1> tid=0x41] Initialization of region _notificationRegion_67.195.81.186<v0>32769 completed [vm0] [info 2017/05/03 09:59:58.620 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME:null [vm0] [info 2017/05/03 09:59:58.621 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Reading gemfire.home System Property -> null [vm0] [info 2017/05/03 09:59:58.621 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME environment variable not set; HTTP service will not start. [vm0] [warn 2017/05/03 09:59:58.622 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] geode-web war file was not found [vm0] [info 2017/05/03 09:59:58.622 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME:null [vm0] [info 2017/05/03 09:59:58.622 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Reading gemfire.home System Property -> null [vm0] [info 2017/05/03 09:59:58.622 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME environment variable not set; HTTP service will not start. [vm0] [warn 2017/05/03 09:59:58.623 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] geode-pulse war file was not found [vm0] [info 2017/05/03 09:59:58.624 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME:null [vm0] [info 2017/05/03 09:59:58.624 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Reading gemfire.home System Property -> null [vm0] [info 2017/05/03 09:59:58.624 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GEODE_HOME environment variable not set; HTTP service will not start. [vm0] [warn 2017/05/03 09:59:58.625 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] geode-web-api war file was not found [vm0] [info 2017/05/03 09:59:58.640 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Loading previously deployed jars [vm0] [info 2017/05/03 09:59:58.673 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Initializing region PdxTypes [vm0] [info 2017/05/03 09:59:58.674 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Initialization of region PdxTypes completed [vm0] [info 2017/05/03 09:59:58.698 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>org.eclipse.jetty.io.EofException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.698 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>org.eclipse.jetty.io.EofException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.698 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>org.eclipse.jetty.io.EofException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.700 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>java.nio.channels.ClosedChannelException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.700 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>java.nio.channels.ClosedChannelException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.701 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=add>java.nio.channels.ClosedChannelException</ExpectedException> [vm0] [info 2017/05/03 09:59:58.701 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: [Ljava.lang.Object;@73c290cc [vm0] from org.apache.geode.test.dunit.NamedCallable.call with 0 args on object: callable(setUpJmxManagerOnVm0) (took 2066 ms) [info 2017/05/03 09:59:58.755 UTC <Test worker> tid=0x13] Started testable shell: org.apache.geode.management.internal.cli.HeadlessGfsh@3ca99de5 ConfigCommandsDUnitTest using endpoint: penates.apache.org[24052] [info 2017/05/03 09:59:58.783 UTC <Test worker> tid=0x13] Successfully connected to managing node using JMX distributed system properties: {locators=localhost[55738], name=controller, enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=error} [locator] [info 2017/05/03 09:59:59.153 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(controller:24728):32771 [locator] [info 2017/05/03 09:59:59.453 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 09:59:59.454 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|19] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771] [locator] failure detection ports: 49214 53414 33394 [locator] [info 2017/05/03 09:59:59.461 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 09:59:59.461 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|19] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|18] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}] [locator] [info 2017/05/03 09:59:59.461 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|19] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771] [locator] [info 2017/05/03 09:59:59.462 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|19] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771] [locator] failure detection ports: 49214 53414 33394 [locator] [info 2017/05/03 09:59:59.462 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(controller:24728)<v19>:32771 > [locator] [info 2017/05/03 09:59:59.462 UTC <View Message Processor> tid=0x3d] Admitting member <penates(controller:24728)<v19>:32771>. Now there are 3 non-admin member(s). [vm0] [info 2017/05/03 09:59:59.463 UTC <unicast receiver,penates-16656> tid=0x29] received new view: View[67.195.81.186(24818:locator)<ec><v0>:32769|19] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}, 67.195.81.186(controller:24728)<v19>:32771] [vm0] old view is: View[67.195.81.186(24818:locator)<ec><v0>:32769|18] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}] [vm0] [info 2017/05/03 09:59:59.467 UTC <View Message Processor> tid=0x47] Membership: Processing addition < 67.195.81.186(controller:24728)<v19>:32771 > [vm0] [info 2017/05/03 09:59:59.468 UTC <View Message Processor> tid=0x47] Admitting member <67.195.81.186(controller:24728)<v19>:32771>. Now there are 3 non-admin member(s). [vm0] [info 2017/05/03 09:59:59.473 UTC <pool-3-thread-2> tid=0x48] Initializing region _monitoringRegion_67.195.81.186<v19>32771 [locator] [info 2017/05/03 09:59:59.508 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(controller:24728)<v19>:32771 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 09:59:59.510 UTC <Pooled High Priority Message Processor 1> tid=0x3e] Member 67.195.81.186(controller:24728)<v19>:32771 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 09:59:59.567 UTC <pool-3-thread-2> tid=0x48] Initialization of region _monitoringRegion_67.195.81.186<v19>32771 completed [vm0] [info 2017/05/03 09:59:59.568 UTC <pool-3-thread-2> tid=0x48] Initializing region _notificationRegion_67.195.81.186<v19>32771 [vm0] [info 2017/05/03 09:59:59.570 UTC <pool-3-thread-2> tid=0x48] Initialization of region _notificationRegion_67.195.81.186<v19>32771 completed [vm1] distributed system properties: {locators=localhost[55738], name=VM1, enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=info} [locator] [info 2017/05/03 10:00:00.210 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(VM1:24910):32772 [locator] [info 2017/05/03 10:00:00.511 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 10:00:00.512 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|20] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771, penates(VM1:24910)<v20>:32772] [locator] failure detection ports: 49214 53414 33394 55017 [locator] [info 2017/05/03 10:00:00.514 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 10:00:00.514 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|20] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771, penates(VM1:24910)<v20>:32772] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|19] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771] [locator] [info 2017/05/03 10:00:00.514 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|20] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771, penates(VM1:24910)<v20>:32772] [locator] [info 2017/05/03 10:00:00.515 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|20] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771, penates(VM1:24910)<v20>:32772] [locator] failure detection ports: 49214 53414 33394 55017 [locator] [info 2017/05/03 10:00:00.515 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(VM1:24910)<v20>:32772 > [locator] [info 2017/05/03 10:00:00.515 UTC <View Message Processor> tid=0x3d] Admitting member <penates(VM1:24910)<v20>:32772>. Now there are 4 non-admin member(s). [vm0] [info 2017/05/03 10:00:00.516 UTC <unicast receiver,penates-16656> tid=0x29] received new view: View[67.195.81.186(24818:locator)<ec><v0>:32769|20] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}, 67.195.81.186(controller:24728)<v19>:32771, 67.195.81.186(VM1:24910)<v20>:32772] [vm0] old view is: View[67.195.81.186(24818:locator)<ec><v0>:32769|19] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v18>:32770{lead}, 67.195.81.186(controller:24728)<v19>:32771] [vm0] [info 2017/05/03 10:00:00.518 UTC <View Message Processor> tid=0x47] Membership: Processing addition < 67.195.81.186(VM1:24910)<v20>:32772 > [vm0] [info 2017/05/03 10:00:00.518 UTC <View Message Processor> tid=0x47] Admitting member <67.195.81.186(VM1:24910)<v20>:32772>. Now there are 4 non-admin member(s). [vm0] [info 2017/05/03 10:00:00.520 UTC <pool-3-thread-3> tid=0x4d] Initializing region _monitoringRegion_67.195.81.186<v20>32772 [locator] [info 2017/05/03 10:00:00.522 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(VM1:24910)<v20>:32772 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 10:00:00.523 UTC <Pooled High Priority Message Processor 2> tid=0x4b] Member 67.195.81.186(VM1:24910)<v20>:32772 is equivalent or in the same redundancy zone. [vm0] [info 2017/05/03 10:00:00.528 UTC <pool-3-thread-3> tid=0x4d] Initialization of region _monitoringRegion_67.195.81.186<v20>32772 completed [vm0] [info 2017/05/03 10:00:00.530 UTC <pool-3-thread-3> tid=0x4d] Initializing region _notificationRegion_67.195.81.186<v20>32772 [vm0] [info 2017/05/03 10:00:00.533 UTC <pool-3-thread-3> tid=0x4d] Initialization of region _notificationRegion_67.195.81.186<v20>32772 completed [vm0] 5.567: [GC (Allocation Failure) [PSYoungGen: 131584K->10046K(153088K)] 137824K->16294K(502784K), 0.0168898 secs] [Times: user=0.09 sys=0.02, real=0.02 secs] [vm0] [info 2017/05/03 10:00:00.710 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x44] (tid=68 msgId=0) Executing alter runtime --log-level=info --log-file-size-limit=50 --archive-disk-space-limit=32 --archive-file-size-limit=49 --statistic-sample-rate=2000 --statistic-archive-file=/tmp/junit872410637326872687/controller/stat.gfs --enable-statistics=true --log-disk-space-limit=10 [vm0] [info 2017/05/03 10:00:00.792 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x44] (tid=68 msgId=1) Error occurred while executing "alter runtime --log-level=info --log-file-size-limit=50 --archive-disk-space-limit=32 --archive-file-size-limit=49 --statistic-sample-rate=2000 --statistic-archive-file=/tmp/junit872410637326872687/controller/stat.gfs --enable-statistics=true --log-disk-space-limit=10". [info 2017/05/03 10:00:00.803 UTC <Test worker> tid=0x13] #SB Result [info 2017/05/03 10:00:00.803 UTC <Test worker> tid=0x13] Could not process command due to GemFire error. Exception : class java.lang.NullPointerException , Message : null [info 2017/05/03 10:00:00.868 UTC <Test worker> tid=0x13] GemFireCache[id = 1749887901; isClosing = true; isShutDownAll = false; created = Wed May 03 09:59:59 UTC 2017; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [info 2017/05/03 10:00:00.912 UTC <Test worker> tid=0x13] Shutting down DistributionManager 67.195.81.186(controller:24728)<v19>:32771. [locator] [info 2017/05/03 10:00:00.914 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(controller:24728)<v19>:32771 for penates(controller:24728)<v19>:32771 [vm0] [info 2017/05/03 10:00:00.915 UTC <Pooled High Priority Message Processor 2> tid=0x4b] received leave request from 67.195.81.186(controller:24728)<v19>:32771 for 67.195.81.186(controller:24728)<v19>:32771 [locator] [info 2017/05/03 10:00:00.926 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(controller:24728)<v19>:32771 gracefully left the distributed cache: shutdown message received [vm0] [info 2017/05/03 10:00:00.928 UTC <Pooled High Priority Message Processor 2> tid=0x4b] Member at 67.195.81.186(controller:24728)<v19>:32771 gracefully left the distributed cache: shutdown message received [info 2017/05/03 10:00:01.017 UTC <Test worker> tid=0x13] Now closing distribution for 67.195.81.186(controller:24728)<v19>:32771 [info 2017/05/03 10:00:01.018 UTC <Test worker> tid=0x13] Stopping membership services [locator] [info 2017/05/03 10:00:01.022 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(controller:24728)<v19>:32771 for penates(controller:24728)<v19>:32771 [vm0] [info 2017/05/03 10:00:01.023 UTC <unicast receiver,penates-16656> tid=0x29] received leave request from 67.195.81.186(controller:24728)<v19>:32771 for 67.195.81.186(controller:24728)<v19>:32771 [info 2017/05/03 10:00:01.024 UTC <Test worker> tid=0x13] GMSHealthMonitor server socket is closed in stopServices(). [info 2017/05/03 10:00:01.024 UTC <Geode Failure Detection Server thread 0> tid=0xdb] GMSHealthMonitor server thread exiting [info 2017/05/03 10:00:01.025 UTC <Test worker> tid=0x13] GMSHealthMonitor serverSocketExecutor is terminated [info 2017/05/03 10:00:01.036 UTC <Test worker> tid=0x13] DistributionManager stopped in 122ms. [info 2017/05/03 10:00:01.036 UTC <Test worker> tid=0x13] Marking DistributionManager 67.195.81.186(controller:24728)<v19>:32771 as closed. [locator] [info 2017/05/03 10:00:01.051 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(VM1:24910)<v20>:32772 for penates(VM1:24910)<v20>:32772 [vm0] [info 2017/05/03 10:00:01.051 UTC <Pooled High Priority Message Processor 2> tid=0x4b] received leave request from 67.195.81.186(VM1:24910)<v20>:32772 for 67.195.81.186(VM1:24910)<v20>:32772 [locator] [info 2017/05/03 10:00:01.052 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(VM1:24910)<v20>:32772 gracefully left the distributed cache: shutdown message received [vm0] [info 2017/05/03 10:00:01.052 UTC <Pooled High Priority Message Processor 2> tid=0x4b] Member at 67.195.81.186(VM1:24910)<v20>:32772 gracefully left the distributed cache: shutdown message received [locator] [info 2017/05/03 10:00:01.155 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(VM1:24910)<v20>:32772 for penates(VM1:24910)<v20>:32772 [vm0] [info 2017/05/03 10:00:01.156 UTC <unicast receiver,penates-16656> tid=0x29] received leave request from 67.195.81.186(VM1:24910)<v20>:32772 for 67.195.81.186(VM1:24910)<v20>:32772 [vm0] [info 2017/05/03 10:00:01.165 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) [vm0] [info 2017/05/03 10:00:01.181 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GemFireCache[id = 902758041; isClosing = true; isShutDownAll = false; created = Wed May 03 09:59:58 UTC 2017; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm0] [info 2017/05/03 10:00:01.219 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Shutting down DistributionManager 67.195.81.186(Manager:4040)<v18>:32770. [locator] [info 2017/05/03 10:00:01.221 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(Manager:4040)<v18>:32770 for penates(Manager:4040)<v18>:32770 [locator] [info 2017/05/03 10:00:01.222 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(Manager:4040)<v18>:32770 gracefully left the distributed cache: shutdown message received [locator] [info 2017/05/03 10:00:01.322 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 5 requests for the next membership view [locator] [info 2017/05/03 10:00:01.323 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|21] members: [penates(24818:locator)<ec><v0>:32769] shutdown: [penates(VM1:24910)<v20>:32772, penates(controller:24728)<v19>:32771, penates(Manager:4040)<v18>:32770] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|20] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v18>:32770{lead}, penates(controller:24728)<v19>:32771, penates(VM1:24910)<v20>:32772] [locator] [info 2017/05/03 10:00:01.323 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|21] members: [penates(24818:locator)<ec><v0>:32769] shutdown: [penates(VM1:24910)<v20>:32772, penates(controller:24728)<v19>:32771, penates(Manager:4040)<v18>:32770] [vm0] [info 2017/05/03 10:00:01.324 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Now closing distribution for 67.195.81.186(Manager:4040)<v18>:32770 [locator] [info 2017/05/03 10:00:01.325 UTC <Geode Membership View Creator> tid=0x31] no recipients for new view aside from myself [vm0] [info 2017/05/03 10:00:01.325 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Stopping membership services [locator] [info 2017/05/03 10:00:01.328 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(:<unknown:0>)<v18>:32770 for penates(Manager:4040)<v18>:32770 [vm0] [info 2017/05/03 10:00:01.327 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GMSHealthMonitor server socket is closed in stopServices(). [vm0] [info 2017/05/03 10:00:01.328 UTC <Geode Failure Detection Server thread 0> tid=0x2d] GMSHealthMonitor server thread exiting [vm0] [info 2017/05/03 10:00:01.328 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] GMSHealthMonitor serverSocketExecutor is terminated [vm0] [info 2017/05/03 10:00:01.337 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] DistributionManager stopped in 117ms. [vm0] [info 2017/05/03 10:00:01.337 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Marking DistributionManager 67.195.81.186(Manager:4040)<v18>:32770 as closed. [vm0] [info 2017/05/03 10:00:01.354 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) (took 188 ms) [vm3] [info 2017/05/03 10:00:01.358 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) [vm3] [info 2017/05/03 10:00:01.370 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) (took 12 ms) [vm0] [info 2017/05/03 10:00:01.390 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(verify service stopped) [vm0] [info 2017/05/03 10:00:01.390 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(verify service stopped) (took 0 ms) [vm0] [info 2017/05/03 10:00:01.394 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$42/109096332.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$42/109096332@7e3b6b3c [vm0] [info 2017/05/03 10:00:01.403 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$42/109096332.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$42/109096332@7e3b6b3c (took 8 ms) [vm3] [info 2017/05/03 10:00:01.412 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 [vm3] [info 2017/05/03 10:00:01.450 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 (took 36 ms) [vm0] [info 2017/05/03 10:00:01.464 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm0] [info 2017/05/03 10:00:01.465 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm3] [info 2017/05/03 10:00:01.467 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm3] [info 2017/05/03 10:00:01.467 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [info 2017/05/03 10:00:01.473 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.473 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.478 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.479 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.479 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.479 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.484 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.489 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.489 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.490 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 5 ms) [info 2017/05/03 10:00:01.492 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.492 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.494 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.495 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.495 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.495 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.496 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.496 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.497 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.497 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [info 2017/05/03 10:00:01.499 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.499 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.501 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.501 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.501 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.501 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.502 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.502 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.503 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.503 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [info 2017/05/03 10:00:01.504 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.504 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.506 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.507 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.507 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.507 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.510 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.510 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.510 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.510 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [info 2017/05/03 10:00:01.512 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.512 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.514 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.515 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.515 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.515 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.516 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.516 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.517 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.517 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [info 2017/05/03 10:00:01.518 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.519 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.520 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017/05/03 10:00:01.521 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.521 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.521 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm0] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [vm3] [info 2017/05/03 10:00:01.522 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm3] [info 2017/05/03 10:00:01.523 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.523 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm3] [info 2017/05/03 10:00:01.523 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" (took 0 ms) [info 2017/05/03 10:00:01.525 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [info 2017/05/03 10:00:01.525 UTC <Test worker> tid=0x13] <ExpectedException action=remove>java.rmi.NoSuchObjectException: no such object in table</ExpectedException> [vm0] [info 2017/05/03 10:00:01.527 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.IgnoredException$1.run with 0 args on object: "IgnoredException remove" [vm0] [info 2017 ...[truncated 23358 chars]... @4d0808ff [info 2017/05/03 10:00:02.358 UTC <Test worker> tid=0x13] Started testable shell: org.apache.geode.management.internal.cli.HeadlessGfsh@218802fd ConfigCommandsDUnitTest using endpoint: penates.apache.org[28108] [info 2017/05/03 10:00:02.380 UTC <Test worker> tid=0x13] Successfully connected to managing node using JMX [vm1] distributed system properties: {groups=testAlterUpdatesSharedConfig, locators=localhost[20870], enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=error} [vm1] 335.603: [GC (Allocation Failure) [PSYoungGen: 144772K->13724K(142336K)] 151051K->20020K(492032K), 0.0259409 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] [vm3] [info 2017/05/03 10:00:03.194 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) [vm3] [info 2017/05/03 10:00:03.195 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) (took 0 ms) [vm3] [info 2017/05/03 10:00:03.206 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 [vm3] [info 2017/05/03 10:00:03.208 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 (took 1 ms) [vm3] [info 2017/05/03 10:00:03.214 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm3] [info 2017/05/03 10:00:03.215 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm3] [info 2017/05/03 10:00:03.220 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm3] [info 2017/05/03 10:00:03.221 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [locator] [info 2017/05/03 10:00:03.224 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Received method: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 [locator] [info 2017/05/03 10:00:03.224 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Got result: null [locator] from org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 (took 0 ms) [vm3] [info 2017/05/03 10:00:03.229 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@5d3c5765 [vm3] [info 2017/05/03 10:00:03.229 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@5d3c5765 (took 0 ms) [vm3] [info 2017/05/03 10:00:03.237 UTC <RMI TCP Connection(1)-67.195.81.186> 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@4cc3145e [vm3] [info 2017/05/03 10:00:03.237 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] 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@4cc3145e (took 0 ms) Previously run tests: [TestHeapDUnitTest, TestLocatorsDUnitTest, TestSubscriptionsDUnitTest, ClusterConfigurationServiceDUnitTest, ConfigCommandsDUnitTest] [vm3] [info 2017/05/03 10:00:03.244 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm3] [info 2017/05/03 10:00:03.244 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [setup] START TEST ConfigCommandsDUnitTest.testDescribeConfig [vm0] distributed system properties: {name=Manager, http-service-port=26122, jmx-manager=true, jmx-manager-bind-address=penates.apache.org, jmx-manager-port=24210, mcast-port=0, log-level=info, disable-auto-reconnect=true, enable-cluster-configuration=false, jmx-manager-start=true, locators=localhost[55738], use-cluster-configuration=false} [locator] [info 2017/05/03 10:00:03.300 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(Manager:4040):32770 [locator] [info 2017/05/03 10:00:03.601 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 10:00:03.601 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|22] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}] [locator] failure detection ports: 49214 53329 [locator] [info 2017/05/03 10:00:03.605 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 10:00:03.605 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|22] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|21] members: [penates(24818:locator)<ec><v0>:32769] shutdown: [penates(VM1:24910)<v20>:32772, penates(controller:24728)<v19>:32771, penates(Manager:4040)<v18>:32770] [locator] [info 2017/05/03 10:00:03.605 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|22] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}] [locator] [info 2017/05/03 10:00:03.606 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|22] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}] [locator] failure detection ports: 49214 53329 [locator] [info 2017/05/03 10:00:03.606 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(Manager:4040)<v22>:32770 > [locator] [info 2017/05/03 10:00:03.607 UTC <View Message Processor> tid=0x3d] Admitting member <penates(Manager:4040)<v22>:32770>. Now there are 2 non-admin member(s). [locator] [info 2017/05/03 10:00:03.610 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(Manager:4040)<v22>:32770 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:03.771 UTC <Test worker> tid=0x13] Started testable shell: org.apache.geode.management.internal.cli.HeadlessGfsh@5049c184 ConfigCommandsDUnitTest using endpoint: penates.apache.org[24210] [info 2017/05/03 10:00:03.786 UTC <Test worker> tid=0x13] Successfully connected to managing node using JMX distributed system properties: {name=Member2, groups=G1, enable-time-statistics=true, statistic-sampling-enabled=true, mcast-port=0, log-level=info, disable-auto-reconnect=true, enable-cluster-configuration=false, locators=localhost[55738], use-cluster-configuration=false} [info 2017/05/03 10:00:03.793 UTC <Test worker> tid=0x13] Startup Configuration: ### GemFire Properties defined with api ### disable-auto-reconnect=true enable-cluster-configuration=false enable-time-statistics=true groups=G1 locators=localhost[55738] log-level=info mcast-port=0 name=Member2 statistic-sampling-enabled=true use-cluster-configuration=false ### GemFire Properties using default values ### ack-severe-alert-threshold=0 ack-wait-threshold=15 archive-disk-space-limit=0 archive-file-size-limit=0 async-distribution-timeout=0 async-max-queue-size=8 async-queue-timeout=60000 bind-address= cache-xml-file=cache.xml cluster-configuration-dir= cluster-ssl-ciphers=any cluster-ssl-enabled=false cluster-ssl-keystore= cluster-ssl-keystore-password= cluster-ssl-keystore-type= cluster-ssl-protocols=any cluster-ssl-require-authentication=true cluster-ssl-truststore= cluster-ssl-truststore-password= conflate-events=server conserve-sockets=true delta-propagation=true deploy-working-dir=/home/jenkins/jenkins-slave/workspace/Geode-nightly/geode-core/build/distributedTest disable-tcp=false distributed-system-id=-1 distributed-transactions=false durable-client-id= durable-client-timeout=300 enable-network-partition-detection=true enforce-unique-host=false gateway-ssl-ciphers=any gateway-ssl-enabled=false gateway-ssl-keystore= gateway-ssl-keystore-password= gateway-ssl-keystore-type= gateway-ssl-protocols=any gateway-ssl-require-authentication=true gateway-ssl-truststore= gateway-ssl-truststore-password= http-service-bind-address= http-service-port=7070 http-service-ssl-ciphers=any http-service-ssl-enabled=false http-service-ssl-keystore= http-service-ssl-keystore-password= http-service-ssl-keystore-type= http-service-ssl-protocols=any http-service-ssl-require-authentication=false http-service-ssl-truststore= http-service-ssl-truststore-password= jmx-manager=false jmx-manager-access-file= jmx-manager-bind-address= jmx-manager-hostname-for-clients= jmx-manager-http-port=7070 jmx-manager-password-file= jmx-manager-port=1099 jmx-manager-ssl-ciphers=any jmx-manager-ssl-enabled=false jmx-manager-ssl-keystore= jmx-manager-ssl-keystore-password= jmx-manager-ssl-keystore-type= jmx-manager-ssl-protocols=any jmx-manager-ssl-require-authentication=true jmx-manager-ssl-truststore= jmx-manager-ssl-truststore-password= jmx-manager-start=false jmx-manager-update-rate=2000 load-cluster-configuration-from-dir=false locator-wait-time=0 lock-memory=false log-disk-space-limit=0 log-file= log-file-size-limit=0 max-num-reconnect-tries=3 max-wait-time-reconnect=60000 mcast-address=239.192.81.1 mcast-flow-control=1048576, 0.25, 5000 mcast-recv-buffer-size=1048576 mcast-send-buffer-size=65535 mcast-ttl=32 member-timeout=5000 membership-port-range=32769-61000 memcached-bind-address= memcached-port=0 memcached-protocol=ASCII off-heap-memory-size= redis-bind-address= redis-password= redis-port=0 redundancy-zone= remote-locators= remove-unresponsive-client=false roles= security-client-accessor= security-client-accessor-pp= security-client-auth-init= security-client-authenticator= security-client-dhalgo= security-log-file= security-log-level=config security-manager= security-peer-auth-init= security-peer-authenticator= security-peer-verifymember-timeout=1000 security-post-processor= security-udp-dhalgo= server-bind-address= server-ssl-ciphers=any server-ssl-enabled=false server-ssl-keystore= server-ssl-keystore-password= server-ssl-keystore-type= server-ssl-protocols=any server-ssl-require-authentication=true server-ssl-truststore= server-ssl-truststore-password= socket-buffer-size=32768 socket-lease-time=60000 ssl-ciphers=any ssl-cluster-alias= ssl-default-alias= ssl-enabled-components= ssl-gateway-alias= ssl-jmx-alias= ssl-keystore= ssl-keystore-password= ssl-keystore-type= ssl-locator-alias= ssl-protocols=any ssl-require-authentication=true ssl-server-alias= ssl-truststore= ssl-truststore-password= ssl-web-alias= ssl-web-require-authentication=false start-dev-rest-api=false start-locator= statistic-archive-file= statistic-sample-rate=1000 tcp-port=0 udp-fragment-size=60000 udp-recv-buffer-size=1048576 udp-send-buffer-size=65535 user-command-packages= [info 2017/05/03 10:00:03.797 UTC <Test worker> tid=0x13] Starting membership services [info 2017/05/03 10:00:03.817 UTC <Test worker> tid=0x13] JGroups channel created (took 19ms) [info 2017/05/03 10:00:03.818 UTC <Test worker> tid=0x13] GemFire P2P Listener started on /67.195.81.186:34232 [info 2017/05/03 10:00:03.819 UTC <Geode Failure Detection Server thread 0> tid=0x11c] Started failure detection server thread on /67.195.81.186:36450. [info 2017/05/03 10:00:03.823 UTC <Test worker> tid=0x13] Attempting to join the distributed system through coordinator 67.195.81.186(24818:locator)<ec><v0>:32769 using address 67.195.81.186(Member2:24728):32771 [locator] [info 2017/05/03 10:00:03.824 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(Member2:24728):32771 [locator] [info 2017/05/03 10:00:04.125 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 10:00:04.125 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|23] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}, penates(Member2:24728)<v23>:32771] [locator] failure detection ports: 49214 53329 36450 [info 2017/05/03 10:00:04.126 UTC <unicast receiver,penates-31609> tid=0x118] received new view: View[67.195.81.186(24818:locator)<ec><v0>:32769|23] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v22>:32770{lead}, 67.195.81.186(Member2:24728)<v23>:32771] old view is: null [info 2017/05/03 10:00:04.128 UTC <Test worker> tid=0x13] Finished joining (took 308ms). [locator] [info 2017/05/03 10:00:04.128 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 10:00:04.128 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|23] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}, penates(Member2:24728)<v23>:32771] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|22] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}] [info 2017/05/03 10:00:04.128 UTC <Test worker> tid=0x13] Starting DistributionManager 67.195.81.186(Member2:24728)<v23>:32771. (took 333 ms) [locator] [info 2017/05/03 10:00:04.128 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|23] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}, penates(Member2:24728)<v23>:32771] [info 2017/05/03 10:00:04.128 UTC <Test worker> tid=0x13] Initial (distribution manager) view = View[67.195.81.186(24818:locator)<ec><v0>:32769|23] members: [67.195.81.186(24818:locator)<ec><v0>:32769, 67.195.81.186(Manager:4040)<v22>:32770{lead}, 67.195.81.186(Member2:24728)<v23>:32771] [info 2017/05/03 10:00:04.128 UTC <Test worker> tid=0x13] Admitting member <67.195.81.186(24818:locator)<ec><v0>:32769>. Now there are 1 non-admin member(s). [locator] [info 2017/05/03 10:00:04.129 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|23] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}, penates(Member2:24728)<v23>:32771] [locator] failure detection ports: 49214 53329 36450 [locator] [info 2017/05/03 10:00:04.129 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(Member2:24728)<v23>:32771 > [info 2017/05/03 10:00:04.129 UTC <Test worker> tid=0x13] Admitting member <67.195.81.186(Manager:4040)<v22>:32770>. Now there are 2 non-admin member(s). [locator] [info 2017/05/03 10:00:04.129 UTC <View Message Processor> tid=0x3d] Admitting member <penates(Member2:24728)<v23>:32771>. Now there are 3 non-admin member(s). [info 2017/05/03 10:00:04.129 UTC <Test worker> tid=0x13] Admitting member <67.195.81.186(Member2:24728)<v23>:32771>. Now there are 3 non-admin member(s). [locator] [info 2017/05/03 10:00:04.134 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(Member2:24728)<v23>:32771 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:04.139 UTC <P2P message reader for 67.195.81.186(24818:locator)<ec><v0>:32769 shared unordered uid=20 port=43266> tid=0x126] Member 67.195.81.186(24818:locator)<ec><v0>:32769 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:04.139 UTC <P2P message reader for 67.195.81.186(Manager:4040)<v22>:32770 shared unordered uid=8 port=43265> tid=0x124] Member 67.195.81.186(Manager:4040)<v22>:32770 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:04.158 UTC <Test worker> tid=0x13] No locator(s) found with cluster configuration service [info 2017/05/03 10:00:04.158 UTC <Test worker> tid=0x13] Requesting cluster configuration [info 2017/05/03 10:00:04.168 UTC <Test worker> tid=0x13] Initializing region _monitoringRegion_67.195.81.186<v23>32771 [info 2017/05/03 10:00:04.176 UTC <Test worker> tid=0x13] Region _monitoringRegion_67.195.81.186<v23>32771 requesting initial image from 67.195.81.186(Manager:4040)<v22>:32770 [info 2017/05/03 10:00:04.178 UTC <Test worker> tid=0x13] _monitoringRegion_67.195.81.186<v23>32771 is done getting image from 67.195.81.186(Manager:4040)<v22>:32770. isDeltaGII is false [info 2017/05/03 10:00:04.178 UTC <Test worker> tid=0x13] Initialization of region _monitoringRegion_67.195.81.186<v23>32771 completed [info 2017/05/03 10:00:04.206 UTC <Test worker> tid=0x13] Loading previously deployed jars [info 2017/05/03 10:00:04.208 UTC <Test worker> tid=0x13] Initializing region PdxTypes [info 2017/05/03 10:00:04.213 UTC <Test worker> tid=0x13] Region PdxTypes requesting initial image from 67.195.81.186(Manager:4040)<v22>:32770 [info 2017/05/03 10:00:04.214 UTC <Test worker> tid=0x13] PdxTypes is done getting image from 67.195.81.186(Manager:4040)<v22>:32770. isDeltaGII is false [info 2017/05/03 10:00:04.214 UTC <Test worker> tid=0x13] Initialization of region PdxTypes completed [info 2017/05/03 10:00:04.240 UTC <Test worker> tid=0x13] Cache server connection listener bound to address /0:0:0:0:0:0:0:0:28904 with backlog 1,000. [info 2017/05/03 10:00:04.254 UTC <Test worker> tid=0x13] ClientHealthMonitorThread maximum allowed time between pings: 60,000 [info 2017/05/03 10:00:04.259 UTC <Cache Server Selector /0:0:0:0:0:0:0:0:28904 local port: 28904> tid=0x13c] SELECTOR enabled [info 2017/05/03 10:00:04.264 UTC <Test worker> tid=0x13] CacheServer Configuration: port=28904 max-connections=9 max-threads=10 notify-by-subscription=true socket-buffer-size=32768 maximum-time-between-pings=60000 maximum-message-count=230000 message-time-to-live=180 eviction-policy=none capacity=1 overflow directory=. groups=[] loadProbe=ConnectionCountProbe loadPollInterval=5000 tcpNoDelay=true [info 2017/05/03 10:00:04.277 UTC <Test worker> tid=0x13] #SB Actual JVM Args : [info 2017/05/03 10:00:04.277 UTC <Test worker> tid=0x13] #SB JVM -Dgemfire.DEFAULT_MAX_OPLOG_SIZE=10 [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Dgemfire.disallowMcastDefaults=true [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Djline.terminal=jline.UnsupportedTerminal [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -XX:+HeapDumpOnOutOfMemoryError [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Xmx768m [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Dfile.encoding=ISO-8859-1 [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Duser.country=US [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Duser.language=en [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -Duser.variant [info 2017/05/03 10:00:04.278 UTC <Test worker> tid=0x13] #SB JVM -ea [info 2017/05/03 10:00:04.358 UTC <Test worker> tid=0x13] #SB Hiding the defaults Configuration of member : "Member2"Configuration of member : "Member2" JVM command line arguments ------------------------------------------------------------------------------------------------ -Dgemfire.DEFAULT_MAX_OPLOG_SIZE=10 -Dgemfire.disallowMcastDefaults=true -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager -Djline.terminal=jline.UnsupportedTerminal -XX:+HeapDumpOnOutOfMemoryError -Xmx768m -Dfile.encoding=ISO-8859-1 -Duser.country=US -Duser.language=en -Duser.variant -ea GemFire properties defined using the API ............................................................................................................ disable-auto-reconnect : true enable-cluster-configuration : false enable-time-statistics : true groups : G1 locators : localhost[55738] log-level : info mcast-port : 0 name : Member2 statistic-sampling-enabled : true use-cluster-configuration : false GemFire properties defined at the runtime ............................................................................................................ archive-file-size-limit : 1000 Cache attributes ............................................................................................................ is-server : true Cache-server attributes . max-connections : 9 . max-threads : 10 . port : 28904 . tcp-no-delay : true [info 2017/05/03 10:00:04.397 UTC <Test worker> tid=0x13] #SB No hiding of defaults Configuration of member : "Member2"Configuration of member : "Member2" JVM command line arguments ------------------------------------------------------------------------------------------------ -Dgemfire.DEFAULT_MAX_OPLOG_SIZE=10 -Dgemfire.disallowMcastDefaults=true -Djava.security.manager=worker.org.gradle.process.internal.worker.child.BootstrapSecurityManager -Djline.terminal=jline.UnsupportedTerminal -XX:+HeapDumpOnOutOfMemoryError -Xmx768m -Dfile.encoding=ISO-8859-1 -Duser.country=US -Duser.language=en -Duser.variant -ea GemFire properties defined using the API ...................................................................................................................... disable-auto-reconnect : true enable-cluster-configuration : false enable-time-statistics : true groups : G1 locators : localhost[55738] log-level : info mcast-port : 0 name : Member2 statistic-sampling-enabled : true use-cluster-configuration : false GemFire properties defined at the runtime ...................................................................................................................... archive-file-size-limit : 1000 GemFire properties using default values ...................................................................................................................... ack-severe-alert-threshold : 0 ack-wait-threshold : 15 archive-disk-space-limit : 0 async-distribution-timeout : 0 async-max-queue-size : 8 async-queue-timeout : 60000 bind-address : cache-xml-file : cache.xml cluster-configuration-dir : cluster-ssl-ciphers : any cluster-ssl-enabled : false cluster-ssl-keystore : cluster-ssl-keystore-password : cluster-ssl-keystore-type : cluster-ssl-protocols : any cluster-ssl-require-authentication : true cluster-ssl-truststore : cluster-ssl-truststore-password : conflate-events : server conserve-sockets : true delta-propagation : true deploy-working-dir : /home/jenkins/jenkins-slave/workspace/Geode-nightly/geode-core/build/distributedTest disable-tcp : false distributed-system-id : -1 distributed-transactions : false durable-client-id : durable-client-timeout : 300 enable-network-partition-detection : true enforce-unique-host : false gateway-ssl-ciphers : any gateway-ssl-enabled : false gateway-ssl-keystore : gateway-ssl-keystore-password : gateway-ssl-keystore-type : gateway-ssl-protocols : any gateway-ssl-require-authentication : true gateway-ssl-truststore : gateway-ssl-truststore-password : http-service-bind-address : http-service-port : 7070 http-service-ssl-ciphers : any http-service-ssl-enabled : false http-service-ssl-keystore : http-service-ssl-keystore-password : http-service-ssl-keystore-type : http-service-ssl-protocols : any http-service-ssl-require-authentication : false http-service-ssl-truststore : http-service-ssl-truststore-password : jmx-manager : false jmx-manager-access-file : jmx-manager-bind-address : jmx-manager-hostname-for-clients : jmx-manager-http-port : 7070 jmx-manager-password-file : jmx-manager-port : 1099 jmx-manager-ssl-ciphers : any jmx-manager-ssl-enabled : false jmx-manager-ssl-keystore : jmx-manager-ssl-keystore-password : jmx-manager-ssl-keystore-type : jmx-manager-ssl-protocols : any jmx-manager-ssl-require-authentication : true jmx-manager-ssl-truststore : jmx-manager-ssl-truststore-password : jmx-manager-start : false jmx-manager-update-rate : 2000 load-cluster-configuration-from-dir : false locator-wait-time : 0 lock-memory : false log-disk-space-limit : 0 log-file : log-file-size-limit : 0 max-num-reconnect-tries : 3 max-wait-time-reconnect : 60000 mcast-address : 239.192.81.1 mcast-flow-control : 1048576, 0.25, 5000 mcast-recv-buffer-size : 1048576 mcast-send-buffer-size : 65535 mcast-ttl : 32 member-timeout : 5000 membership-port-range : 32769-61000 memcached-bind-address : memcached-port : 0 memcached-protocol : ASCII off-heap-memory-size : redis-bind-address : redis-password : redis-port : 0 redundancy-zone : remote-locators : remove-unresponsive-client : false roles : security-client-accessor : security-client-accessor-pp : security-client-auth-init : security-client-authenticator : security-client-dhalgo : security-log-file : security-log-level : config security-manager : security-peer-auth-init : security-peer-authenticator : security-peer-verifymember-timeout : 1000 security-post-processor : security-shiro-init : security-udp-dhalgo : server-bind-address : server-ssl-ciphers : any server-ssl-enabled : false server-ssl-keystore : server-ssl-keystore-password : server-ssl-keystore-type : server-ssl-protocols : any server-ssl-require-authentication : true server-ssl-truststore : server-ssl-truststore-password : socket-buffer-size : 32768 socket-lease-time : 60000 ssl-ciphers : any ssl-cluster-alias : ssl-default-alias : ssl-enabled-components : ssl-gateway-alias : ssl-jmx-alias : ssl-keystore : ssl-keystore-password : ssl-keystore-type : ssl-locator-alias : ssl-protocols : any ssl-require-authentication : true ssl-server-alias : ssl-truststore : ssl-truststore-password : ssl-web-alias : ssl-web-require-authentication : false start-dev-rest-api : false start-locator : statistic-archive-file : statistic-sample-rate : 1000 tcp-port : 0 udp-fragment-size : 60000 udp-recv-buffer-size : 1048576 udp-send-buffer-size : 65535 user-command-packages : Cache attributes ...................................................................................................................... copy-on-read : false is-server : true lock-lease : 120 lock-timeout : 60 message-sync-interval : 1 pdx-disk-store : pdx-ignore-unread-fields : false pdx-persistent : false pdx-read-serialized : false search-timeout : 300 Cache-server attributes . bind-address : . hostname-for-clients : . load-poll-interval : 5000 . max-connections : 9 . max-threads : 10 . maximum-message-count : 230000 . maximum-time-between-pings : 60000 . message-time-to-live : 180 . notify-by-subscription : true . port : 28904 . socket-buffer-size : 32768 . tcp-no-delay : true [info 2017/05/03 10:00:04.401 UTC <Test worker> tid=0x13] Cache server on port 28,904 is shutting down. [info 2017/05/03 10:00:04.431 UTC <Test worker> tid=0x13] GemFireCache[id = 230371191; isClosing = true; isShutDownAll = false; created = Wed May 03 10:00:04 UTC 2017; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [info 2017/05/03 10:00:04.439 UTC <Test worker> tid=0x13] Shutting down DistributionManager 67.195.81.186(Member2:24728)<v23>:32771. [locator] [info 2017/05/03 10:00:04.441 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(Member2:24728)<v23>:32771 for penates(Member2:24728)<v23>:32771 [locator] [info 2017/05/03 10:00:04.441 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(Member2:24728)<v23>:32771 gracefully left the distributed cache: shutdown message received [info 2017/05/03 10:00:04.542 UTC <Test worker> tid=0x13] Now closing distribution for 67.195.81.186(Member2:24728)<v23>:32771 [info 2017/05/03 10:00:04.542 UTC <Test worker> tid=0x13] Stopping membership services [locator] [info 2017/05/03 10:00:04.545 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(Member2:24728)<v23>:32771 for penates(Member2:24728)<v23>:32771 [info 2017/05/03 10:00:04.546 UTC <Test worker> tid=0x13] GMSHealthMonitor server socket is closed in stopServices(). [info 2017/05/03 10:00:04.546 UTC <Geode Failure Detection Server thread 0> tid=0x11c] GMSHealthMonitor server thread exiting [info 2017/05/03 10:00:04.547 UTC <Test worker> tid=0x13] GMSHealthMonitor serverSocketExecutor is terminated [info 2017/05/03 10:00:04.551 UTC <Test worker> tid=0x13] DistributionManager stopped in 112ms. [info 2017/05/03 10:00:04.552 UTC <Test worker> tid=0x13] Marking DistributionManager 67.195.81.186(Member2:24728)<v23>:32771 as closed. [locator] [info 2017/05/03 10:00:04.581 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(Manager:4040)<v22>:32770 for penates(Manager:4040)<v22>:32770 [locator] [info 2017/05/03 10:00:04.582 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(Manager:4040)<v22>:32770 gracefully left the distributed cache: shutdown message received [locator] [info 2017/05/03 10:00:04.686 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(Manager:4040)<v22>:32770 for penates(Manager:4040)<v22>:32770 [vm3] [info 2017/05/03 10:00:04.694 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) [vm3] [info 2017/05/03 10:00:04.694 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) (took 0 ms) [vm3] [info 2017/05/03 10:00:04.710 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 [vm3] [info 2017/05/03 10:00:04.712 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 (took 1 ms) [vm3] [info 2017/05/03 10:00:04.718 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm3] [info 2017/05/03 10:00:04.719 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm3] [info 2017/05/03 10:00:04.724 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm3] [info 2017/05/03 10:00:04.724 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [locator] [info 2017/05/03 10:00:04.727 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Received method: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 [locator] [info 2017/05/03 10:00:04.727 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Got result: null [locator] from org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 (took 0 ms) [vm3] [info 2017/05/03 10:00:04.732 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@4684b6e5 [vm3] [info 2017/05/03 10:00:04.732 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@4684b6e5 (took 0 ms) [vm3] [info 2017/05/03 10:00:04.777 UTC <RMI TCP Connection(1)-67.195.81.186> 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@4e982622 [vm3] [info 2017/05/03 10:00:04.777 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] 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@4e982622 (took 0 ms) Previously run tests: [TestHeapDUnitTest, TestLocatorsDUnitTest, TestSubscriptionsDUnitTest, ClusterConfigurationServiceDUnitTest, ConfigCommandsDUnitTest] [vm3] [info 2017/05/03 10:00:04.783 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [setup] START TEST ConfigCommandsDUnitTest.testAlterRuntimeConfig [vm3] [info 2017/05/03 10:00:04.784 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm0] distributed system properties: {name=Manager, http-service-port=29802, jmx-manager=true, jmx-manager-bind-address=penates.apache.org, jmx-manager-port=21873, mcast-port=0, log-level=info, disable-auto-reconnect=true, enable-cluster-configuration=false, jmx-manager-start=true, locators=localhost[55738], use-cluster-configuration=false} [locator] [info 2017/05/03 10:00:04.816 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(Manager:4040):32770 [locator] [info 2017/05/03 10:00:04.816 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 5 requests for the next membership view [locator] [info 2017/05/03 10:00:04.816 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|24] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}] shutdown: [penates(Member2:24728)<v23>:32771, penates(Manager:4040)<v22>:32770] [locator] failure detection ports: 49214 38405 [locator] [info 2017/05/03 10:00:04.819 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 10:00:04.820 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|24] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}] shutdown: [penates(Member2:24728)<v23>:32771, penates(Manager:4040)<v22>:32770] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|23] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v22>:32770{lead}, penates(Member2:24728)<v23>:32771] [locator] [info 2017/05/03 10:00:04.820 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|24] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}] shutdown: [penates(Member2:24728)<v23>:32771, penates(Manager:4040)<v22>:32770] [locator] [info 2017/05/03 10:00:04.821 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|24] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}] shutdown: [penates(Member2:24728)<v23>:32771, penates(Manager:4040)<v22>:32770] [locator] failure detection ports: 49214 38405 [locator] [info 2017/05/03 10:00:04.821 UTC <View Message Processor> tid=0x3d] Membership: Processing addition < penates(Manager:4040)<v24>:32770 > [locator] [info 2017/05/03 10:00:04.821 UTC <View Message Processor> tid=0x3d] Admitting member <penates(Manager:4040)<v24>:32770>. Now there are 2 non-admin member(s). [locator] [info 2017/05/03 10:00:04.846 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(Manager:4040)<v24>:32770 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:04.974 UTC <Test worker> tid=0x13] Started testable shell: org.apache.geode.management.internal.cli.HeadlessGfsh@fda9845 ConfigCommandsDUnitTest using endpoint: penates.apache.org[21873] [info 2017/05/03 10:00:04.996 UTC <Test worker> tid=0x13] Successfully connected to managing node using JMX distributed system properties: {locators=localhost[55738], name=controller, enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=error} [locator] [info 2017/05/03 10:00:05.038 UTC <unicast receiver,penates-48> tid=0x2a] received join request from penates(controller:24728):32771 [locator] [info 2017/05/03 10:00:05.339 UTC <Geode Membership View Creator> tid=0x31] View Creator is processing 1 requests for the next membership view [locator] [info 2017/05/03 10:00:05.340 UTC <Geode Membership View Creator> tid=0x31] preparing new view View[penates(24818:locator)<ec><v0>:32769|25] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}, penates(controller:24728)<v25>:32771] [locator] failure detection ports: 49214 38405 50925 [locator] [info 2017/05/03 10:00:05.345 UTC <Geode Membership View Creator> tid=0x31] finished waiting for responses to view preparation [locator] [info 2017/05/03 10:00:05.346 UTC <Geode Membership View Creator> tid=0x31] received new view: View[penates(24818:locator)<ec><v0>:32769|25] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}, penates(controller:24728)<v25>:32771] [locator] old view is: View[penates(24818:locator)<ec><v0>:32769|24] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}] shutdown: [penates(Member2:24728)<v23>:32771, penates(Manager:4040)<v22>:32770] [locator] [info 2017/05/03 10:00:05.346 UTC <Geode Membership View Creator> tid=0x31] Peer locator received new membership view: View[penates(24818:locator)<ec><v0>:32769|25] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}, penates(controller:24728)<v25>:32771] [locator] [info 2017/05/03 10:00:05.346 UTC <P2P message reader@112f5001> tid=0xb8] Admitting member <penates(controller:24728)<v25>:32771>. Now there are 3 non-admin member(s). [locator] [info 2017/05/03 10:00:05.347 UTC <Geode Membership View Creator> tid=0x31] sending new view View[penates(24818:locator)<ec><v0>:32769|25] members: [penates(24818:locator)<ec><v0>:32769, penates(Manager:4040)<v24>:32770{lead}, penates(controller:24728)<v25>:32771] [locator] failure detection ports: 49214 38405 50925 [locator] [info 2017/05/03 10:00:05.353 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member penates(controller:24728)<v25>:32771 is equivalent or in the same redundancy zone. [info 2017/05/03 10:00:05.552 UTC <Test worker> tid=0x13] Result [info 2017/05/03 10:00:05.552 UTC <Test worker> tid=0x13] Runtime configuration altered successfully for the following member(s) 67.195.81.186(controller:24728)<v25>:32771 [info 2017/05/03 10:00:05.605 UTC <Test worker> tid=0x13] GemFireCache[id = 229822841; isClosing = true; isShutDownAll = false; created = Wed May 03 10:00:05 UTC 2017; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [info 2017/05/03 10:00:05.611 UTC <Test worker> tid=0x13] Shutting down DistributionManager 67.195.81.186(controller:24728)<v25>:32771. [locator] [info 2017/05/03 10:00:05.613 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(controller:24728)<v25>:32771 for penates(controller:24728)<v25>:32771 [locator] [info 2017/05/03 10:00:05.613 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(controller:24728)<v25>:32771 gracefully left the distributed cache: shutdown message received [info 2017/05/03 10:00:05.713 UTC <Test worker> tid=0x13] Now closing distribution for 67.195.81.186(controller:24728)<v25>:32771 [info 2017/05/03 10:00:05.714 UTC <Test worker> tid=0x13] Stopping membership services [info 2017/05/03 10:00:05.716 UTC <Test worker> tid=0x13] GMSHealthMonitor server socket is closed in stopServices(). [info 2017/05/03 10:00:05.718 UTC <Geode Failure Detection Server thread 0> tid=0x15c] GMSHealthMonitor server thread exiting [locator] [info 2017/05/03 10:00:05.717 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(controller:24728)<v25>:32771 for penates(controller:24728)<v25>:32771 [info 2017/05/03 10:00:05.719 UTC <Test worker> tid=0x13] GMSHealthMonitor serverSocketExecutor is terminated [info 2017/05/03 10:00:05.725 UTC <Test worker> tid=0x13] DistributionManager stopped in 113ms. [info 2017/05/03 10:00:05.725 UTC <Test worker> tid=0x13] Marking DistributionManager 67.195.81.186(controller:24728)<v25>:32771 as closed. [locator] [info 2017/05/03 10:00:05.779 UTC <Pooled High Priority Message Processor 2> tid=0x4c] received leave request from penates(Manager:4040)<v24>:32770 for penates(Manager:4040)<v24>:32770 [locator] [info 2017/05/03 10:00:05.779 UTC <Pooled High Priority Message Processor 2> tid=0x4c] Member at penates(Manager:4040)<v24>:32770 gracefully left the distributed cache: shutdown message received [locator] [info 2017/05/03 10:00:05.884 UTC <unicast receiver,penates-48> tid=0x2a] received leave request from penates(Manager:4040)<v24>:32770 for penates(Manager:4040)<v24>:32770 [vm3] [info 2017/05/03 10:00:05.892 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) [vm3] [info 2017/05/03 10:00:05.892 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(disconnectFromDS) (took 0 ms) [vm3] [info 2017/05/03 10:00:05.903 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 [vm3] [info 2017/05/03 10:00:05.904 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953.run with 0 args on object: org.apache.geode.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/253583953@57693b78 (took 0 ms) [vm3] [info 2017/05/03 10:00:05.910 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm3] [info 2017/05/03 10:00:05.911 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm3] [info 2017/05/03 10:00:05.917 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm3] [info 2017/05/03 10:00:05.918 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [locator] [info 2017/05/03 10:00:05.921 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Received method: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 [locator] [info 2017/05/03 10:00:05.922 UTC <RMI TCP Connection(3)-67.195.81.186> tid=0x94] Got result: null [locator] from org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932.run with 0 args on object: org.apache.geode.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$34/2121072932@2e50edb5 (took 0 ms) [vm3] [info 2017/05/03 10:00:05.926 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Received method: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@25e3046f [vm3] [info 2017/05/03 10:00:05.926 UTC <RMI TCP Connection(1)-67.195.81.186> tid=0x1b] Got result: null [vm3] from org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2.run with 0 args on object: org.apache.geode.test.dunit.rules.DistributedRestoreSystemProperties$2@25e3046f (took 0 ms) {noformat} -- This message was sent by Atlassian JIRA (v6.3.15#6346)