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