Kevin Duling created GEODE-1711: ----------------------------------- Summary: PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf Key: GEODE-1711 URL: https://issues.apache.org/jira/browse/GEODE-1711 Project: Geode Issue Type: Bug Reporter: Kevin Duling
In Geode_develop_DistributedTests/3421: {noformat} Error Message com.gemstone.gemfire.cache.DiskAccessException: For DiskStore: PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion: Could not schedule asynchronous write because the flusher thread had been terminated. Stacktrace com.gemstone.gemfire.cache.DiskAccessException: For DiskStore: PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion: Could not schedule asynchronous write because the flusher thread had been terminated. at com.gemstone.gemfire.internal.cache.DiskStoreImpl.checkForFlusherThreadTermination(DiskStoreImpl.java:1223) at com.gemstone.gemfire.internal.cache.DiskStoreImpl.addAsyncItem(DiskStoreImpl.java:1271) at com.gemstone.gemfire.internal.cache.DiskStoreImpl.scheduleAsyncWrite(DiskStoreImpl.java:1335) at com.gemstone.gemfire.internal.cache.DiskRegion.scheduleAsyncWrite(DiskRegion.java:483) at com.gemstone.gemfire.internal.cache.DiskEntry$Helper.scheduleAsyncWrite(DiskEntry.java:1494) at com.gemstone.gemfire.internal.cache.DiskEntry$Helper.update(DiskEntry.java:1034) at com.gemstone.gemfire.internal.cache.AbstractDiskRegionEntry.setValue(AbstractDiskRegionEntry.java:42) at com.gemstone.gemfire.internal.cache.AbstractRegionEntry.setValueWithTombstoneCheck(AbstractRegionEntry.java:241) at com.gemstone.gemfire.internal.cache.EntryEventImpl.setNewValueInRegion(EntryEventImpl.java:1614) at com.gemstone.gemfire.internal.cache.EntryEventImpl.putExistingEntry(EntryEventImpl.java:1482) at com.gemstone.gemfire.internal.cache.AbstractRegionMap.updateEntry(AbstractRegionMap.java:2882) at com.gemstone.gemfire.internal.cache.AbstractRegionMap.basicPut(AbstractRegionMap.java:2713) at com.gemstone.gemfire.internal.cache.LocalRegion.virtualPut(LocalRegion.java:5955) at com.gemstone.gemfire.internal.cache.DistributedRegion.virtualPut(DistributedRegion.java:348) at com.gemstone.gemfire.internal.cache.LocalRegionDataView.putEntry(LocalRegionDataView.java:132) at com.gemstone.gemfire.internal.cache.LocalRegion.basicPut(LocalRegion.java:5350) at com.gemstone.gemfire.internal.cache.LocalRegion.validatedPut(LocalRegion.java:1668) at com.gemstone.gemfire.internal.cache.LocalRegion.put(LocalRegion.java:1655) at com.gemstone.gemfire.internal.cache.AbstractRegion.put(AbstractRegion.java:288) at com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf(PersistentRVVRecoveryDUnitTest.java:824) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:112) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:56) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66) at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) at org.gradle.messaging.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32) at org.gradle.messaging.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93) at com.sun.proxy.$Proxy2.processTestClass(Unknown Source) at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) at org.gradle.messaging.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:360) at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54) at org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Standard Output Previously run tests: [PersistentRecoveryOrderDUnitTest, PersistentRVVRecoveryDUnitTest] [vm_0][info 2016/07/27 08:22:42.569 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_0][info 2016/07/27 08:22:42.570 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_1][info 2016/07/27 08:22:42.571 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_1][info 2016/07/27 08:22:42.571 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_2][info 2016/07/27 08:22:42.573 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_2][info 2016/07/27 08:22:42.573 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [setup] START TEST PersistentRVVRecoveryDUnitTest.testNoConcurrencyChecks [vm_3][info 2016/07/27 08:22:42.576 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_3][info 2016/07/27 08:22:42.576 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_0][info 2016/07/27 08:22:42.576 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_0][info 2016/07/27 08:22:42.576 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [vm_1][info 2016/07/27 08:22:42.577 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_1][info 2016/07/27 08:22:42.577 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [vm_2][info 2016/07/27 08:22:42.577 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_2][info 2016/07/27 08:22:42.578 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [vm_3][info 2016/07/27 08:22:42.578 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_3][info 2016/07/27 08:22:42.578 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) distributed system properties: {locators=localhost[52265], enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=info} [locator][info 2016/07/27 08:22:42.653 PDT <Geode Membership View Creator> tid=0x27] View Creator is processing 4 requests for the next membership view [locator][info 2016/07/27 08:22:42.653 PDT <Geode Membership View Creator> tid=0x27] received new view: View[venezuela(12353:locator)<ec><v0>:1025|62] members: [venezuela(12353:locator)<ec><v0>:1025] shutdown: [venezuela(12418)<ec><v61>:1028, venezuela(12414)<ec><v58>:1026] [locator]old view is: View[venezuela(12353:locator)<ec><v0>:1025|61] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12414)<ec><v58>:1026{lead}, venezuela(12418)<ec><v61>:1028] [locator][info 2016/07/27 08:22:42.653 PDT <Geode Membership View Creator> tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator)<ec><v0>:1025|62] members: [venezuela(12353:locator)<ec><v0>:1025] shutdown: [venezuela(12418)<ec><v61>:1028, venezuela(12414)<ec><v58>:1026] [locator][info 2016/07/27 08:22:42.653 PDT <Geode Membership View Creator> tid=0x27] no recipients for new view aside from myself [info 2016/07/27 08:22:42.839 PDT <Test worker> tid=0xa] Startup Configuration: ### GemFire Properties defined with api ### disable-auto-reconnect=true enable-cluster-configuration=false locators=localhost[52265] log-level=info mcast-port=0 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=. disable-tcp=false distributed-system-id=-1 distributed-transactions=false durable-client-id= durable-client-timeout=300 enable-network-partition-detection=false enable-time-statistics=false 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= groups= 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=false 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=1024-65535 memcached-bind-address= memcached-port=0 memcached-protocol=ASCII name= 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= 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-enabled=false ssl-protocols=any ssl-require-authentication=true start-dev-rest-api=false start-locator= statistic-archive-file= statistic-sample-rate=1000 statistic-sampling-enabled=true tcp-port=0 udp-fragment-size=60000 udp-recv-buffer-size=1048576 udp-send-buffer-size=65535 user-command-packages= [info 2016/07/27 08:22:43.008 PDT <Test worker> tid=0xa] Starting membership services [info 2016/07/27 08:22:43.101 PDT <Test worker> tid=0xa] JGroups channel created (took 92ms) [info 2016/07/27 08:22:43.108 PDT <Test worker> tid=0xa] GemFire P2P Listener started on null [info 2016/07/27 08:22:43.110 PDT <Geode Failure Detection Server thread 0> tid=0xa2] Started failure detection server thread on venezuela.gemstone.com/10.118.32.90:30225. [info 2016/07/27 08:22:43.122 PDT <Test worker> tid=0xa] Attempting to join the distributed system through coordinator venezuela(12353:locator)<ec><v0>:1025 using address venezuela(12321)<ec>:1026 [locator][info 2016/07/27 08:22:43.131 PDT <unicast receiver,venezuela-31226> tid=0x21] received join request from venezuela(12321)<ec>:1026 [locator][info 2016/07/27 08:22:43.437 PDT <Geode Membership View Creator> tid=0x27] View Creator is processing 1 requests for the next membership view [locator][info 2016/07/27 08:22:43.437 PDT <Geode Membership View Creator> tid=0x27] preparing new view View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [locator]failure detection ports: 45258 30225 [locator][info 2016/07/27 08:22:43.441 PDT <Geode Membership View Creator> tid=0x27] finished waiting for responses to view preparation [locator][info 2016/07/27 08:22:43.441 PDT <Geode Membership View Creator> tid=0x27] received new view: View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [locator]old view is: View[venezuela(12353:locator)<ec><v0>:1025|62] members: [venezuela(12353:locator)<ec><v0>:1025] shutdown: [venezuela(12418)<ec><v61>:1028, venezuela(12414)<ec><v58>:1026] [locator][info 2016/07/27 08:22:43.441 PDT <Geode Membership View Creator> tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [locator][info 2016/07/27 08:22:43.442 PDT <Geode Membership View Creator> tid=0x27] sending new view View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [locator]failure detection ports: 45258 30225 [locator][info 2016/07/27 08:22:43.442 PDT <View Message Processor> tid=0x33] Membership: Processing addition < venezuela(12321)<ec><v63>:1026 > [locator][info 2016/07/27 08:22:43.442 PDT <View Message Processor> tid=0x33] Admitting member <venezuela(12321)<ec><v63>:1026>. Now there are 2 non-admin member(s). [info 2016/07/27 08:22:43.442 PDT <unicast receiver,venezuela-6806> tid=0x9e] received new view: View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] old view is: null [info 2016/07/27 08:22:43.445 PDT <Test worker> tid=0xa] Finished joining (took 334ms). [info 2016/07/27 08:22:43.446 PDT <Test worker> tid=0xa] Starting DistributionManager venezuela(12321)<ec><v63>:1026. (took 562 ms) [info 2016/07/27 08:22:43.447 PDT <Test worker> tid=0xa] Initial (distribution manager) view = View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [info 2016/07/27 08:22:43.447 PDT <Test worker> tid=0xa] Admitting member <venezuela(12353:locator)<ec><v0>:1025>. Now there are 1 non-admin member(s). [info 2016/07/27 08:22:43.448 PDT <Test worker> tid=0xa] Admitting member <venezuela(12321)<ec><v63>:1026>. Now there are 2 non-admin member(s). [locator][info 2016/07/27 08:22:43.468 PDT <Pooled High Priority Message Processor 2> tid=0x47] Member venezuela(12321)<ec><v63>:1026 is equivalent or in the same redundancy zone. [info 2016/07/27 08:22:43.475 PDT <P2P message reader for venezuela(12353:locator)<ec><v0>:1025 shared unordered uid=54 port=54835> tid=0xa7] Member venezuela(12353:locator)<ec><v0>:1025 is equivalent or in the same redundancy zone. [info 2016/07/27 08:22:43.684 PDT <Test worker> tid=0xa] Initializing region _monitoringRegion_10.118.32.90<v63>1026 [info 2016/07/27 08:22:43.691 PDT <Test worker> tid=0xa] Initialization of region _monitoringRegion_10.118.32.90<v63>1026 completed [info 2016/07/27 08:22:43.913 PDT <Test worker> tid=0xa] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [info 2016/07/27 08:22:43.926 PDT <Test worker> tid=0xa] Initializing region PdxTypes [info 2016/07/27 08:22:43.928 PDT <Test worker> tid=0xa] Initialization of region PdxTypes completed [info 2016/07/27 08:22:43.952 PDT <Test worker> tid=0xa] GemFireCache[id = 923031962; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:43 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_0][info 2016/07/27 08:22:43.989 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195@310e441b [vm_0][info 2016/07/27 08:22:43.989 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195@310e441b (took 0 ms) [vm_1][info 2016/07/27 08:22:43.990 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456@72df2354 [vm_1][info 2016/07/27 08:22:43.990 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456@72df2354 (took 0 ms) [vm_2][info 2016/07/27 08:22:43.991 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286@17d31ca3 [vm_2][info 2016/07/27 08:22:43.991 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286@17d31ca3 (took 0 ms) [vm_3][info 2016/07/27 08:22:43.992 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163@2e3019b0 [vm_3][info 2016/07/27 08:22:43.992 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163@2e3019b0 (took 0 ms) [vm_0][info 2016/07/27 08:22:43.992 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_0][info 2016/07/27 08:22:43.993 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_1][info 2016/07/27 08:22:43.993 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_1][info 2016/07/27 08:22:43.993 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_2][info 2016/07/27 08:22:43.993 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_2][info 2016/07/27 08:22:43.994 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_3][info 2016/07/27 08:22:43.994 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_3][info 2016/07/27 08:22:43.994 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_0][info 2016/07/27 08:22:43.995 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_0][info 2016/07/27 08:22:43.995 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_1][info 2016/07/27 08:22:43.995 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_1][info 2016/07/27 08:22:43.995 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_2][info 2016/07/27 08:22:43.996 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_2][info 2016/07/27 08:22:43.996 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_3][info 2016/07/27 08:22:43.996 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_3][info 2016/07/27 08:22:43.996 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [info 2016/07/27 08:22:44.000 PDT <Test worker> tid=0xa] Shutting down DistributionManager venezuela(12321)<ec><v63>:1026. [locator][info 2016/07/27 08:22:44.002 PDT <Pooled High Priority Message Processor 2> tid=0x47] received leave request from venezuela(12321)<ec><v63>:1026 for venezuela(12321)<ec><v63>:1026 [locator][info 2016/07/27 08:22:44.002 PDT <Pooled High Priority Message Processor 2> tid=0x47] Member at venezuela(12321)<ec><v63>:1026 gracefully left the distributed cache: shutdown message received [info 2016/07/27 08:22:44.104 PDT <Test worker> tid=0xa] Now closing distribution for venezuela(12321)<ec><v63>:1026 [info 2016/07/27 08:22:44.104 PDT <Test worker> tid=0xa] Stopping membership services [locator][info 2016/07/27 08:22:44.106 PDT <unicast receiver,venezuela-31226> tid=0x21] received leave request from venezuela(12321)<ec><v63>:1026 for venezuela(12321)<ec><v63>:1026 [info 2016/07/27 08:22:44.107 PDT <Test worker> tid=0xa] GMSHealthMonitor server socket is closed in stopServices(). [info 2016/07/27 08:22:44.108 PDT <Geode Failure Detection Server thread 0> tid=0xa2] GMSHealthMonitor server thread exiting [info 2016/07/27 08:22:44.108 PDT <Test worker> tid=0xa] GMSHealthMonitor serverSocketExecutor is terminated [info 2016/07/27 08:22:44.114 PDT <Test worker> tid=0xa] DistributionManager stopped in 114ms. [info 2016/07/27 08:22:44.114 PDT <Test worker> tid=0xa] Marking DistributionManager venezuela(12321)<ec><v63>:1026 as closed. [vm_1][info 2016/07/27 08:22:44.117 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_1][info 2016/07/27 08:22:44.117 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [vm_0][info 2016/07/27 08:22:44.117 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_0][info 2016/07/27 08:22:44.117 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [vm_2][info 2016/07/27 08:22:44.119 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_2][info 2016/07/27 08:22:44.119 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [vm_3][info 2016/07/27 08:22:44.120 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_3][info 2016/07/27 08:22:44.120 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [locator][info 2016/07/27 08:22:44.121 PDT <RMI TCP Connection(2)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019.run with 0 args on object: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019@658426d0 [locator][info 2016/07/27 08:22:44.121 PDT <RMI TCP Connection(2)-10.118.32.90> tid=0x12] Got result: null [locator] from com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019.run with 0 args on object: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019@658426d0 (took 0 ms) Previously run tests: [PersistentRecoveryOrderDUnitTest, PersistentRVVRecoveryDUnitTest] [vm_0][info 2016/07/27 08:22:44.125 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_0][info 2016/07/27 08:22:44.126 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_1][info 2016/07/27 08:22:44.129 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_1][info 2016/07/27 08:22:44.129 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_2][info 2016/07/27 08:22:44.130 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_2][info 2016/07/27 08:22:44.130 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [vm_3][info 2016/07/27 08:22:44.130 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) [vm_3][info 2016/07/27 08:22:44.131 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(setupVM) (took 0 ms) [setup] START TEST PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf [vm_0][info 2016/07/27 08:22:44.132 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_0][info 2016/07/27 08:22:44.132 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [vm_1][info 2016/07/27 08:22:44.133 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_1][info 2016/07/27 08:22:44.133 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [vm_2][info 2016/07/27 08:22:44.133 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_2][info 2016/07/27 08:22:44.134 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) distributed system properties: {locators=localhost[52265], enable-cluster-configuration=false, use-cluster-configuration=false, mcast-port=0, disable-auto-reconnect=true, log-level=info} [vm_3][info 2016/07/27 08:22:44.135 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args [vm_3][info 2016/07/27 08:22:44.135 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase.setRegionName with 1 args (took 0 ms) [info 2016/07/27 08:22:44.139 PDT <Test worker> tid=0xa] Startup Configuration: ### GemFire Properties defined with api ### disable-auto-reconnect=true enable-cluster-configuration=false locators=localhost[52265] log-level=info mcast-port=0 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=. disable-tcp=false distributed-system-id=-1 distributed-transactions=false durable-client-id= durable-client-timeout=300 enable-network-partition-detection=false enable-time-statistics=false 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= groups= 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=false 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=1024-65535 memcached-bind-address= memcached-port=0 memcached-protocol=ASCII name= 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= 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-enabled=false ssl-protocols=any ssl-require-authentication=true start-dev-rest-api=false start-locator= statistic-archive-file= statistic-sample-rate=1000 statistic-sampling-enabled=true tcp-port=0 udp-fragment-size=60000 udp-recv-buffer-size=1048576 udp-send-buffer-size=65535 user-command-packages= [info 2016/07/27 08:22:44.141 PDT <Test worker> tid=0xa] Starting membership services [info 2016/07/27 08:22:44.150 PDT <Test worker> tid=0xa] JGroups channel created (took 9ms) [info 2016/07/27 08:22:44.151 PDT <Test worker> tid=0xa] GemFire P2P Listener started on null [info 2016/07/27 08:22:44.152 PDT <Geode Failure Detection Server thread 0> tid=0xca] Started failure detection server thread on venezuela.gemstone.com/10.118.32.90:47292. [info 2016/07/27 08:22:44.153 PDT <Test worker> tid=0xa] Attempting to join the distributed system through coordinator venezuela(12353:locator)<ec><v0>:1025 using address venezuela(12321)<ec>:1026 [locator][info 2016/07/27 08:22:44.154 PDT <unicast receiver,venezuela-31226> tid=0x21] received join request from venezuela(12321)<ec>:1026 [locator][info 2016/07/27 08:22:44.357 PDT <Geode Membership View Creator> tid=0x27] View Creator is processing 3 requests for the next membership view [locator][info 2016/07/27 08:22:44.358 PDT <Geode Membership View Creator> tid=0x27] preparing new view View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] [locator]failure detection ports: 45258 47292 [locator][info 2016/07/27 08:22:44.359 PDT <Geode Membership View Creator> tid=0x27] finished waiting for responses to view preparation [locator][info 2016/07/27 08:22:44.359 PDT <Geode Membership View Creator> tid=0x27] received new view: View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] [locator]old view is: View[venezuela(12353:locator)<ec><v0>:1025|63] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v63>:1026{lead}] [locator][info 2016/07/27 08:22:44.359 PDT <Geode Membership View Creator> tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] [info 2016/07/27 08:22:44.359 PDT <unicast receiver,venezuela-23921> tid=0xc6] received new view: View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] old view is: null [locator][info 2016/07/27 08:22:44.360 PDT <Geode Membership View Creator> tid=0x27] sending new view View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] [locator]failure detection ports: 45258 47292 [locator][info 2016/07/27 08:22:44.360 PDT <View Message Processor> tid=0x33] Membership: Processing addition < venezuela(12321)<ec><v64>:1026 > [locator][info 2016/07/27 08:22:44.360 PDT <View Message Processor> tid=0x33] Admitting member <venezuela(12321)<ec><v64>:1026>. Now there are 2 non-admin member(s). [info 2016/07/27 08:22:44.360 PDT <Test worker> tid=0xa] Finished joining (took 208ms). [info 2016/07/27 08:22:44.361 PDT <Test worker> tid=0xa] Starting DistributionManager venezuela(12321)<ec><v64>:1026. (took 221 ms) [info 2016/07/27 08:22:44.361 PDT <Test worker> tid=0xa] Initial (distribution manager) view = View[venezuela(12353:locator)<ec><v0>:1025|64] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12321)<ec><v64>:1026{lead}] shutdown: [venezuela(12321)<ec><v63>:1026] [info 2016/07/27 08:22:44.361 PDT <Test worker> tid=0xa] Admitting member <venezuela(12353:locator)<ec><v0>:1025>. Now there are 1 non-admin member(s). [info 2016/07/27 08:22:44.361 PDT <Test worker> tid=0xa] Admitting member <venezuela(12321)<ec><v64>:1026>. Now there are 2 non-admin member(s). [locator][info 2016/07/27 08:22:44.364 PDT <Pooled High Priority Message Processor 2> tid=0x47] Member venezuela(12321)<ec><v64>:1026 is equivalent or in the same redundancy zone. [info 2016/07/27 08:22:44.366 PDT <P2P message reader for venezuela(12353:locator)<ec><v0>:1025 shared unordered uid=55 port=58813> tid=0xcf] Member venezuela(12353:locator)<ec><v0>:1025 is equivalent or in the same redundancy zone. [info 2016/07/27 08:22:44.375 PDT <Test worker> tid=0xa] Initializing region _monitoringRegion_10.118.32.90<v64>1026 [info 2016/07/27 08:22:44.376 PDT <Test worker> tid=0xa] Initialization of region _monitoringRegion_10.118.32.90<v64>1026 completed [info 2016/07/27 08:22:44.381 PDT <Test worker> tid=0xa] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [info 2016/07/27 08:22:44.382 PDT <Test worker> tid=0xa] Initializing region PdxTypes [info 2016/07/27 08:22:44.384 PDT <Test worker> tid=0xa] Initialization of region PdxTypes completed [info 2016/07/27 08:22:44.419 PDT <Test worker> tid=0xa] Created disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion with unique id 9048b6bb98354e5f-8d643eccc5e71544 [info 2016/07/27 08:22:44.431 PDT <Test worker> tid=0xa] recovery region initialization took 1 ms [info 2016/07/27 08:22:44.502 PDT <Test worker> tid=0xa] Created oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:44.506 PDT <Test worker> tid=0xa] Created oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [warn 2016/07/27 08:22:44.511 PDT <Test worker> tid=0xa] Creating persistent region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion, but enable-network-partition-detection is set to false. Running with network partition detection disabled can lead to an unrecoverable system in the event of a network split. [info 2016/07/27 08:22:44.512 PDT <Test worker> tid=0xa] Initializing region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion [info 2016/07/27 08:22:44.515 PDT <Test worker> tid=0xa] Region /PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion was created on this member with the persistent id venezuela.gemstone.com/10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testWriteCorrectVersionToKrf/1 created at timestamp 1469632964511 version 0 diskStoreId 9048b6bb98354e5f-8d643eccc5e71544 name . [info 2016/07/27 08:22:44.516 PDT <Test worker> tid=0xa] Initialization of region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion completed [info 2016/07/27 08:22:44.525 PDT <Test worker> tid=0xa] <ExpectedException action=add>DiskAccessException</ExpectedException> [info 2016/07/27 08:22:44.526 PDT <Test worker> tid=0xa] <ExpectedException action=add>DiskAccessException</ExpectedException> [info 2016/07/27 08:22:44.526 PDT <Test worker> tid=0xa] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_0][info 2016/07/27 08:22:44.526 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" [vm_0][info 2016/07/27 08:22:44.526 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_0][info 2016/07/27 08:22:44.526 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_0][info 2016/07/27 08:22:44.526 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" (took 0 ms) [vm_1][info 2016/07/27 08:22:44.527 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Received method: com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" [vm_1][info 2016/07/27 08:22:44.527 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_1][info 2016/07/27 08:22:44.527 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_1][info 2016/07/27 08:22:44.527 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0x1ee] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" (took 0 ms) [vm_2][info 2016/07/27 08:22:44.529 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" [vm_2][info 2016/07/27 08:22:44.529 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_2][info 2016/07/27 08:22:44.529 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_2][info 2016/07/27 08:22:44.529 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" (took 0 ms) [vm_3][info 2016/07/27 08:22:44.532 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" [vm_3][info 2016/07/27 08:22:44.533 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_3][info 2016/07/27 08:22:44.533 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] <ExpectedException action=add>DiskAccessException</ExpectedException> [vm_3][info 2016/07/27 08:22:44.533 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.IgnoredException$2.run with 0 args on object: "IgnoredException addIgnoredException" (took 0 ms) [info 2016/07/27 08:22:45.411 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.412 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.417 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.417 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.421 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#4 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.421 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#4 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.423 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#5 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.424 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#5 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.426 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#6 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.427 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#6 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.430 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#7 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.430 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#7 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.432 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#8 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.433 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#8 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.434 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#9 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.435 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] Created oplog#9 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.437 PDT <Oplog Delete Task> tid=0xdf] Deleted oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.437 PDT <Oplog Delete Task> tid=0xdf] Deleted oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.440 PDT <Idle OplogCompactor> tid=0xdd] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. [info 2016/07/27 08:22:45.442 PDT <OplogCompactor PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion for oplog oplog#1> tid=0xdd] OplogCompactor for PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion compaction oplog id(s): oplog#1 [error 2016/07/27 08:22:45.442 PDT <Asynchronous disk writer for region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion> tid=0xdc] A DiskAccessException has occurred while writing to the disk for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. The cache will be closed. com.gemstone.gemfire.cache.DiskAccessException at com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$16.afterWritingBytes(PersistentRVVRecoveryDUnitTest.java:802) at com.gemstone.gemfire.internal.cache.DiskStoreImpl$FlusherThread.run(DiskStoreImpl.java:1743) at java.lang.Thread.run(Thread.java:745) [error 2016/07/27 08:22:45.443 PDT <Test worker> tid=0xa] A DiskAccessException has occurred while writing to the disk for region /PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. The cache will be closed. com.gemstone.gemfire.cache.DiskAccessException: For DiskStore: PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion: Could not schedule asynchronous write because the flusher thread had been terminated. at com.gemstone.gemfire.internal.cache.DiskStoreImpl.checkForFlusherThreadTermination(DiskStoreImpl.java:1223) at com.gemstone.gemfire.internal.cache.DiskStoreImpl.addAsyncItem(DiskStoreImpl.java:1271) at com.gemstone.gemfire.internal.cache.DiskStoreImpl.scheduleAsyncWrite(DiskStoreImpl.java:1335) at com.gemstone.gemfire.internal.cache.DiskRegion.scheduleAsyncWrite(DiskRegion.java:483) at com.gemstone.gemfire.internal.cache.DiskEntry$Helper.scheduleAsyncWrite(DiskEntry.java:1494) at com.gemstone.gemfire.internal.cache.DiskEntry$Helper.update(DiskEntry.java:1034) at com.gemstone.gemfire.internal.cache.AbstractDiskRegionEntry.setValue(AbstractDiskRegionEntry.java:42) at com.gemstone.gemfire.internal.cache.AbstractRegionEntry.setValueWithTombstoneCheck(AbstractRegionEntry.java:241) at com.gemstone.gemfire.internal.cache.EntryEventImpl.setNewValueInRegion(EntryEventImpl.java:1614) at com.gemstone.gemfire.internal.cache.EntryEventImpl.putExistingEntry(EntryEventImpl.java:1482) at com.gemstone.gemfire.internal.cache.AbstractRegionMap.updateEntry(AbstractRegionMap.java:2882) at com.gemstone.gemfire.internal.cache.AbstractRegionMap.basicPut(AbstractRegionMap.java:2713) at com.gemstone.gemfire.internal.cache.LocalRegion.virtualPut(LocalRegion.java:5955) at com.gemstone.gemfire.internal.cache.DistributedRegion.virtualPut(DistributedRegion.java:348) at com.gemstone.gemfire.internal.cache.LocalRegionDataView.putEntry(LocalRegionDataView.java:132) at com.gemstone.gemfire.internal.cache.LocalRegion.basicPut(LocalRegion.java:5350) at com.gemstone.gemfire.internal.cache.LocalRegion.validatedPut(LocalRegion.java:1668) at com.gemstone.gemfire.internal.cache.LocalRegion.put(LocalRegion.java:1655) at com.gemstone.gemfire.internal.cache.AbstractRegion.put(AbstractRegion.java:288) at com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf(PersistentRVVRecoveryDUnitTest.java:824) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.jav ...[truncated 404278 chars]... o 2016/07/27 08:22:52.187 PDT <unicast receiver,venezuela-14080> tid=0x6ec] received new view: View[venezuela(12353:locator)<ec><v0>:1025|79] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12414)<ec><v77>:1026{lead}, venezuela(12418)<ec><v78>:1028, venezuela(12422)<ec><v79>:1029] [vm_1]old view is: View[venezuela(12353:locator)<ec><v0>:1025|78] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12414)<ec><v77>:1026{lead}, venezuela(12418)<ec><v78>:1028] [vm_0][info 2016/07/27 08:22:52.188 PDT <View Message Processor> tid=0x640] Membership: Processing addition < venezuela(12422)<ec><v79>:1029 > [vm_0][info 2016/07/27 08:22:52.188 PDT <View Message Processor> tid=0x640] Admitting member <venezuela(12422)<ec><v79>:1029>. Now there are 4 non-admin member(s). [vm_1][info 2016/07/27 08:22:52.188 PDT <View Message Processor> tid=0x70a] Membership: Processing addition < venezuela(12422)<ec><v79>:1029 > [vm_1][info 2016/07/27 08:22:52.188 PDT <View Message Processor> tid=0x70a] Admitting member <venezuela(12422)<ec><v79>:1029>. Now there are 4 non-admin member(s). [locator][info 2016/07/27 08:22:52.187 PDT <View Message Processor> tid=0x33] Admitting member <venezuela(12422)<ec><v79>:1029>. Now there are 4 non-admin member(s). [locator][info 2016/07/27 08:22:52.191 PDT <Pooled High Priority Message Processor 2> tid=0x47] Member venezuela(12422)<ec><v79>:1029 is equivalent or in the same redundancy zone. [vm_1][info 2016/07/27 08:22:52.192 PDT <Pooled High Priority Message Processor 1> tid=0x704] Member venezuela(12422)<ec><v79>:1029 is equivalent or in the same redundancy zone. [vm_0][info 2016/07/27 08:22:52.194 PDT <Pooled High Priority Message Processor 1> tid=0x639] Member venezuela(12422)<ec><v79>:1029 is equivalent or in the same redundancy zone. [vm_2][info 2016/07/27 08:22:52.196 PDT <P2P message reader for venezuela(12353:locator)<ec><v0>:1025 shared unordered uid=69 port=33472> tid=0x229] Member venezuela(12353:locator)<ec><v0>:1025 is equivalent or in the same redundancy zone. [vm_2][info 2016/07/27 08:22:52.197 PDT <P2P message reader for venezuela(12414)<ec><v77>:1026 shared unordered uid=102 port=33474> tid=0x22b] Member venezuela(12414)<ec><v77>:1026 is equivalent or in the same redundancy zone. [vm_2][info 2016/07/27 08:22:52.197 PDT <P2P message reader for venezuela(12418)<ec><v78>:1028 shared unordered uid=97 port=33473> tid=0x22a] Member venezuela(12418)<ec><v78>:1028 is equivalent or in the same redundancy zone. [vm_2][info 2016/07/27 08:22:52.209 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initializing region _monitoringRegion_10.118.32.90<v79>1029 [vm_2][info 2016/07/27 08:22:52.211 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initialization of region _monitoringRegion_10.118.32.90<v79>1029 completed [vm_2][info 2016/07/27 08:22:52.215 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [vm_2][info 2016/07/27 08:22:52.216 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initializing region PdxTypes [vm_2][info 2016/07/27 08:22:52.221 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Region PdxTypes requesting initial image from venezuela(12414)<ec><v77>:1026 [vm_2][info 2016/07/27 08:22:52.222 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] PdxTypes is done getting image from venezuela(12414)<ec><v77>:1026. isDeltaGII is false [vm_2][info 2016/07/27 08:22:52.222 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initialization of region PdxTypes completed [vm_2][info 2016/07/27 08:22:52.229 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Created disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id d622de9692114548-927ae2095ddda5f8 [vm_2][info 2016/07/27 08:22:52.230 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] recovery region initialization took 0 ms [vm_2][info 2016/07/27 08:22:52.232 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Created oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_2][info 2016/07/27 08:22:52.232 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Created oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_2][info 2016/07/27 08:22:52.233 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion [vm_2][info 2016/07/27 08:22:52.239 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion requesting initial image from venezuela(12418)<ec><v78>:1028 [vm_2][info 2016/07/27 08:22:52.241 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion is done getting image from venezuela(12418)<ec><v78>:1028. isDeltaGII is false [vm_2][info 2016/07/27 08:22:52.241 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion initialized persistent id: venezuela.gemstone.com/10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/2 created at timestamp 1469632972233 version 0 diskStoreId d622de9692114548-927ae2095ddda5f8 name with data from venezuela(12418)<ec><v78>:1028. [vm_2][info 2016/07/27 08:22:52.241 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed [vm_2][info 2016/07/27 08:22:52.243 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" (took 383 ms) [vm_0][info 2016/07/27 08:22:52.244 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" [vm_0][info 2016/07/27 08:22:52.252 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" (took 7 ms) [vm_1][info 2016/07/27 08:22:52.253 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" [vm_1][info 2016/07/27 08:22:52.263 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" (took 9 ms) [vm_2][info 2016/07/27 08:22:52.263 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" [vm_2][info 2016/07/27 08:22:52.273 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" (took 8 ms) [vm_1][info 2016/07/27 08:22:52.273 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$21.run with 0 args on object: "destroy" [vm_1][info 2016/07/27 08:22:52.275 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$21.run with 0 args on object: "destroy" (took 1 ms) [vm_0][info 2016/07/27 08:22:52.276 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$21.run with 0 args on object: "destroy" [vm_0][info 2016/07/27 08:22:52.277 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$21.run with 0 args on object: "destroy" (took 1 ms) [vm_0][info 2016/07/27 08:22:52.278 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_0][info 2016/07/27 08:22:52.278 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: [B@6287740d [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_1][info 2016/07/27 08:22:52.279 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_1][info 2016/07/27 08:22:52.279 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: [B@3d9fd327 [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_2][info 2016/07/27 08:22:52.280 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_2][info 2016/07/27 08:22:52.280 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: [B@7178467d [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_2][info 2016/07/27 08:22:52.280 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" [vm_2][info 2016/07/27 08:22:52.282 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] GemFireCache[id = 1372605178; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:52 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_2][info 2016/07/27 08:22:54.071 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_2][info 2016/07/27 08:22:54.076 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" (took 1795 ms) [vm_1][info 2016/07/27 08:22:54.077 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" [vm_1][info 2016/07/27 08:22:54.079 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] GemFireCache[id = 189009256; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:51 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_1][info 2016/07/27 08:22:54.089 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.092 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" (took 14 ms) [vm_0][info 2016/07/27 08:22:54.093 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" [vm_0][info 2016/07/27 08:22:54.095 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] GemFireCache[id = 1594119895; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:51 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_0][info 2016/07/27 08:22:54.104 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.106 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" (took 13 ms) [vm_0][info 2016/07/27 08:22:54.107 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" [vm_0][info 2016/07/27 08:22:54.113 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initializing region _monitoringRegion_10.118.32.90<v77>1026 [vm_0][info 2016/07/27 08:22:54.114 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initialization of region _monitoringRegion_10.118.32.90<v77>1026 completed [vm_0][info 2016/07/27 08:22:54.116 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [vm_0][info 2016/07/27 08:22:54.117 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initializing region PdxTypes [vm_0][info 2016/07/27 08:22:54.119 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initialization of region PdxTypes completed [vm_0][info 2016/07/27 08:22:54.120 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 68f3eb6a1a354b9a-9ca04f3f6513b7df [vm_0][info 2016/07/27 08:22:54.121 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/0/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.121 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/0/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.122 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] recovery oplog load took 1 ms [vm_0][info 2016/07/27 08:22:54.122 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.123 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.123 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] recovery region initialization took 1 ms [vm_0][info 2016/07/27 08:22:54.124 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion [vm_0][info 2016/07/27 08:22:54.126 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Region /PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion recovered from the local disk. Old persistent ID: /10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/0 created at timestamp 1469632971474 version 0 diskStoreId 68f3eb6a1a354b9a-9ca04f3f6513b7df name , new persistent ID venezuela.gemstone.com/10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/0 created at timestamp 1469632974123 version 0 diskStoreId 68f3eb6a1a354b9a-9ca04f3f6513b7df name [vm_0][info 2016/07/27 08:22:54.127 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed [vm_0][info 2016/07/27 08:22:54.128 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" (took 20 ms) [vm_0][info 2016/07/27 08:22:54.128 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_0][info 2016/07/27 08:22:54.128 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: [B@74a68ea6 [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_0][info 2016/07/27 08:22:54.129 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" [vm_0][info 2016/07/27 08:22:54.129 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$19.run with 0 args on object: "createData" (took 0 ms) [vm_0][info 2016/07/27 08:22:54.130 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_0][info 2016/07/27 08:22:54.130 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: [B@8b08803 [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_0][info 2016/07/27 08:22:54.130 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$23.call with 0 args on object: "getRVV" [vm_0][info 2016/07/27 08:22:54.130 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: [B@53e38bf3 [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$23.call with 0 args on object: "getRVV" (took 0 ms) [vm_1][info 2016/07/27 08:22:54.132 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" [vm_1][info 2016/07/27 08:22:54.137 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region _monitoringRegion_10.118.32.90<v78>1028 [vm_1][info 2016/07/27 08:22:54.138 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region _monitoringRegion_10.118.32.90<v78>1028 completed [vm_1][info 2016/07/27 08:22:54.140 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [vm_1][info 2016/07/27 08:22:54.141 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region PdxTypes [vm_1][info 2016/07/27 08:22:54.145 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Region PdxTypes requesting initial image from venezuela(12414)<ec><v77>:1026 [vm_1][info 2016/07/27 08:22:54.145 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] PdxTypes is done getting image from venezuela(12414)<ec><v77>:1026. isDeltaGII is false [vm_1][info 2016/07/27 08:22:54.146 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region PdxTypes completed [vm_1][info 2016/07/27 08:22:54.147 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 521556444b114433-894e0052e0d0d7b6 [vm_1][info 2016/07/27 08:22:54.147 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.148 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.148 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] recovery oplog load took 1 ms [vm_1][info 2016/07/27 08:22:54.149 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.149 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.150 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] recovery region initialization took 2 ms [vm_1][info 2016/07/27 08:22:54.151 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion [vm_1][info 2016/07/27 08:22:54.163 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion requesting initial image from venezuela(12414)<ec><v77>:1026 [vm_1][info 2016/07/27 08:22:54.165 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion is done getting image from venezuela(12414)<ec><v77>:1026. isDeltaGII is true [vm_1][info 2016/07/27 08:22:54.165 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion initialized persistent id: venezuela.gemstone.com/10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1 created at timestamp 1469632974150 version 0 diskStoreId 521556444b114433-894e0052e0d0d7b6 name with data from venezuela(12414)<ec><v77>:1026. [vm_1][info 2016/07/27 08:22:54.166 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed [vm_1][info 2016/07/27 08:22:54.168 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" (took 35 ms) [vm_1][info 2016/07/27 08:22:54.169 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_1][info 2016/07/27 08:22:54.169 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: [B@26de7ab4 [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_1][info 2016/07/27 08:22:54.170 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$23.call with 0 args on object: "getRVV" [vm_1][info 2016/07/27 08:22:54.170 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: [B@4a7865c3 [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$23.call with 0 args on object: "getRVV" (took 0 ms) [vm_0][info 2016/07/27 08:22:54.171 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" [vm_0][info 2016/07/27 08:22:54.172 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] GemFireCache[id = 1640756305; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:54 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_0][info 2016/07/27 08:22:54.183 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Created oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_0][info 2016/07/27 08:22:54.187 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" (took 16 ms) [vm_1][info 2016/07/27 08:22:54.188 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" [vm_1][info 2016/07/27 08:22:54.189 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] GemFireCache[id = 196827383; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:54 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_1][info 2016/07/27 08:22:54.196 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.201 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$4.run with 0 args on object: "close cache" (took 12 ms) [vm_1][info 2016/07/27 08:22:54.203 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" [vm_1][info 2016/07/27 08:22:54.214 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region _monitoringRegion_10.118.32.90<v78>1028 [vm_1][info 2016/07/27 08:22:54.215 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region _monitoringRegion_10.118.32.90<v78>1028 completed [vm_1][info 2016/07/27 08:22:54.218 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] The cache has been created with "use-cluster-configuration=false". It will not receive any cluster configuration [vm_1][info 2016/07/27 08:22:54.218 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region PdxTypes [vm_1][info 2016/07/27 08:22:54.219 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region PdxTypes completed [vm_1][info 2016/07/27 08:22:54.220 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 521556444b114433-894e0052e0d0d7b6 [vm_1][info 2016/07/27 08:22:54.220 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#2 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_2.drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.221 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.221 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#2 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_2.krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.221 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Recovering oplog#1 /venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1/BACKUPPersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion_1.krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.222 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] recovery oplog load took 2 ms [vm_1][info 2016/07/27 08:22:54.222 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.223 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Created oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.223 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] recovery region initialization took 1 ms [vm_1][info 2016/07/27 08:22:54.224 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion [vm_1][info 2016/07/27 08:22:54.226 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Region /PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion recovered from the local disk. Old persistent ID: /10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1 created at timestamp 1469632974150 version 0 diskStoreId 521556444b114433-894e0052e0d0d7b6 name , new persistent ID venezuela.gemstone.com/10.118.32.90:/venezuela1/users/build/jenkins/blds/workspace/Geode_develop_DistributedTests/geode-core/build/distributedTest/diskDir-testRecoveryWithKRF/1 created at timestamp 1469632974223 version 0 diskStoreId 521556444b114433-894e0052e0d0d7b6 name [vm_1][info 2016/07/27 08:22:54.226 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed [vm_1][info 2016/07/27 08:22:54.227 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentReplicatedTestBase$7.run with 0 args on object: "Create persistent region" (took 23 ms) [vm_1][info 2016/07/27 08:22:54.228 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_1][info 2016/07/27 08:22:54.228 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: [B@3706224 [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_1][info 2016/07/27 08:22:54.229 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" [vm_1][info 2016/07/27 08:22:54.229 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: [B@3d41da06 [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRVVRecoveryDUnitTest$22.call with 0 args on object: "getRVV" (took 0 ms) [vm_0][info 2016/07/27 08:22:54.230 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195@310e441b [vm_0][info 2016/07/27 08:22:54.230 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$9/72500195@310e441b (took 0 ms) [vm_1][info 2016/07/27 08:22:54.231 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456@72df2354 [vm_1][info 2016/07/27 08:22:54.231 PDT <Idle OplogCompactor> tid=0x729] Closing oplog#2 early since it is empty. It is for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.233 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] GemFireCache[id = 349580945; isClosing = true; isShutDownAll = false; created = Wed Jul 27 08:22:54 PDT 2016; server = false; copyOnRead = false; lockLease = 120; lockTimeout = 60]: Now closing. [vm_1][info 2016/07/27 08:22:54.234 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.234 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.235 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.235 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.235 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.235 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.237 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.237 PDT <Oplog Delete Task> tid=0x72a] Deleted oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. [vm_1][info 2016/07/27 08:22:54.239 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$8/949738456@72df2354 (took 7 ms) [vm_2][info 2016/07/27 08:22:54.239 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286@17d31ca3 [vm_2][info 2016/07/27 08:22:54.240 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/1504845286@17d31ca3 (took 0 ms) [vm_3][info 2016/07/27 08:22:54.240 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163@2e3019b0 [vm_3][info 2016/07/27 08:22:54.241 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163.run with 0 args on object: com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$4/640281163@2e3019b0 (took 0 ms) [vm_0][info 2016/07/27 08:22:54.247 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_0][info 2016/07/27 08:22:54.247 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_1][info 2016/07/27 08:22:54.248 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_1][info 2016/07/27 08:22:54.248 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_2][info 2016/07/27 08:22:54.249 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_2][info 2016/07/27 08:22:54.249 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_3][info 2016/07/27 08:22:54.249 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args [vm_3][info 2016/07/27 08:22:54.250 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.internal.cache.persistence.PersistentRecoveryOrderDUnitTest.resetAckWaitThreshold with 0 args (took 0 ms) [vm_0][info 2016/07/27 08:22:54.250 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_0][info 2016/07/27 08:22:54.250 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_1][info 2016/07/27 08:22:54.251 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_1][info 2016/07/27 08:22:54.251 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_2][info 2016/07/27 08:22:54.252 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_2][info 2016/07/27 08:22:54.252 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_3][info 2016/07/27 08:22:54.252 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) [vm_3][info 2016/07/27 08:22:54.252 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownCreationStackGenerator) (took 0 ms) [vm_0][info 2016/07/27 08:22:54.253 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_0][info 2016/07/27 08:22:54.254 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Shutting down DistributionManager venezuela(12414)<ec><v77>:1026. [locator][info 2016/07/27 08:22:54.254 PDT <Pooled High Priority Message Processor 1> tid=0x37] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_1][info 2016/07/27 08:22:54.254 PDT <Pooled High Priority Message Processor 3> tid=0x727] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_1][info 2016/07/27 08:22:54.255 PDT <Pooled High Priority Message Processor 3> tid=0x727] Member at venezuela(12414)<ec><v77>:1026 gracefully left the distributed cache: shutdown message received [vm_2][info 2016/07/27 08:22:54.254 PDT <Pooled High Priority Message Processor 2> tid=0x237] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_2][info 2016/07/27 08:22:54.255 PDT <Pooled High Priority Message Processor 2> tid=0x237] Member at venezuela(12414)<ec><v77>:1026 gracefully left the distributed cache: shutdown message received [locator][info 2016/07/27 08:22:54.254 PDT <Pooled High Priority Message Processor 1> tid=0x37] Member at venezuela(12414)<ec><v77>:1026 gracefully left the distributed cache: shutdown message received [vm_0][info 2016/07/27 08:22:54.357 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Now closing distribution for venezuela(12414)<ec><v77>:1026 [vm_0][info 2016/07/27 08:22:54.357 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Stopping membership services [vm_1][info 2016/07/27 08:22:54.357 PDT <unicast receiver,venezuela-14080> tid=0x6ec] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_2][info 2016/07/27 08:22:54.358 PDT <unicast receiver,venezuela-27526> tid=0x21c] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_0][info 2016/07/27 08:22:54.357 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] GMSHealthMonitor server socket is closed in stopServices(). [vm_0][info 2016/07/27 08:22:54.358 PDT <Geode Failure Detection Server thread 0> tid=0x629] GMSHealthMonitor server thread exiting [vm_0][info 2016/07/27 08:22:54.358 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] GMSHealthMonitor serverSocketExecutor is terminated [locator][info 2016/07/27 08:22:54.358 PDT <unicast receiver,venezuela-31226> tid=0x21] received leave request from venezuela(12414)<ec><v77>:1026 for venezuela(12414)<ec><v77>:1026 [vm_0][info 2016/07/27 08:22:54.363 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] DistributionManager stopped in 109ms. [vm_0][info 2016/07/27 08:22:54.363 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Marking DistributionManager venezuela(12414)<ec><v77>:1026 as closed. [vm_0][info 2016/07/27 08:22:54.363 PDT <RMI TCP Connection(14)-10.118.32.90> tid=0xbe] Got result: null [vm_0] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 110 ms) [vm_1][info 2016/07/27 08:22:54.364 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_1][info 2016/07/27 08:22:54.365 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Shutting down DistributionManager venezuela(12418)<ec><v78>:1028. [locator][info 2016/07/27 08:22:54.365 PDT <Pooled High Priority Message Processor 1> tid=0x37] received leave request from venezuela(12418)<ec><v78>:1028 for venezuela(12418)<ec><v78>:1028 [locator][info 2016/07/27 08:22:54.366 PDT <Pooled High Priority Message Processor 1> tid=0x37] Member at venezuela(12418)<ec><v78>:1028 gracefully left the distributed cache: shutdown message received [vm_2][info 2016/07/27 08:22:54.365 PDT <Pooled High Priority Message Processor 2> tid=0x237] received leave request from venezuela(12418)<ec><v78>:1028 for venezuela(12418)<ec><v78>:1028 [vm_2][info 2016/07/27 08:22:54.366 PDT <Pooled High Priority Message Processor 2> tid=0x237] Member at venezuela(12418)<ec><v78>:1028 gracefully left the distributed cache: shutdown message received [vm_1][info 2016/07/27 08:22:54.468 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Now closing distribution for venezuela(12418)<ec><v78>:1028 [vm_1][info 2016/07/27 08:22:54.468 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Stopping membership services [vm_2][info 2016/07/27 08:22:54.468 PDT <unicast receiver,venezuela-27526> tid=0x21c] received leave request from venezuela(12418)<ec><v78>:1028 for venezuela(12418)<ec><v78>:1028 [locator][info 2016/07/27 08:22:54.469 PDT <unicast receiver,venezuela-31226> tid=0x21] received leave request from venezuela(12418)<ec><v78>:1028 for venezuela(12418)<ec><v78>:1028 [vm_1][info 2016/07/27 08:22:54.469 PDT <Geode Failure Detection Server thread 0> tid=0x6f0] GMSHealthMonitor server thread exiting [vm_1][info 2016/07/27 08:22:54.469 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] GMSHealthMonitor server socket is closed in stopServices(). [vm_1][info 2016/07/27 08:22:54.469 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] GMSHealthMonitor serverSocketExecutor is terminated [vm_1][info 2016/07/27 08:22:54.472 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] DistributionManager stopped in 107ms. [vm_1][info 2016/07/27 08:22:54.473 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Marking DistributionManager venezuela(12418)<ec><v78>:1028 as closed. [vm_1][info 2016/07/27 08:22:54.473 PDT <RMI TCP Connection(15)-10.118.32.90> tid=0x12] Got result: null [vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 108 ms) [vm_2][info 2016/07/27 08:22:54.474 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_2][info 2016/07/27 08:22:54.474 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Shutting down DistributionManager venezuela(12422)<ec><v79>:1029. [locator][info 2016/07/27 08:22:54.475 PDT <Pooled High Priority Message Processor 1> tid=0x37] received leave request from venezuela(12422)<ec><v79>:1029 for venezuela(12422)<ec><v79>:1029 [locator][info 2016/07/27 08:22:54.475 PDT <Pooled High Priority Message Processor 1> tid=0x37] Member at venezuela(12422)<ec><v79>:1029 gracefully left the distributed cache: shutdown message received [locator][info 2016/07/27 08:22:54.577 PDT <Geode Membership View Creator> tid=0x27] View Creator is processing 5 requests for the next membership view [locator][info 2016/07/27 08:22:54.577 PDT <Geode Membership View Creator> tid=0x27] received new view: View[venezuela(12353:locator)<ec><v0>:1025|80] members: [venezuela(12353:locator)<ec><v0>:1025] shutdown: [venezuela(12418)<ec><v78>:1028, venezuela(12422)<ec><v79>:1029, venezuela(12414)<ec><v77>:1026] [locator]old view is: View[venezuela(12353:locator)<ec><v0>:1025|79] members: [venezuela(12353:locator)<ec><v0>:1025, venezuela(12414)<ec><v77>:1026{lead}, venezuela(12418)<ec><v78>:1028, venezuela(12422)<ec><v79>:1029] [locator][info 2016/07/27 08:22:54.577 PDT <Geode Membership View Creator> tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator)<ec><v0>:1025|80] members: [venezuela(12353:locator)<ec><v0>:1025] shutdown: [venezuela(12418)<ec><v78>:1028, venezuela(12422)<ec><v79>:1029, venezuela(12414)<ec><v77>:1026] [locator][info 2016/07/27 08:22:54.578 PDT <Geode Membership View Creator> tid=0x27] no recipients for new view aside from myself [vm_2][info 2016/07/27 08:22:54.578 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Now closing distribution for venezuela(12422)<ec><v79>:1029 [vm_2][info 2016/07/27 08:22:54.578 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Stopping membership services [locator][info 2016/07/27 08:22:54.579 PDT <unicast receiver,venezuela-31226> tid=0x21] received leave request from venezuela(12422)<ec><v79>:1029 for venezuela(12422)<ec><v79>:1029 [vm_2][info 2016/07/27 08:22:54.579 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] GMSHealthMonitor server socket is closed in stopServices(). [vm_2][info 2016/07/27 08:22:54.579 PDT <Geode Failure Detection Server thread 0> tid=0x220] GMSHealthMonitor server thread exiting [vm_2][info 2016/07/27 08:22:54.579 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] GMSHealthMonitor serverSocketExecutor is terminated [vm_2][info 2016/07/27 08:22:54.582 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] DistributionManager stopped in 108ms. [vm_2][info 2016/07/27 08:22:54.582 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Marking DistributionManager venezuela(12422)<ec><v79>:1029 as closed. [vm_2][info 2016/07/27 08:22:54.582 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 108 ms) [vm_3][info 2016/07/27 08:22:54.583 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) [vm_3][info 2016/07/27 08:22:54.583 PDT <RMI TCP Connection(13)-10.118.32.90> tid=0x12] Got result: null [vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on object: runnable(tearDownVM) (took 0 ms) [locator][info 2016/07/27 08:22:54.584 PDT <RMI TCP Connection(2)-10.118.32.90> tid=0x12] Received method: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019.run with 0 args on object: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019@658426d0 [locator][info 2016/07/27 08:22:54.584 PDT <RMI TCP Connection(2)-10.118.32.90> tid=0x12] Got result: null [locator] from com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019.run with 0 args on object: com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$6/609302019@658426d0 (took 0 ms) {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)