[ https://issues.apache.org/jira/browse/GEODE-1711?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Bruce Schuchardt updated GEODE-1711: ------------------------------------ Component/s: persistence > PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf > ----------------------------------------------------------- > > Key: GEODE-1711 > URL: https://issues.apache.org/jira/browse/GEODE-1711 > Project: Geode > Issue Type: Bug > Components: persistence > Reporter: Kevin Duling > Labels: CI > > 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)