Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id 4F6E5200B64 for ; Tue, 2 Aug 2016 17:31:46 +0200 (CEST) Received: by cust-asf.ponee.io (Postfix) id 4DC21160A76; Tue, 2 Aug 2016 15:31:46 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 98E2C160A65 for ; Tue, 2 Aug 2016 17:31:42 +0200 (CEST) Received: (qmail 51673 invoked by uid 500); 2 Aug 2016 15:31:41 -0000 Mailing-List: contact issues-help@geode.incubator.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@geode.incubator.apache.org Delivered-To: mailing list issues@geode.incubator.apache.org Received: (qmail 51664 invoked by uid 99); 2 Aug 2016 15:31:41 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Aug 2016 15:31:41 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 3D4EFC0B9A for ; Tue, 2 Aug 2016 15:31:41 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -5.446 X-Spam-Level: X-Spam-Status: No, score=-5.446 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, RCVD_IN_DNSWL_HI=-5, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, RP_MATCHES_RCVD=-1.426] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id DrAhzL5NtHch for ; Tue, 2 Aug 2016 15:31:24 +0000 (UTC) Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with SMTP id 8F1BA5F306 for ; Tue, 2 Aug 2016 15:31:21 +0000 (UTC) Received: (qmail 51049 invoked by uid 99); 2 Aug 2016 15:31:20 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Aug 2016 15:31:20 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id 92CC42C0D64 for ; Tue, 2 Aug 2016 15:31:20 +0000 (UTC) Date: Tue, 2 Aug 2016 15:31:20 +0000 (UTC) From: "Bruce Schuchardt (JIRA)" To: issues@geode.incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (GEODE-1711) PersistentRVVRecoveryDUnitTest.testWriteCorrectVersionToKrf MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Tue, 02 Aug 2016 15:31:46 -0000 [ 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 tid=0x27] View Creator is processing 4 requests for the next membership view > [locator][info 2016/07/27 08:22:42.653 PDT tid=0x27] received new view: View[venezuela(12353:locator):1025|62] members: [venezuela(12353:locator):1025] shutdown: [venezuela(12418):1028, venezuela(12414):1026] > [locator]old view is: View[venezuela(12353:locator):1025|61] members: [venezuela(12353:locator):1025, venezuela(12414):1026{lead}, venezuela(12418):1028] > [locator][info 2016/07/27 08:22:42.653 PDT tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator):1025|62] members: [venezuela(12353:locator):1025] shutdown: [venezuela(12418):1028, venezuela(12414):1026] > [locator][info 2016/07/27 08:22:42.653 PDT tid=0x27] no recipients for new view aside from myself > [info 2016/07/27 08:22:42.839 PDT 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 tid=0xa] Starting membership services > [info 2016/07/27 08:22:43.101 PDT tid=0xa] JGroups channel created (took 92ms) > [info 2016/07/27 08:22:43.108 PDT tid=0xa] GemFire P2P Listener started on null > [info 2016/07/27 08:22:43.110 PDT 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 tid=0xa] Attempting to join the distributed system through coordinator venezuela(12353:locator):1025 using address venezuela(12321):1026 > [locator][info 2016/07/27 08:22:43.131 PDT tid=0x21] received join request from venezuela(12321):1026 > [locator][info 2016/07/27 08:22:43.437 PDT tid=0x27] View Creator is processing 1 requests for the next membership view > [locator][info 2016/07/27 08:22:43.437 PDT tid=0x27] preparing new view View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [locator]failure detection ports: 45258 30225 > [locator][info 2016/07/27 08:22:43.441 PDT tid=0x27] finished waiting for responses to view preparation > [locator][info 2016/07/27 08:22:43.441 PDT tid=0x27] received new view: View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [locator]old view is: View[venezuela(12353:locator):1025|62] members: [venezuela(12353:locator):1025] shutdown: [venezuela(12418):1028, venezuela(12414):1026] > [locator][info 2016/07/27 08:22:43.441 PDT tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [locator][info 2016/07/27 08:22:43.442 PDT tid=0x27] sending new view View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [locator]failure detection ports: 45258 30225 > [locator][info 2016/07/27 08:22:43.442 PDT tid=0x33] Membership: Processing addition < venezuela(12321):1026 > > [locator][info 2016/07/27 08:22:43.442 PDT tid=0x33] Admitting member :1026>. Now there are 2 non-admin member(s). > [info 2016/07/27 08:22:43.442 PDT tid=0x9e] received new view: View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > old view is: null > [info 2016/07/27 08:22:43.445 PDT tid=0xa] Finished joining (took 334ms). > [info 2016/07/27 08:22:43.446 PDT tid=0xa] Starting DistributionManager venezuela(12321):1026. (took 562 ms) > [info 2016/07/27 08:22:43.447 PDT tid=0xa] Initial (distribution manager) view = View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [info 2016/07/27 08:22:43.447 PDT tid=0xa] Admitting member :1025>. Now there are 1 non-admin member(s). > [info 2016/07/27 08:22:43.448 PDT tid=0xa] Admitting member :1026>. Now there are 2 non-admin member(s). > [locator][info 2016/07/27 08:22:43.468 PDT tid=0x47] Member venezuela(12321):1026 is equivalent or in the same redundancy zone. > [info 2016/07/27 08:22:43.475 PDT :1025 shared unordered uid=54 port=54835> tid=0xa7] Member venezuela(12353:locator):1025 is equivalent or in the same redundancy zone. > [info 2016/07/27 08:22:43.684 PDT tid=0xa] Initializing region _monitoringRegion_10.118.32.901026 > [info 2016/07/27 08:22:43.691 PDT tid=0xa] Initialization of region _monitoringRegion_10.118.32.901026 completed > [info 2016/07/27 08:22:43.913 PDT 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 tid=0xa] Initializing region PdxTypes > [info 2016/07/27 08:22:43.928 PDT tid=0xa] Initialization of region PdxTypes completed > [info 2016/07/27 08:22:43.952 PDT 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 tid=0xa] Shutting down DistributionManager venezuela(12321):1026. > [locator][info 2016/07/27 08:22:44.002 PDT tid=0x47] received leave request from venezuela(12321):1026 for venezuela(12321):1026 > [locator][info 2016/07/27 08:22:44.002 PDT tid=0x47] Member at venezuela(12321):1026 gracefully left the distributed cache: shutdown message received > [info 2016/07/27 08:22:44.104 PDT tid=0xa] Now closing distribution for venezuela(12321):1026 > [info 2016/07/27 08:22:44.104 PDT tid=0xa] Stopping membership services > [locator][info 2016/07/27 08:22:44.106 PDT tid=0x21] received leave request from venezuela(12321):1026 for venezuela(12321):1026 > [info 2016/07/27 08:22:44.107 PDT tid=0xa] GMSHealthMonitor server socket is closed in stopServices(). > [info 2016/07/27 08:22:44.108 PDT tid=0xa2] GMSHealthMonitor server thread exiting > [info 2016/07/27 08:22:44.108 PDT tid=0xa] GMSHealthMonitor serverSocketExecutor is terminated > [info 2016/07/27 08:22:44.114 PDT tid=0xa] DistributionManager stopped in 114ms. > [info 2016/07/27 08:22:44.114 PDT tid=0xa] Marking DistributionManager venezuela(12321):1026 as closed. > [vm_1][info 2016/07/27 08:22:44.117 PDT 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 tid=0xa] Starting membership services > [info 2016/07/27 08:22:44.150 PDT tid=0xa] JGroups channel created (took 9ms) > [info 2016/07/27 08:22:44.151 PDT tid=0xa] GemFire P2P Listener started on null > [info 2016/07/27 08:22:44.152 PDT 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 tid=0xa] Attempting to join the distributed system through coordinator venezuela(12353:locator):1025 using address venezuela(12321):1026 > [locator][info 2016/07/27 08:22:44.154 PDT tid=0x21] received join request from venezuela(12321):1026 > [locator][info 2016/07/27 08:22:44.357 PDT tid=0x27] View Creator is processing 3 requests for the next membership view > [locator][info 2016/07/27 08:22:44.358 PDT tid=0x27] preparing new view View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > [locator]failure detection ports: 45258 47292 > [locator][info 2016/07/27 08:22:44.359 PDT tid=0x27] finished waiting for responses to view preparation > [locator][info 2016/07/27 08:22:44.359 PDT tid=0x27] received new view: View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > [locator]old view is: View[venezuela(12353:locator):1025|63] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] > [locator][info 2016/07/27 08:22:44.359 PDT tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > [info 2016/07/27 08:22:44.359 PDT tid=0xc6] received new view: View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > old view is: null > [locator][info 2016/07/27 08:22:44.360 PDT tid=0x27] sending new view View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > [locator]failure detection ports: 45258 47292 > [locator][info 2016/07/27 08:22:44.360 PDT tid=0x33] Membership: Processing addition < venezuela(12321):1026 > > [locator][info 2016/07/27 08:22:44.360 PDT tid=0x33] Admitting member :1026>. Now there are 2 non-admin member(s). > [info 2016/07/27 08:22:44.360 PDT tid=0xa] Finished joining (took 208ms). > [info 2016/07/27 08:22:44.361 PDT tid=0xa] Starting DistributionManager venezuela(12321):1026. (took 221 ms) > [info 2016/07/27 08:22:44.361 PDT tid=0xa] Initial (distribution manager) view = View[venezuela(12353:locator):1025|64] members: [venezuela(12353:locator):1025, venezuela(12321):1026{lead}] shutdown: [venezuela(12321):1026] > [info 2016/07/27 08:22:44.361 PDT tid=0xa] Admitting member :1025>. Now there are 1 non-admin member(s). > [info 2016/07/27 08:22:44.361 PDT tid=0xa] Admitting member :1026>. Now there are 2 non-admin member(s). > [locator][info 2016/07/27 08:22:44.364 PDT tid=0x47] Member venezuela(12321):1026 is equivalent or in the same redundancy zone. > [info 2016/07/27 08:22:44.366 PDT :1025 shared unordered uid=55 port=58813> tid=0xcf] Member venezuela(12353:locator):1025 is equivalent or in the same redundancy zone. > [info 2016/07/27 08:22:44.375 PDT tid=0xa] Initializing region _monitoringRegion_10.118.32.901026 > [info 2016/07/27 08:22:44.376 PDT tid=0xa] Initialization of region _monitoringRegion_10.118.32.901026 completed > [info 2016/07/27 08:22:44.381 PDT 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 tid=0xa] Initializing region PdxTypes > [info 2016/07/27 08:22:44.384 PDT tid=0xa] Initialization of region PdxTypes completed > [info 2016/07/27 08:22:44.419 PDT tid=0xa] Created disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion with unique id 9048b6bb98354e5f-8d643eccc5e71544 > [info 2016/07/27 08:22:44.431 PDT tid=0xa] recovery region initialization took 1 ms > [info 2016/07/27 08:22:44.502 PDT tid=0xa] Created oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:44.506 PDT tid=0xa] Created oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [warn 2016/07/27 08:22:44.511 PDT 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 tid=0xa] Initializing region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion > [info 2016/07/27 08:22:44.515 PDT 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 tid=0xa] Initialization of region PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion completed > [info 2016/07/27 08:22:44.525 PDT tid=0xa] DiskAccessException > [info 2016/07/27 08:22:44.526 PDT tid=0xa] DiskAccessException > [info 2016/07/27 08:22:44.526 PDT tid=0xa] DiskAccessException > [vm_0][info 2016/07/27 08:22:44.526 PDT 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 tid=0xbe] DiskAccessException > [vm_0][info 2016/07/27 08:22:44.526 PDT tid=0xbe] DiskAccessException > [vm_0][info 2016/07/27 08:22:44.526 PDT 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 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 tid=0x1ee] DiskAccessException > [vm_1][info 2016/07/27 08:22:44.527 PDT tid=0x1ee] DiskAccessException > [vm_1][info 2016/07/27 08:22:44.527 PDT 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 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 tid=0x12] DiskAccessException > [vm_2][info 2016/07/27 08:22:44.529 PDT tid=0x12] DiskAccessException > [vm_2][info 2016/07/27 08:22:44.529 PDT 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 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 tid=0x12] DiskAccessException > [vm_3][info 2016/07/27 08:22:44.533 PDT tid=0x12] DiskAccessException > [vm_3][info 2016/07/27 08:22:44.533 PDT 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 tid=0xdc] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.412 PDT tid=0xdc] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.417 PDT tid=0xdc] Created oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.417 PDT tid=0xdc] Created oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.421 PDT tid=0xdc] Created oplog#4 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.421 PDT tid=0xdc] Created oplog#4 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.423 PDT tid=0xdc] Created oplog#5 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.424 PDT tid=0xdc] Created oplog#5 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.426 PDT tid=0xdc] Created oplog#6 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.427 PDT tid=0xdc] Created oplog#6 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.430 PDT tid=0xdc] Created oplog#7 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.430 PDT tid=0xdc] Created oplog#7 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.432 PDT tid=0xdc] Created oplog#8 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.433 PDT tid=0xdc] Created oplog#8 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.434 PDT tid=0xdc] Created oplog#9 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.435 PDT tid=0xdc] Created oplog#9 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.437 PDT tid=0xdf] Deleted oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.437 PDT tid=0xdf] Deleted oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.440 PDT tid=0xdd] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion. > [info 2016/07/27 08:22:45.442 PDT tid=0xdd] OplogCompactor for PersistentRVVRecoveryDUnitTest_testWriteCorrectVersionToKrfRegion compaction oplog id(s): oplog#1 > [error 2016/07/27 08:22:45.442 PDT 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 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 tid=0x6ec] received new view: View[venezuela(12353:locator):1025|79] members: [venezuela(12353:locator):1025, venezuela(12414):1026{lead}, venezuela(12418):1028, venezuela(12422):1029] > [vm_1]old view is: View[venezuela(12353:locator):1025|78] members: [venezuela(12353:locator):1025, venezuela(12414):1026{lead}, venezuela(12418):1028] > [vm_0][info 2016/07/27 08:22:52.188 PDT tid=0x640] Membership: Processing addition < venezuela(12422):1029 > > [vm_0][info 2016/07/27 08:22:52.188 PDT tid=0x640] Admitting member :1029>. Now there are 4 non-admin member(s). > [vm_1][info 2016/07/27 08:22:52.188 PDT tid=0x70a] Membership: Processing addition < venezuela(12422):1029 > > [vm_1][info 2016/07/27 08:22:52.188 PDT tid=0x70a] Admitting member :1029>. Now there are 4 non-admin member(s). > [locator][info 2016/07/27 08:22:52.187 PDT tid=0x33] Admitting member :1029>. Now there are 4 non-admin member(s). > [locator][info 2016/07/27 08:22:52.191 PDT tid=0x47] Member venezuela(12422):1029 is equivalent or in the same redundancy zone. > [vm_1][info 2016/07/27 08:22:52.192 PDT tid=0x704] Member venezuela(12422):1029 is equivalent or in the same redundancy zone. > [vm_0][info 2016/07/27 08:22:52.194 PDT tid=0x639] Member venezuela(12422):1029 is equivalent or in the same redundancy zone. > [vm_2][info 2016/07/27 08:22:52.196 PDT :1025 shared unordered uid=69 port=33472> tid=0x229] Member venezuela(12353:locator):1025 is equivalent or in the same redundancy zone. > [vm_2][info 2016/07/27 08:22:52.197 PDT :1026 shared unordered uid=102 port=33474> tid=0x22b] Member venezuela(12414):1026 is equivalent or in the same redundancy zone. > [vm_2][info 2016/07/27 08:22:52.197 PDT :1028 shared unordered uid=97 port=33473> tid=0x22a] Member venezuela(12418):1028 is equivalent or in the same redundancy zone. > [vm_2][info 2016/07/27 08:22:52.209 PDT tid=0x12] Initializing region _monitoringRegion_10.118.32.901029 > [vm_2][info 2016/07/27 08:22:52.211 PDT tid=0x12] Initialization of region _monitoringRegion_10.118.32.901029 completed > [vm_2][info 2016/07/27 08:22:52.215 PDT 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 tid=0x12] Initializing region PdxTypes > [vm_2][info 2016/07/27 08:22:52.221 PDT tid=0x12] Region PdxTypes requesting initial image from venezuela(12414):1026 > [vm_2][info 2016/07/27 08:22:52.222 PDT tid=0x12] PdxTypes is done getting image from venezuela(12414):1026. isDeltaGII is false > [vm_2][info 2016/07/27 08:22:52.222 PDT tid=0x12] Initialization of region PdxTypes completed > [vm_2][info 2016/07/27 08:22:52.229 PDT tid=0x12] Created disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id d622de9692114548-927ae2095ddda5f8 > [vm_2][info 2016/07/27 08:22:52.230 PDT tid=0x12] recovery region initialization took 0 ms > [vm_2][info 2016/07/27 08:22:52.232 PDT tid=0x12] Created oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_2][info 2016/07/27 08:22:52.232 PDT tid=0x12] Created oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_2][info 2016/07/27 08:22:52.233 PDT tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion > [vm_2][info 2016/07/27 08:22:52.239 PDT tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion requesting initial image from venezuela(12418):1028 > [vm_2][info 2016/07/27 08:22:52.241 PDT tid=0x12] PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion is done getting image from venezuela(12418):1028. isDeltaGII is false > [vm_2][info 2016/07/27 08:22:52.241 PDT 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):1028. > [vm_2][info 2016/07/27 08:22:52.241 PDT tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed > [vm_2][info 2016/07/27 08:22:52.243 PDT 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 tid=0x12] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_2][info 2016/07/27 08:22:54.076 PDT 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 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 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 tid=0x12] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.092 PDT 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 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 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 tid=0xbe] Created oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_0][info 2016/07/27 08:22:54.106 PDT 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 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 tid=0xbe] Initializing region _monitoringRegion_10.118.32.901026 > [vm_0][info 2016/07/27 08:22:54.114 PDT tid=0xbe] Initialization of region _monitoringRegion_10.118.32.901026 completed > [vm_0][info 2016/07/27 08:22:54.116 PDT 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 tid=0xbe] Initializing region PdxTypes > [vm_0][info 2016/07/27 08:22:54.119 PDT tid=0xbe] Initialization of region PdxTypes completed > [vm_0][info 2016/07/27 08:22:54.120 PDT tid=0xbe] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 68f3eb6a1a354b9a-9ca04f3f6513b7df > [vm_0][info 2016/07/27 08:22:54.121 PDT 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 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 tid=0xbe] recovery oplog load took 1 ms > [vm_0][info 2016/07/27 08:22:54.122 PDT tid=0xbe] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_0][info 2016/07/27 08:22:54.123 PDT tid=0xbe] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_0][info 2016/07/27 08:22:54.123 PDT tid=0xbe] recovery region initialization took 1 ms > [vm_0][info 2016/07/27 08:22:54.124 PDT tid=0xbe] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion > [vm_0][info 2016/07/27 08:22:54.126 PDT 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 tid=0xbe] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed > [vm_0][info 2016/07/27 08:22:54.128 PDT 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 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 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 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 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 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 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 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 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 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 tid=0x12] Initializing region _monitoringRegion_10.118.32.901028 > [vm_1][info 2016/07/27 08:22:54.138 PDT tid=0x12] Initialization of region _monitoringRegion_10.118.32.901028 completed > [vm_1][info 2016/07/27 08:22:54.140 PDT 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 tid=0x12] Initializing region PdxTypes > [vm_1][info 2016/07/27 08:22:54.145 PDT tid=0x12] Region PdxTypes requesting initial image from venezuela(12414):1026 > [vm_1][info 2016/07/27 08:22:54.145 PDT tid=0x12] PdxTypes is done getting image from venezuela(12414):1026. isDeltaGII is false > [vm_1][info 2016/07/27 08:22:54.146 PDT tid=0x12] Initialization of region PdxTypes completed > [vm_1][info 2016/07/27 08:22:54.147 PDT tid=0x12] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 521556444b114433-894e0052e0d0d7b6 > [vm_1][info 2016/07/27 08:22:54.147 PDT 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 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 tid=0x12] recovery oplog load took 1 ms > [vm_1][info 2016/07/27 08:22:54.149 PDT tid=0x12] Created oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.149 PDT tid=0x12] Created oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.150 PDT tid=0x12] recovery region initialization took 2 ms > [vm_1][info 2016/07/27 08:22:54.151 PDT tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion > [vm_1][info 2016/07/27 08:22:54.163 PDT tid=0x12] Region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion requesting initial image from venezuela(12414):1026 > [vm_1][info 2016/07/27 08:22:54.165 PDT tid=0x12] PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion is done getting image from venezuela(12414):1026. isDeltaGII is true > [vm_1][info 2016/07/27 08:22:54.165 PDT 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):1026. > [vm_1][info 2016/07/27 08:22:54.166 PDT tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed > [vm_1][info 2016/07/27 08:22:54.168 PDT 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 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 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 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 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 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 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 tid=0xbe] Created oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_0][info 2016/07/27 08:22:54.187 PDT 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 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 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 tid=0x12] Created oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.201 PDT 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 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 tid=0x12] Initializing region _monitoringRegion_10.118.32.901028 > [vm_1][info 2016/07/27 08:22:54.215 PDT tid=0x12] Initialization of region _monitoringRegion_10.118.32.901028 completed > [vm_1][info 2016/07/27 08:22:54.218 PDT 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 tid=0x12] Initializing region PdxTypes > [vm_1][info 2016/07/27 08:22:54.219 PDT tid=0x12] Initialization of region PdxTypes completed > [vm_1][info 2016/07/27 08:22:54.220 PDT tid=0x12] Recovered disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion with unique id 521556444b114433-894e0052e0d0d7b6 > [vm_1][info 2016/07/27 08:22:54.220 PDT 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 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 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 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 tid=0x12] recovery oplog load took 2 ms > [vm_1][info 2016/07/27 08:22:54.222 PDT tid=0x12] Created oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.223 PDT tid=0x12] Created oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.223 PDT tid=0x12] recovery region initialization took 1 ms > [vm_1][info 2016/07/27 08:22:54.224 PDT tid=0x12] Initializing region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion > [vm_1][info 2016/07/27 08:22:54.226 PDT 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 tid=0x12] Initialization of region PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion completed > [vm_1][info 2016/07/27 08:22:54.227 PDT 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 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 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 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 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 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 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 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 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 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 tid=0x72a] Deleted oplog#2 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.234 PDT tid=0x72a] Deleted oplog#2 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.235 PDT tid=0x72a] Deleted oplog#2 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.235 PDT tid=0x72a] Deleted oplog#1 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.235 PDT tid=0x72a] Deleted oplog#1 krf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.235 PDT tid=0x72a] Deleted oplog#1 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.237 PDT tid=0x72a] Deleted oplog#3 crf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.237 PDT tid=0x72a] Deleted oplog#3 drf for disk store PersistentRVVRecoveryDUnitTest_testRecoveryWithKRFRegion. > [vm_1][info 2016/07/27 08:22:54.239 PDT 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 tid=0xbe] Shutting down DistributionManager venezuela(12414):1026. > [locator][info 2016/07/27 08:22:54.254 PDT tid=0x37] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_1][info 2016/07/27 08:22:54.254 PDT tid=0x727] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_1][info 2016/07/27 08:22:54.255 PDT tid=0x727] Member at venezuela(12414):1026 gracefully left the distributed cache: shutdown message received > [vm_2][info 2016/07/27 08:22:54.254 PDT tid=0x237] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_2][info 2016/07/27 08:22:54.255 PDT tid=0x237] Member at venezuela(12414):1026 gracefully left the distributed cache: shutdown message received > [locator][info 2016/07/27 08:22:54.254 PDT tid=0x37] Member at venezuela(12414):1026 gracefully left the distributed cache: shutdown message received > [vm_0][info 2016/07/27 08:22:54.357 PDT tid=0xbe] Now closing distribution for venezuela(12414):1026 > [vm_0][info 2016/07/27 08:22:54.357 PDT tid=0xbe] Stopping membership services > [vm_1][info 2016/07/27 08:22:54.357 PDT tid=0x6ec] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_2][info 2016/07/27 08:22:54.358 PDT tid=0x21c] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_0][info 2016/07/27 08:22:54.357 PDT tid=0xbe] GMSHealthMonitor server socket is closed in stopServices(). > [vm_0][info 2016/07/27 08:22:54.358 PDT tid=0x629] GMSHealthMonitor server thread exiting > [vm_0][info 2016/07/27 08:22:54.358 PDT tid=0xbe] GMSHealthMonitor serverSocketExecutor is terminated > [locator][info 2016/07/27 08:22:54.358 PDT tid=0x21] received leave request from venezuela(12414):1026 for venezuela(12414):1026 > [vm_0][info 2016/07/27 08:22:54.363 PDT tid=0xbe] DistributionManager stopped in 109ms. > [vm_0][info 2016/07/27 08:22:54.363 PDT tid=0xbe] Marking DistributionManager venezuela(12414):1026 as closed. > [vm_0][info 2016/07/27 08:22:54.363 PDT 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 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 tid=0x12] Shutting down DistributionManager venezuela(12418):1028. > [locator][info 2016/07/27 08:22:54.365 PDT tid=0x37] received leave request from venezuela(12418):1028 for venezuela(12418):1028 > [locator][info 2016/07/27 08:22:54.366 PDT tid=0x37] Member at venezuela(12418):1028 gracefully left the distributed cache: shutdown message received > [vm_2][info 2016/07/27 08:22:54.365 PDT tid=0x237] received leave request from venezuela(12418):1028 for venezuela(12418):1028 > [vm_2][info 2016/07/27 08:22:54.366 PDT tid=0x237] Member at venezuela(12418):1028 gracefully left the distributed cache: shutdown message received > [vm_1][info 2016/07/27 08:22:54.468 PDT tid=0x12] Now closing distribution for venezuela(12418):1028 > [vm_1][info 2016/07/27 08:22:54.468 PDT tid=0x12] Stopping membership services > [vm_2][info 2016/07/27 08:22:54.468 PDT tid=0x21c] received leave request from venezuela(12418):1028 for venezuela(12418):1028 > [locator][info 2016/07/27 08:22:54.469 PDT tid=0x21] received leave request from venezuela(12418):1028 for venezuela(12418):1028 > [vm_1][info 2016/07/27 08:22:54.469 PDT tid=0x6f0] GMSHealthMonitor server thread exiting > [vm_1][info 2016/07/27 08:22:54.469 PDT tid=0x12] GMSHealthMonitor server socket is closed in stopServices(). > [vm_1][info 2016/07/27 08:22:54.469 PDT tid=0x12] GMSHealthMonitor serverSocketExecutor is terminated > [vm_1][info 2016/07/27 08:22:54.472 PDT tid=0x12] DistributionManager stopped in 107ms. > [vm_1][info 2016/07/27 08:22:54.473 PDT tid=0x12] Marking DistributionManager venezuela(12418):1028 as closed. > [vm_1][info 2016/07/27 08:22:54.473 PDT 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 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 tid=0x12] Shutting down DistributionManager venezuela(12422):1029. > [locator][info 2016/07/27 08:22:54.475 PDT tid=0x37] received leave request from venezuela(12422):1029 for venezuela(12422):1029 > [locator][info 2016/07/27 08:22:54.475 PDT tid=0x37] Member at venezuela(12422):1029 gracefully left the distributed cache: shutdown message received > [locator][info 2016/07/27 08:22:54.577 PDT tid=0x27] View Creator is processing 5 requests for the next membership view > [locator][info 2016/07/27 08:22:54.577 PDT tid=0x27] received new view: View[venezuela(12353:locator):1025|80] members: [venezuela(12353:locator):1025] shutdown: [venezuela(12418):1028, venezuela(12422):1029, venezuela(12414):1026] > [locator]old view is: View[venezuela(12353:locator):1025|79] members: [venezuela(12353:locator):1025, venezuela(12414):1026{lead}, venezuela(12418):1028, venezuela(12422):1029] > [locator][info 2016/07/27 08:22:54.577 PDT tid=0x27] Peer locator received new membership view: View[venezuela(12353:locator):1025|80] members: [venezuela(12353:locator):1025] shutdown: [venezuela(12418):1028, venezuela(12422):1029, venezuela(12414):1026] > [locator][info 2016/07/27 08:22:54.578 PDT tid=0x27] no recipients for new view aside from myself > [vm_2][info 2016/07/27 08:22:54.578 PDT tid=0x12] Now closing distribution for venezuela(12422):1029 > [vm_2][info 2016/07/27 08:22:54.578 PDT tid=0x12] Stopping membership services > [locator][info 2016/07/27 08:22:54.579 PDT tid=0x21] received leave request from venezuela(12422):1029 for venezuela(12422):1029 > [vm_2][info 2016/07/27 08:22:54.579 PDT tid=0x12] GMSHealthMonitor server socket is closed in stopServices(). > [vm_2][info 2016/07/27 08:22:54.579 PDT tid=0x220] GMSHealthMonitor server thread exiting > [vm_2][info 2016/07/27 08:22:54.579 PDT tid=0x12] GMSHealthMonitor serverSocketExecutor is terminated > [vm_2][info 2016/07/27 08:22:54.582 PDT tid=0x12] DistributionManager stopped in 108ms. > [vm_2][info 2016/07/27 08:22:54.582 PDT tid=0x12] Marking DistributionManager venezuela(12422):1029 as closed. > [vm_2][info 2016/07/27 08:22:54.582 PDT 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 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 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 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 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)