[
https://issues.apache.org/jira/browse/GEODE-5791?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16630755#comment-16630755
]
Mark Hanson edited comment on GEODE-5791 at 9/27/18 5:15 PM:
-------------------------------------------------------------
{{Log excerpt}}{{[setup] START TEST
DistributedAckRegionCCEDUnitTest.testEntryVersionRollover [vm0] [info
2018/09/27 06:22:36.691 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Received method:
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$8.run with 0 args on
object: "Create Region" [vm0] distributed system properties:
{statistic-sampling-enabled=true, mcast-port=0, log-level=info,
validate-serializable-objects=true, disable-auto-reconnect=true,
enable-cluster-configuration=false,
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue,
locators=localhost[43291], conserve-sockets=false,
use-cluster-configuration=false} [vm0] [info 2018/09/27 06:22:36.698 UTC <RMI
TCP Connection(1)-172.17.0.5> tid=0x20] Startup Configuration: [vm0] ###
GemFire Properties defined with system property ### [vm0]
validate-serializable-objects=true [vm0] ### GemFire Properties defined with
api ### [vm0] conserve-sockets=false [vm0] disable-auto-reconnect=true [vm0]
enable-cluster-configuration=false [vm0] locators=localhost[43291] [vm0]
log-level=info [vm0] mcast-port=0 [vm0]
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue
[vm0] statistic-sampling-enabled=true [vm0] use-cluster-configuration=false
[vm0] ### GemFire Properties using default values ### [vm0]
ack-severe-alert-threshold=0 [vm0] ack-wait-threshold=15 [vm0]
archive-disk-space-limit=0 [vm0] archive-file-size-limit=0 [vm0]
async-distribution-timeout=0 [vm0] async-max-queue-size=8 [vm0]
async-queue-timeout=60000 [vm0] bind-address= [vm0] cache-xml-file=cache.xml
[vm0] cluster-configuration-dir= [vm0] cluster-ssl-ciphers=any [vm0]
cluster-ssl-enabled=false [vm0] cluster-ssl-keystore= [vm0]
cluster-ssl-keystore-password= [vm0] cluster-ssl-keystore-type= [vm0]
cluster-ssl-protocols=any [vm0] cluster-ssl-require-authentication=true [vm0]
cluster-ssl-truststore= [vm0] cluster-ssl-truststore-password= [vm0]
conflate-events=server [vm0] delta-propagation=true [vm0]
deploy-working-dir=/tmp/build/ae3c03f4/built-gemfire/test/geode/geode-core/build/distributedTest149/dunit/vm0
[vm0] disable-tcp=false [vm0] distributed-system-id=-1 [vm0]
distributed-transactions=false [vm0] durable-client-id= [vm0]
durable-client-timeout=300 [vm0] enable-network-partition-detection=true [vm0]
enable-time-statistics=false [vm0] enforce-unique-host=false [vm0]
gateway-ssl-ciphers=any [vm0] gateway-ssl-enabled=false [vm0]
gateway-ssl-keystore= [vm0] gateway-ssl-keystore-password= [vm0]
gateway-ssl-keystore-type= [vm0] gateway-ssl-protocols=any [vm0]
gateway-ssl-require-authentication=true [vm0] gateway-ssl-truststore= [vm0]
gateway-ssl-truststore-password= [vm0] groups= [vm0] http-service-bind-address=
[vm0] http-service-port=7070 [vm0] http-service-ssl-ciphers=any [vm0]
http-service-ssl-enabled=false [vm0] http-service-ssl-keystore= [vm0]
http-service-ssl-keystore-password= [vm0] http-service-ssl-keystore-type= [vm0]
http-service-ssl-protocols=any [vm0]
http-service-ssl-require-authentication=false [vm0]
http-service-ssl-truststore= [vm0] http-service-ssl-truststore-password= [vm0]
jmx-manager=false [vm0] jmx-manager-access-file= [vm0]
jmx-manager-bind-address= [vm0] jmx-manager-hostname-for-clients= [vm0]
jmx-manager-http-port=7070 [vm0] jmx-manager-password-file= [vm0]
jmx-manager-port=1099 [vm0] jmx-manager-ssl-ciphers=any [vm0]
jmx-manager-ssl-enabled=false [vm0] jmx-manager-ssl-keystore= [vm0]
jmx-manager-ssl-keystore-password= [vm0] jmx-manager-ssl-keystore-type= [vm0]
jmx-manager-ssl-protocols=any [vm0] jmx-manager-ssl-require-authentication=true
[vm0] jmx-manager-ssl-truststore= [vm0] jmx-manager-ssl-truststore-password=
[vm0] jmx-manager-start=false [vm0] jmx-manager-update-rate=2000 [vm0]
load-cluster-configuration-from-dir=false [vm0] locator-wait-time=0 [vm0]
lock-memory=false [vm0] log-disk-space-limit=0 [vm0] log-file= [vm0]
log-file-size-limit=0 [vm0] max-num-reconnect-tries=3 [vm0]
max-wait-time-reconnect=60000 [vm0] mcast-address=239.192.81.1 [vm0]
mcast-flow-control=1048576, 0.25, 5000 [vm0] mcast-recv-buffer-size=1048576
[vm0] mcast-send-buffer-size=65535 [vm0] mcast-ttl=32 [vm0] member-timeout=5000
[vm0] membership-port-range=32769-61000 [vm0] memcached-bind-address= [vm0]
memcached-port=0 [vm0] memcached-protocol=ASCII [vm0] name= [vm0]
off-heap-memory-size= [vm0] redis-bind-address= [vm0] redis-password= [vm0]
redis-port=0 [vm0] redundancy-zone= [vm0] remote-locators= [vm0]
remove-unresponsive-client=false [vm0] roles= [vm0] security-client-accessor=
[vm0] security-client-accessor-pp= [vm0] security-client-auth-init= [vm0]
security-client-authenticator= [vm0] security-client-dhalgo= [vm0]
security-log-file= [vm0] security-log-level=config [vm0] security-manager=
[vm0] security-peer-auth-init= [vm0] security-peer-authenticator= [vm0]
security-peer-verifymember-timeout=1000 [vm0] security-post-processor= [vm0]
security-udp-dhalgo= [vm0] server-bind-address= [vm0] server-ssl-ciphers=any
[vm0] server-ssl-enabled=false [vm0] server-ssl-keystore= [vm0]
server-ssl-keystore-password= [vm0] server-ssl-keystore-type= [vm0]
server-ssl-protocols=any [vm0] server-ssl-require-authentication=true [vm0]
server-ssl-truststore= [vm0] server-ssl-truststore-password= [vm0]
socket-buffer-size=32768 [vm0] socket-lease-time=60000 [vm0] ssl-ciphers=any
[vm0] ssl-cluster-alias= [vm0] ssl-default-alias= [vm0] ssl-enabled-components=
[vm0] ssl-endpoint-identification-enabled=false [vm0] ssl-gateway-alias= [vm0]
ssl-jmx-alias= [vm0] ssl-keystore= [vm0] ssl-keystore-password= [vm0]
ssl-keystore-type= [vm0] ssl-locator-alias= [vm0] ssl-protocols=any [vm0]
ssl-require-authentication=true [vm0] ssl-server-alias= [vm0] ssl-truststore=
[vm0] ssl-truststore-password= [vm0] ssl-truststore-type= [vm0] ssl-web-alias=
[vm0] ssl-web-require-authentication=false [vm0] start-dev-rest-api=false [vm0]
start-locator= [vm0] statistic-archive-file= [vm0] statistic-sample-rate=1000
[vm0] tcp-port=0 [vm0] thread-monitor-enabled=true [vm0]
thread-monitor-interval-ms=60000 [vm0] thread-monitor-time-limit-ms=30000 [vm0]
udp-fragment-size=60000 [vm0] udp-recv-buffer-size=1048576 [vm0]
udp-send-buffer-size=65535 [vm0] user-command-packages= [vm0] [info 2018/09/27
06:22:36.699 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20] initializing
InternalDataSerializer with 0 services [vm0] [info 2018/09/27 06:22:36.704 UTC
<RMI TCP Connection(1)-172.17.0.5> tid=0x20] setting a serialization filter
containing
java.**;javax.management.**;javax.print.attribute.EnumSyntax;antlr.**;org.apache.commons.modeler.AttributeInfo;org.apache.commons.modeler.FeatureInfo;org.apache.commons.modeler.ManagedBean;org.apache.geode.distributed.internal.DistributionConfigSnapshot;org.apache.geode.distributed.internal.RuntimeDistributionConfigImpl;org.apache.geode.distributed.internal.DistributionConfigImpl;org.apache.geode.distributed.internal.membership.InternalDistributedMember;org.apache.geode.internal.cache.persistence.PersistentMemberID;org.apache.geode.internal.cache.persistence.DiskStoreID;org.apache.geode.internal.cache.tier.sockets.VersionedObjectList;org.apache.shiro.*;org.apache.shiro.authz.*;org.apache.shiro.authc.*;org.apache.logging.log4j.Level;org.apache.logging.log4j.spi.StandardLevel;com.sun.proxy.$Proxy*;com.healthmarketscience.rmiio.RemoteInputStream;javax.rmi.ssl.SslRMIClientSocketFactory;javax.net.ssl.SSLHandshakeException;javax.net.ssl.SSLException;sun.security.validator.ValidatorException;sun.security.provider.certpath.SunCertPathBuilderException;org.apache.geode.modules.util.SessionCustomExpiry;org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue;Unable
to render embedded object: File (22:36.708 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] [ThreadsMonitor] a New Monitor object and
process were created. [vm0] [info 2018/09/27 06:22:36.708 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Serial Queue info : THROTTLE_PERCENT: 0.75
SERIAL_QUEUE_BYTE_LIMIT :41943040 SERIAL_QUEUE_THROTTLE :31457280
TOTAL_SERIAL_QUEUE_BYTE_LIMIT :83886080 TOTAL_SERIAL_QUEUE_THROTTLE :31457280
SERIAL_QUEUE_SIZE_LIMIT :20000 SERIAL_QUEUE_SIZE_THROTTLE :15000 [vm0] [info
2018/09/27 06:22:36.710 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Starting membership services [vm0] [info 2018/09/27 06:22:36.721 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] JGroups channel created (took 10ms) [vm0]
[info 2018/09/27 06:22:36.722 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
GemFire P2P Listener started on /172.17.0.5:53693 [vm0] [info 2018/09/27
06:22:36.723 UTC <Geode Failure Detection Server thread 0> tid=0xb9] Started
failure detection server thread on /172.17.0.5:53614. [vm0] [info 2018/09/27
06:22:36.726 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20] Attempting to
join the distributed system through coordinator
172.17.0.5(87:locator)<ec><v0>:32769 using address 172.17.0.5(286):32770
[locator] [info 2018/09/27 06:22:36.727 UTC <unicast
receiver,0c20036cd386-40784> tid=0x30] Received a join request from
0c20036cd386(286):32770 [locator] [info 2018/09/27 06:22:37.028 UTC <Geode
Membership View Creator> tid=0x37] View Creator is processing 1 requests for
the next membership view [locator] [info 2018/09/27 06:22:37.029 UTC <Geode
Membership View Creator> tid=0x37] preparing new view
View[0c20036cd386(87:locator)<ec><v0>:32769) not found.* [info 2018/09/27
06:22:38.263 UTC <Test worker> tid=0x19] [ThreadsMonitor] a New Monitor object
and process were created. [info 2018/09/27 06:22:38.264 UTC <Test worker>
tid=0x19] Serial Queue info : THROTTLE_PERCENT: 0.75 SERIAL_QUEUE_BYTE_LIMIT
:41943040 SERIAL_QUEUE_THROTTLE :31457280 TOTAL_SERIAL_QUEUE_BYTE_LIMIT
:83886080 TOTAL_SERIAL_QUEUE_THROTTLE :31457280 SERIAL_QUEUE_SIZE_LIMIT :20000
SERIAL_QUEUE_SIZE_THROTTLE :15000 [info 2018/09/27 06:22:38.446 UTC <Test
worker> tid=0x19] Starting membership services [info 2018/09/27 06:22:38.535
UTC <Test worker> tid=0x19] JGroups channel created (took 88ms) [info
2018/09/27 06:22:38.549 UTC <Test worker> tid=0x19] GemFire P2P Listener
started on /172.17.0.5:59424 [info 2018/09/27 06:22:38.551 UTC <Geode Failure
Detection Server thread 0> tid=0x55] Started failure detection server thread on
/172.17.0.5:59098. [info 2018/09/27 06:22:38.570 UTC <Test worker> tid=0x19]
Attempting to join the distributed system through coordinator
172.17.0.5(87:locator)<ec><v0>:32769 using address 172.17.0.5(1):32771
[locator] [info 2018/09/27 06:22:38.583 UTC <unicast
receiver,0c20036cd386-40784> tid=0x30] Received a join request from
0c20036cd386(1):32771 [locator] [info 2018/09/27 06:22:38.884 UTC <Geode
Membership View Creator> tid=0x37] View Creator is processing 1 requests for
the next membership view [locator] [info 2018/09/27 06:22:38.885 UTC <Geode
Membership View Creator> tid=0x37] preparing new view
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.890 UTC <unicast
receiver,0c20036cd386-31210> tid=0x51] received new view:
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\\{lead},
172.17.0.5(1)<v6>:32771] old view is: null [info 2018/09/27 06:22:38.891 UTC
<unicast receiver,0c20036cd386-31210> tid=0x51] Failure detection is now
watching 172.17.0.5(87:locator)<ec><v0>:32769 [info 2018/09/27 06:22:38.904 UTC
<Test worker> tid=0x19] Joined the distributed system (took 345 ms) [info
2018/09/27 06:22:38.905 UTC <Test worker> tid=0x19] Finished joining (took
346ms). [info 2018/09/27 06:22:38.906 UTC <Test worker> tid=0x19] Starting
DistributionManager 172.17.0.5(1)<v6>:32771. (took 625 ms) [locator] [info
2018/09/27 06:22:38.905 UTC <Geode Membership View Creator> tid=0x37] finished
waiting for responses to view preparation [locator] [info 2018/09/27
06:22:38.906 UTC <Geode Membership View Creator> tid=0x37] received new view:
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\\{lead},
0c20036cd386(1)<v6>:32771] [locator] old view is:
View[0c20036cd386(87:locator)<ec><v0>:32769|5] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\\{lead}]
[locator] [info 2018/09/27 06:22:38.906 UTC <Geode Membership View Creator>
tid=0x37] Peer locator received new membership view:
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.909 UTC <Test worker>
tid=0x19] Initial (distribution manager) view =
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\\{lead},
172.17.0.5(1)<v6>:32771] [locator] [info 2018/09/27 06:22:38.909 UTC <Geode
Membership View Creator> tid=0x37] sending new view
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.910 UTC <Test worker>
tid=0x19] Admitting member <172.17.0.5(87:locator)<ec><v0>:32769>. Now there
are 1 non-admin member(s). [info 2018/09/27 06:22:38.910 UTC <Test worker>
tid=0x19] Admitting member <172.17.0.5(286)<v5>:32770>. Now there are 2
non-admin member(s). [info 2018/09/27 06:22:38.910 UTC <Test worker> tid=0x19]
Admitting member <172.17.0.5(1)<v6>:32771>. Now there are 3 non-admin
member(s). [locator] [info 2018/09/27 06:22:38.910 UTC <View Message Processor>
tid=0x98] Membership: Processing addition < 0c20036cd386(1)<v6>:32771 >
[locator] [info 2018/09/27 06:22:38.911 UTC <View Message Processor> tid=0x98]
Admitting member <0c20036cd386(1)<v6>:32771>. Now there are 3 non-admin
member(s). [vm0] [info 2018/09/27 06:22:38.911 UTC <unicast
receiver,0c20036cd386-60541> tid=0xb5] received new view:
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\\{lead},
172.17.0.5(1)<v6>:32771] [vm0] old view is:
View[172.17.0.5(87:locator)<ec><v0>:32769|5] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\\{lead}] [vm0]
[info 2018/09/27 06:22:38.912 UTC <unicast receiver,0c20036cd386-60541>
tid=0xb5] Failure detection is now watching 172.17.0.5(1)<v6>:32771 [vm0] [info
2018/09/27 06:22:38.914 UTC <View Message Processor> tid=0x122] Membership:
Processing addition < 172.17.0.5(1)<v6>:32771 > [vm0] [info 2018/09/27
06:22:38.914 UTC <View Message Processor> tid=0x122] Admitting member
<172.17.0.5(1)<v6>:32771>. Now there are 3 non-admin member(s). [vm0] [info
2018/09/27 06:22:38.942 UTC <Pooled High Priority Message Processor 1>
tid=0xca] Member 172.17.0.5(1)<v6>:32771 is equivalent or in the same
redundancy zone. [locator] [info 2018/09/27 06:22:38.943 UTC <Pooled High
Priority Message Processor 1> tid=0x9b] Member 0c20036cd386(1)<v6>:32771 is
equivalent or in the same redundancy zone. [info 2018/09/27 06:22:38.953 UTC
<P2P message reader for 172.17.0.5(87:locator)<ec><v0>:32769 shared unordered
uid=4 port=45226> tid=0x5a] Member 172.17.0.5(87:locator)<ec><v0>:32769 is
equivalent or in the same redundancy zone. [info 2018/09/27 06:22:38.953 UTC
<P2P message reader for 172.17.0.5(286)<v5>:32770 shared unordered uid=7
port=45228> tid=0x5d] Member 172.17.0.5(286)<v5>:32770 is equivalent or in the
same redundancy zone. [info 2018/09/27 06:22:38.954 UTC <Test worker> tid=0x19]
DistributionManager 172.17.0.5(1)<v6>:32771 started on localhost[43291]. There
were 2 other DMs. others: [172.17.0.5(286)<v5>:32770,
172.17.0.5(87:locator)<ec><v0>:32769] (VERBOSE, took 721 ms) [info 2018/09/27
06:22:38.983 UTC <Thread-21 StatSampler> tid=0x5f] Disabling statistic
archival. [info 2018/09/27 06:22:39.006 UTC <Test worker> tid=0x19] No
locator(s) found with cluster configuration service [locator] [info 2018/09/27
06:22:39.116 UTC <Geode Failure Detection Scheduler> tid=0x31] Failure
detection is now watching 0c20036cd386(1)<v6>:32771 [locator] [info 2018/09/27
06:22:39.119 UTC <Geode Failure Detection thread 1> tid=0xa0] Failure detection
is now watching 0c20036cd386(286)<v5>:32770 [info 2018/09/27 06:22:39.195 UTC
<Test worker> tid=0x19] Initializing region
_monitoringRegion_172.17.0.5<v6>32771 [info 2018/09/27 06:22:39.206 UTC <Test
worker> tid=0x19] Initialization of region
_monitoringRegion_172.17.0.5<v6>32771 completed [vm0] [info 2018/09/27
06:22:39.222 UTC <Geode Failure Detection Scheduler> tid=0xb6] Failure
detection is now watching 172.17.0.5(87:locator)<ec><v0>:32769 [vm0] [info
2018/09/27 06:22:39.228 UTC <Geode Failure Detection thread 1> tid=0x125]
Failure detection is now watching 172.17.0.5(1)<v6>:32771 [info 2018/09/27
06:22:39.807 UTC <Test worker> tid=0x19] Loading previously deployed jars [info
2018/09/27 06:22:39.830 UTC <Test worker> tid=0x19] Initializing region
PdxTypes [info 2018/09/27 06:22:39.843 UTC <Test worker> tid=0x19] Region
PdxTypes requesting initial image from 172.17.0.5(286)<v5>:32770 [info
2018/09/27 06:22:39.850 UTC <Test worker> tid=0x19] PdxTypes is done getting
image from 172.17.0.5(286)<v5>:32770. isDeltaGII is false [info 2018/09/27
06:22:39.850 UTC <Test worker> tid=0x19] Initialization of region PdxTypes
completed [info 2018/09/27 06:22:39.859 UTC <Test worker> tid=0x19]
Initializing region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC [info 2018/09/27
06:22:39.865 UTC <Test worker> tid=0x19] Region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC requesting initial
image from 172.17.0.5(286)<v5>:32770 [info 2018/09/27 06:22:39.882 UTC <Test
worker> tid=0x19] DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC
is done getting image from 172.17.0.5(286)<v5>:32770. isDeltaGII is false [info
2018/09/27 06:22:39.882 UTC <Test worker> tid=0x19] Initialization of region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC completed [vm0]
[info 2018/09/27 06:22:39.972 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Received method:
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run with 0 args on
object: "check conflation count" [vm0] [info 2018/09/27 06:22:39.988 UTC <RMI
TCP Connection(1)-172.17.0.5> tid=0x20] Got result: EXCEPTION_OCCURRED [vm0]
org.junit.ComparisonFailure: [conflated event count] expected:<[2]L> but
was:<[1]L> [vm0] at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [vm0] at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[vm0] at
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run(DistributedAckRegionCCEDUnitTest.java:475)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498) [vm0] at
hydra.MethExecutor.executeObject(MethExecutor.java:244) [vm0] at
org.apache.geode.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:70)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498) [vm0] at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357) [vm0] at
sun.rmi.transport.Transport$1.run(Transport.java:200) [vm0] at
sun.rmi.transport.Transport$1.run(Transport.java:197) [vm0] at
java.security.AccessController.doPrivileged(Native Method) [vm0] at
sun.rmi.transport.Transport.serviceCall(Transport.java:196) [vm0] at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573) [vm0]
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
[vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
[vm0] at java.security.AccessController.doPrivileged(Native Method) [vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at java.lang.Thread.run(Thread.java:748) [vm0] from
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run with 0 args on
object: "check conflation count" (took 15 ms)}}
was (Author: mhansonp):
Log excerpt
[setup] START TEST DistributedAckRegionCCEDUnitTest.testEntryVersionRollover
[vm0] [info 2018/09/27 06:22:36.691 UTC <RMI TCP Connection(1)-172.17.0.5>
tid=0x20] Received method:
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$8.run with 0 args on
object: "Create Region" [vm0] distributed system properties:
\{statistic-sampling-enabled=true, mcast-port=0, log-level=info,
validate-serializable-objects=true, disable-auto-reconnect=true,
enable-cluster-configuration=false,
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue,
locators=localhost[43291], conserve-sockets=false,
use-cluster-configuration=false} [vm0] [info 2018/09/27 06:22:36.698 UTC <RMI
TCP Connection(1)-172.17.0.5> tid=0x20] Startup Configuration: [vm0] ###
GemFire Properties defined with system property ### [vm0]
validate-serializable-objects=true [vm0] ### GemFire Properties defined with
api ### [vm0] conserve-sockets=false [vm0] disable-auto-reconnect=true [vm0]
enable-cluster-configuration=false [vm0] locators=localhost[43291] [vm0]
log-level=info [vm0] mcast-port=0 [vm0]
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue
[vm0] statistic-sampling-enabled=true [vm0] use-cluster-configuration=false
[vm0] ### GemFire Properties using default values ### [vm0]
ack-severe-alert-threshold=0 [vm0] ack-wait-threshold=15 [vm0]
archive-disk-space-limit=0 [vm0] archive-file-size-limit=0 [vm0]
async-distribution-timeout=0 [vm0] async-max-queue-size=8 [vm0]
async-queue-timeout=60000 [vm0] bind-address= [vm0] cache-xml-file=cache.xml
[vm0] cluster-configuration-dir= [vm0] cluster-ssl-ciphers=any [vm0]
cluster-ssl-enabled=false [vm0] cluster-ssl-keystore= [vm0]
cluster-ssl-keystore-password= [vm0] cluster-ssl-keystore-type= [vm0]
cluster-ssl-protocols=any [vm0] cluster-ssl-require-authentication=true [vm0]
cluster-ssl-truststore= [vm0] cluster-ssl-truststore-password= [vm0]
conflate-events=server [vm0] delta-propagation=true [vm0]
deploy-working-dir=/tmp/build/ae3c03f4/built-gemfire/test/geode/geode-core/build/distributedTest149/dunit/vm0
[vm0] disable-tcp=false [vm0] distributed-system-id=-1 [vm0]
distributed-transactions=false [vm0] durable-client-id= [vm0]
durable-client-timeout=300 [vm0] enable-network-partition-detection=true [vm0]
enable-time-statistics=false [vm0] enforce-unique-host=false [vm0]
gateway-ssl-ciphers=any [vm0] gateway-ssl-enabled=false [vm0]
gateway-ssl-keystore= [vm0] gateway-ssl-keystore-password= [vm0]
gateway-ssl-keystore-type= [vm0] gateway-ssl-protocols=any [vm0]
gateway-ssl-require-authentication=true [vm0] gateway-ssl-truststore= [vm0]
gateway-ssl-truststore-password= [vm0] groups= [vm0] http-service-bind-address=
[vm0] http-service-port=7070 [vm0] http-service-ssl-ciphers=any [vm0]
http-service-ssl-enabled=false [vm0] http-service-ssl-keystore= [vm0]
http-service-ssl-keystore-password= [vm0] http-service-ssl-keystore-type= [vm0]
http-service-ssl-protocols=any [vm0]
http-service-ssl-require-authentication=false [vm0]
http-service-ssl-truststore= [vm0] http-service-ssl-truststore-password= [vm0]
jmx-manager=false [vm0] jmx-manager-access-file= [vm0]
jmx-manager-bind-address= [vm0] jmx-manager-hostname-for-clients= [vm0]
jmx-manager-http-port=7070 [vm0] jmx-manager-password-file= [vm0]
jmx-manager-port=1099 [vm0] jmx-manager-ssl-ciphers=any [vm0]
jmx-manager-ssl-enabled=false [vm0] jmx-manager-ssl-keystore= [vm0]
jmx-manager-ssl-keystore-password= [vm0] jmx-manager-ssl-keystore-type= [vm0]
jmx-manager-ssl-protocols=any [vm0] jmx-manager-ssl-require-authentication=true
[vm0] jmx-manager-ssl-truststore= [vm0] jmx-manager-ssl-truststore-password=
[vm0] jmx-manager-start=false [vm0] jmx-manager-update-rate=2000 [vm0]
load-cluster-configuration-from-dir=false [vm0] locator-wait-time=0 [vm0]
lock-memory=false [vm0] log-disk-space-limit=0 [vm0] log-file= [vm0]
log-file-size-limit=0 [vm0] max-num-reconnect-tries=3 [vm0]
max-wait-time-reconnect=60000 [vm0] mcast-address=239.192.81.1 [vm0]
mcast-flow-control=1048576, 0.25, 5000 [vm0] mcast-recv-buffer-size=1048576
[vm0] mcast-send-buffer-size=65535 [vm0] mcast-ttl=32 [vm0] member-timeout=5000
[vm0] membership-port-range=32769-61000 [vm0] memcached-bind-address= [vm0]
memcached-port=0 [vm0] memcached-protocol=ASCII [vm0] name= [vm0]
off-heap-memory-size= [vm0] redis-bind-address= [vm0] redis-password= [vm0]
redis-port=0 [vm0] redundancy-zone= [vm0] remote-locators= [vm0]
remove-unresponsive-client=false [vm0] roles= [vm0] security-client-accessor=
[vm0] security-client-accessor-pp= [vm0] security-client-auth-init= [vm0]
security-client-authenticator= [vm0] security-client-dhalgo= [vm0]
security-log-file= [vm0] security-log-level=config [vm0] security-manager=
[vm0] security-peer-auth-init= [vm0] security-peer-authenticator= [vm0]
security-peer-verifymember-timeout=1000 [vm0] security-post-processor= [vm0]
security-udp-dhalgo= [vm0] server-bind-address= [vm0] server-ssl-ciphers=any
[vm0] server-ssl-enabled=false [vm0] server-ssl-keystore= [vm0]
server-ssl-keystore-password= [vm0] server-ssl-keystore-type= [vm0]
server-ssl-protocols=any [vm0] server-ssl-require-authentication=true [vm0]
server-ssl-truststore= [vm0] server-ssl-truststore-password= [vm0]
socket-buffer-size=32768 [vm0] socket-lease-time=60000 [vm0] ssl-ciphers=any
[vm0] ssl-cluster-alias= [vm0] ssl-default-alias= [vm0] ssl-enabled-components=
[vm0] ssl-endpoint-identification-enabled=false [vm0] ssl-gateway-alias= [vm0]
ssl-jmx-alias= [vm0] ssl-keystore= [vm0] ssl-keystore-password= [vm0]
ssl-keystore-type= [vm0] ssl-locator-alias= [vm0] ssl-protocols=any [vm0]
ssl-require-authentication=true [vm0] ssl-server-alias= [vm0] ssl-truststore=
[vm0] ssl-truststore-password= [vm0] ssl-truststore-type= [vm0] ssl-web-alias=
[vm0] ssl-web-require-authentication=false [vm0] start-dev-rest-api=false [vm0]
start-locator= [vm0] statistic-archive-file= [vm0] statistic-sample-rate=1000
[vm0] tcp-port=0 [vm0] thread-monitor-enabled=true [vm0]
thread-monitor-interval-ms=60000 [vm0] thread-monitor-time-limit-ms=30000 [vm0]
udp-fragment-size=60000 [vm0] udp-recv-buffer-size=1048576 [vm0]
udp-send-buffer-size=65535 [vm0] user-command-packages= [vm0] [info 2018/09/27
06:22:36.699 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20] initializing
InternalDataSerializer with 0 services [vm0] [info 2018/09/27 06:22:36.704 UTC
<RMI TCP Connection(1)-172.17.0.5> tid=0x20] setting a serialization filter
containing
java.**;javax.management.**;javax.print.attribute.EnumSyntax;antlr.**;org.apache.commons.modeler.AttributeInfo;org.apache.commons.modeler.FeatureInfo;org.apache.commons.modeler.ManagedBean;org.apache.geode.distributed.internal.DistributionConfigSnapshot;org.apache.geode.distributed.internal.RuntimeDistributionConfigImpl;org.apache.geode.distributed.internal.DistributionConfigImpl;org.apache.geode.distributed.internal.membership.InternalDistributedMember;org.apache.geode.internal.cache.persistence.PersistentMemberID;org.apache.geode.internal.cache.persistence.DiskStoreID;org.apache.geode.internal.cache.tier.sockets.VersionedObjectList;org.apache.shiro.*;org.apache.shiro.authz.*;org.apache.shiro.authc.*;org.apache.logging.log4j.Level;org.apache.logging.log4j.spi.StandardLevel;com.sun.proxy.$Proxy*;com.healthmarketscience.rmiio.RemoteInputStream;javax.rmi.ssl.SslRMIClientSocketFactory;javax.net.ssl.SSLHandshakeException;javax.net.ssl.SSLException;sun.security.validator.ValidatorException;sun.security.provider.certpath.SunCertPathBuilderException;org.apache.geode.modules.util.SessionCustomExpiry;org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue;!*
[vm0] [info 2018/09/27 06:22:36.708 UTC <RMI TCP Connection(1)-172.17.0.5>
tid=0x20] [ThreadsMonitor] a New Monitor object and process were created. [vm0]
[info 2018/09/27 06:22:36.708 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Serial Queue info : THROTTLE_PERCENT: 0.75 SERIAL_QUEUE_BYTE_LIMIT :41943040
SERIAL_QUEUE_THROTTLE :31457280 TOTAL_SERIAL_QUEUE_BYTE_LIMIT :83886080
TOTAL_SERIAL_QUEUE_THROTTLE :31457280 SERIAL_QUEUE_SIZE_LIMIT :20000
SERIAL_QUEUE_SIZE_THROTTLE :15000 [vm0] [info 2018/09/27 06:22:36.710 UTC <RMI
TCP Connection(1)-172.17.0.5> tid=0x20] Starting membership services [vm0]
[info 2018/09/27 06:22:36.721 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
JGroups channel created (took 10ms) [vm0] [info 2018/09/27 06:22:36.722 UTC
<RMI TCP Connection(1)-172.17.0.5> tid=0x20] GemFire P2P Listener started on
/172.17.0.5:53693 [vm0] [info 2018/09/27 06:22:36.723 UTC <Geode Failure
Detection Server thread 0> tid=0xb9] Started failure detection server thread on
/172.17.0.5:53614. [vm0] [info 2018/09/27 06:22:36.726 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Attempting to join the distributed system
through coordinator 172.17.0.5(87:locator)<ec><v0>:32769 using address
172.17.0.5(286):32770 [locator] [info 2018/09/27 06:22:36.727 UTC <unicast
receiver,0c20036cd386-40784> tid=0x30] Received a join request from
0c20036cd386(286):32770 [locator] [info 2018/09/27 06:22:37.028 UTC <Geode
Membership View Creator> tid=0x37] View Creator is processing 1 requests for
the next membership view [locator] [info 2018/09/27 06:22:37.029 UTC <Geode
Membership View Creator> tid=0x37] preparing new view
View[0c20036cd386(87:locator)<ec><v0>:32769|5] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead}]
[vm0] [info 2018/09/27 06:22:37.031 UTC <unicast receiver,0c20036cd386-60541>
tid=0xb5] received new view: View[172.17.0.5(87:locator)<ec><v0>:32769|5]
members: [172.17.0.5(87:locator)<ec><v0>:32769,
172.17.0.5(286)<v5>:32770\{lead}] [vm0] old view is: null [vm0] [info
2018/09/27 06:22:37.031 UTC <unicast receiver,0c20036cd386-60541> tid=0xb5]
Failure detection is now watching 172.17.0.5(87:locator)<ec><v0>:32769 [vm0]
[info 2018/09/27 06:22:37.032 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Joined the distributed system (took 309 ms) [locator] [info 2018/09/27
06:22:37.032 UTC <Geode Membership View Creator> tid=0x37] finished waiting for
responses to view preparation [vm0] [info 2018/09/27 06:22:37.033 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Finished joining (took 310ms). [locator]
[info 2018/09/27 06:22:37.033 UTC <Geode Membership View Creator> tid=0x37]
received new view: View[0c20036cd386(87:locator)<ec><v0>:32769|5] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead}]
[locator] old view is: View[0c20036cd386(87:locator)<ec><v0>:32769|4] members:
[0c20036cd386(87:locator)<ec><v0>:32769] shutdown:
[0c20036cd386(290)<v2>:32771] [vm0] [info 2018/09/27 06:22:37.033 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Starting DistributionManager
172.17.0.5(286)<v5>:32770. (took 324 ms) [locator] [info 2018/09/27
06:22:37.033 UTC <Geode Membership View Creator> tid=0x37] Peer locator
received new membership view: View[0c20036cd386(87:locator)<ec><v0>:32769|5]
members: [0c20036cd386(87:locator)<ec><v0>:32769,
0c20036cd386(286)<v5>:32770\{lead}] [vm0] [info 2018/09/27 06:22:37.033 UTC
<RMI TCP Connection(1)-172.17.0.5> tid=0x20] Initial (distribution manager)
view = View[172.17.0.5(87:locator)<ec><v0>:32769|5] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\{lead}]
[locator] [info 2018/09/27 06:22:37.033 UTC <Geode Membership View Creator>
tid=0x37] Failure detection is now watching 0c20036cd386(286)<v5>:32770 [vm0]
[info 2018/09/27 06:22:37.033 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Admitting member <172.17.0.5(87:locator)<ec><v0>:32769>. Now there are 1
non-admin member(s). [vm0] [info 2018/09/27 06:22:37.034 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Admitting member
<172.17.0.5(286)<v5>:32770>. Now there are 2 non-admin member(s). [locator]
[info 2018/09/27 06:22:37.034 UTC <Geode Membership View Creator> tid=0x37]
sending new view View[0c20036cd386(87:locator)<ec><v0>:32769|5] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead}]
[locator] [info 2018/09/27 06:22:37.034 UTC <View Message Processor> tid=0x98]
Membership: Processing addition < 0c20036cd386(286)<v5>:32770 > [locator] [info
2018/09/27 06:22:37.035 UTC <View Message Processor> tid=0x98] Admitting member
<0c20036cd386(286)<v5>:32770>. Now there are 2 non-admin member(s). [locator]
[info 2018/09/27 06:22:37.067 UTC <Pooled High Priority Message Processor 1>
tid=0x9b] Member 0c20036cd386(286)<v5>:32770 is equivalent or in the same
redundancy zone. [vm0] [info 2018/09/27 06:22:37.095 UTC <P2P message reader
for 172.17.0.5(87:locator)<ec><v0>:32769 shared unordered uid=3 port=51754>
tid=0xbd] Member 172.17.0.5(87:locator)<ec><v0>:32769 is equivalent or in the
same redundancy zone. [vm0] [info 2018/09/27 06:22:37.096 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] DistributionManager
172.17.0.5(286)<v5>:32770 started on localhost[43291]. There were 1 other DMs.
others: [172.17.0.5(87:locator)<ec><v0>:32769] (VERBOSE, took 391 ms) [vm0]
[info 2018/09/27 06:22:37.099 UTC <Thread-21 StatSampler> tid=0xc0] Disabling
statistic archival. [vm0] [info 2018/09/27 06:22:37.103 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] No locator(s) found with cluster
configuration service [vm0] [info 2018/09/27 06:22:37.113 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Initializing region
_monitoringRegion_172.17.0.5<v5>32770 [vm0] [info 2018/09/27 06:22:37.114 UTC
<RMI TCP Connection(1)-172.17.0.5> tid=0x20] Initialization of region
_monitoringRegion_172.17.0.5<v5>32770 completed [vm0] [info 2018/09/27
06:22:37.358 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20] Loading
previously deployed jars [vm0] [info 2018/09/27 06:22:37.360 UTC <RMI TCP
Connection(1)-172.17.0.5> tid=0x20] Initializing region PdxTypes [vm0] [info
2018/09/27 06:22:37.362 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Initialization of region PdxTypes completed [vm0] [info 2018/09/27 06:22:37.363
UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20] Initializing region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC [vm0] [info
2018/09/27 06:22:37.365 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Initialization of region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC completed [vm0]
[info 2018/09/27 06:22:37.372 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Got result: null [vm0] from
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$8.run with 0 args on
object: "Create Region" (took 680 ms) distributed system properties:
\{statistic-sampling-enabled=true, mcast-port=0, log-level=info,
validate-serializable-objects=true, disable-auto-reconnect=true,
enable-cluster-configuration=false,
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue,
locators=localhost[43291], conserve-sockets=false,
use-cluster-configuration=false} [info 2018/09/27 06:22:38.172 UTC <Test
worker> tid=0x19] Startup Configuration: ### GemFire Properties defined with
api ### conserve-sockets=false disable-auto-reconnect=true
enable-cluster-configuration=false locators=localhost[43291] log-level=info
mcast-port=0
serializable-object-filter=org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue
statistic-sampling-enabled=true use-cluster-configuration=false
validate-serializable-objects=true ### 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
delta-propagation=true
deploy-working-dir=/tmp/build/ae3c03f4/built-gemfire/test/geode/geode-core/build/distributedTest149
disable-tcp=false distributed-system-id=-1 distributed-transactions=false
durable-client-id= durable-client-timeout=300
enable-network-partition-detection=true 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-ciphers=any
jmx-manager-ssl-enabled=false jmx-manager-ssl-keystore=
jmx-manager-ssl-keystore-password= jmx-manager-ssl-keystore-type=
jmx-manager-ssl-protocols=any jmx-manager-ssl-require-authentication=true
jmx-manager-ssl-truststore= jmx-manager-ssl-truststore-password=
jmx-manager-start=false jmx-manager-update-rate=2000
load-cluster-configuration-from-dir=false locator-wait-time=0 lock-memory=false
log-disk-space-limit=0 log-file= log-file-size-limit=0
max-num-reconnect-tries=3 max-wait-time-reconnect=60000
mcast-address=239.192.81.1 mcast-flow-control=1048576, 0.25, 5000
mcast-recv-buffer-size=1048576 mcast-send-buffer-size=65535 mcast-ttl=32
member-timeout=5000 membership-port-range=32769-61000 memcached-bind-address=
memcached-port=0 memcached-protocol=ASCII 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=
security-udp-dhalgo= server-bind-address= server-ssl-ciphers=any
server-ssl-enabled=false server-ssl-keystore= server-ssl-keystore-password=
server-ssl-keystore-type= server-ssl-protocols=any
server-ssl-require-authentication=true server-ssl-truststore=
server-ssl-truststore-password= socket-buffer-size=32768
socket-lease-time=60000 ssl-ciphers=any ssl-cluster-alias= ssl-default-alias=
ssl-enabled-components= ssl-endpoint-identification-enabled=false
ssl-gateway-alias= ssl-jmx-alias= ssl-keystore= ssl-keystore-password=
ssl-keystore-type= ssl-locator-alias= ssl-protocols=any
ssl-require-authentication=true ssl-server-alias= ssl-truststore=
ssl-truststore-password= ssl-truststore-type= ssl-web-alias=
ssl-web-require-authentication=false start-dev-rest-api=false start-locator=
statistic-archive-file= statistic-sample-rate=1000 tcp-port=0
thread-monitor-enabled=true thread-monitor-interval-ms=60000
thread-monitor-time-limit-ms=30000 udp-fragment-size=60000
udp-recv-buffer-size=1048576 udp-send-buffer-size=65535 user-command-packages=
[info 2018/09/27 06:22:38.187 UTC <Test worker> tid=0x19] initializing
InternalDataSerializer with 0 services [info 2018/09/27 06:22:38.211 UTC <Test
worker> tid=0x19] setting a serialization filter containing
java.**;javax.management.**;javax.print.attribute.EnumSyntax;antlr.**;org.apache.commons.modeler.AttributeInfo;org.apache.commons.modeler.FeatureInfo;org.apache.commons.modeler.ManagedBean;org.apache.geode.distributed.internal.DistributionConfigSnapshot;org.apache.geode.distributed.internal.RuntimeDistributionConfigImpl;org.apache.geode.distributed.internal.DistributionConfigImpl;org.apache.geode.distributed.internal.membership.InternalDistributedMember;org.apache.geode.internal.cache.persistence.PersistentMemberID;org.apache.geode.internal.cache.persistence.DiskStoreID;org.apache.geode.internal.cache.tier.sockets.VersionedObjectList;org.apache.shiro.*;org.apache.shiro.authz.*;org.apache.shiro.authc.*;org.apache.logging.log4j.Level;org.apache.logging.log4j.spi.StandardLevel;com.sun.proxy.$Proxy*;com.healthmarketscience.rmiio.RemoteInputStream;javax.rmi.ssl.SslRMIClientSocketFactory;javax.net.ssl.SSLHandshakeException;javax.net.ssl.SSLException;sun.security.validator.ValidatorException;sun.security.provider.certpath.SunCertPathBuilderException;org.apache.geode.modules.util.SessionCustomExpiry;org.apache.geode.cache30.MultiVMRegionTestCase$DeltaValue;!*
[info 2018/09/27 06:22:38.263 UTC <Test worker> tid=0x19] [ThreadsMonitor] a
New Monitor object and process were created. [info 2018/09/27 06:22:38.264 UTC
<Test worker> tid=0x19] Serial Queue info : THROTTLE_PERCENT: 0.75
SERIAL_QUEUE_BYTE_LIMIT :41943040 SERIAL_QUEUE_THROTTLE :31457280
TOTAL_SERIAL_QUEUE_BYTE_LIMIT :83886080 TOTAL_SERIAL_QUEUE_THROTTLE :31457280
SERIAL_QUEUE_SIZE_LIMIT :20000 SERIAL_QUEUE_SIZE_THROTTLE :15000 [info
2018/09/27 06:22:38.446 UTC <Test worker> tid=0x19] Starting membership
services [info 2018/09/27 06:22:38.535 UTC <Test worker> tid=0x19] JGroups
channel created (took 88ms) [info 2018/09/27 06:22:38.549 UTC <Test worker>
tid=0x19] GemFire P2P Listener started on /172.17.0.5:59424 [info 2018/09/27
06:22:38.551 UTC <Geode Failure Detection Server thread 0> tid=0x55] Started
failure detection server thread on /172.17.0.5:59098. [info 2018/09/27
06:22:38.570 UTC <Test worker> tid=0x19] Attempting to join the distributed
system through coordinator 172.17.0.5(87:locator)<ec><v0>:32769 using address
172.17.0.5(1):32771 [locator] [info 2018/09/27 06:22:38.583 UTC <unicast
receiver,0c20036cd386-40784> tid=0x30] Received a join request from
0c20036cd386(1):32771 [locator] [info 2018/09/27 06:22:38.884 UTC <Geode
Membership View Creator> tid=0x37] View Creator is processing 1 requests for
the next membership view [locator] [info 2018/09/27 06:22:38.885 UTC <Geode
Membership View Creator> tid=0x37] preparing new view
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.890 UTC <unicast
receiver,0c20036cd386-31210> tid=0x51] received new view:
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\{lead},
172.17.0.5(1)<v6>:32771] old view is: null [info 2018/09/27 06:22:38.891 UTC
<unicast receiver,0c20036cd386-31210> tid=0x51] Failure detection is now
watching 172.17.0.5(87:locator)<ec><v0>:32769 [info 2018/09/27 06:22:38.904 UTC
<Test worker> tid=0x19] Joined the distributed system (took 345 ms) [info
2018/09/27 06:22:38.905 UTC <Test worker> tid=0x19] Finished joining (took
346ms). [info 2018/09/27 06:22:38.906 UTC <Test worker> tid=0x19] Starting
DistributionManager 172.17.0.5(1)<v6>:32771. (took 625 ms) [locator] [info
2018/09/27 06:22:38.905 UTC <Geode Membership View Creator> tid=0x37] finished
waiting for responses to view preparation [locator] [info 2018/09/27
06:22:38.906 UTC <Geode Membership View Creator> tid=0x37] received new view:
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead},
0c20036cd386(1)<v6>:32771] [locator] old view is:
View[0c20036cd386(87:locator)<ec><v0>:32769|5] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead}]
[locator] [info 2018/09/27 06:22:38.906 UTC <Geode Membership View Creator>
tid=0x37] Peer locator received new membership view:
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.909 UTC <Test worker>
tid=0x19] Initial (distribution manager) view =
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\{lead},
172.17.0.5(1)<v6>:32771] [locator] [info 2018/09/27 06:22:38.909 UTC <Geode
Membership View Creator> tid=0x37] sending new view
View[0c20036cd386(87:locator)<ec><v0>:32769|6] members:
[0c20036cd386(87:locator)<ec><v0>:32769, 0c20036cd386(286)<v5>:32770\{lead},
0c20036cd386(1)<v6>:32771] [info 2018/09/27 06:22:38.910 UTC <Test worker>
tid=0x19] Admitting member <172.17.0.5(87:locator)<ec><v0>:32769>. Now there
are 1 non-admin member(s). [info 2018/09/27 06:22:38.910 UTC <Test worker>
tid=0x19] Admitting member <172.17.0.5(286)<v5>:32770>. Now there are 2
non-admin member(s). [info 2018/09/27 06:22:38.910 UTC <Test worker> tid=0x19]
Admitting member <172.17.0.5(1)<v6>:32771>. Now there are 3 non-admin
member(s). [locator] [info 2018/09/27 06:22:38.910 UTC <View Message Processor>
tid=0x98] Membership: Processing addition < 0c20036cd386(1)<v6>:32771 >
[locator] [info 2018/09/27 06:22:38.911 UTC <View Message Processor> tid=0x98]
Admitting member <0c20036cd386(1)<v6>:32771>. Now there are 3 non-admin
member(s). [vm0] [info 2018/09/27 06:22:38.911 UTC <unicast
receiver,0c20036cd386-60541> tid=0xb5] received new view:
View[172.17.0.5(87:locator)<ec><v0>:32769|6] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\{lead},
172.17.0.5(1)<v6>:32771] [vm0] old view is:
View[172.17.0.5(87:locator)<ec><v0>:32769|5] members:
[172.17.0.5(87:locator)<ec><v0>:32769, 172.17.0.5(286)<v5>:32770\{lead}] [vm0]
[info 2018/09/27 06:22:38.912 UTC <unicast receiver,0c20036cd386-60541>
tid=0xb5] Failure detection is now watching 172.17.0.5(1)<v6>:32771 [vm0] [info
2018/09/27 06:22:38.914 UTC <View Message Processor> tid=0x122] Membership:
Processing addition < 172.17.0.5(1)<v6>:32771 > [vm0] [info 2018/09/27
06:22:38.914 UTC <View Message Processor> tid=0x122] Admitting member
<172.17.0.5(1)<v6>:32771>. Now there are 3 non-admin member(s). [vm0] [info
2018/09/27 06:22:38.942 UTC <Pooled High Priority Message Processor 1>
tid=0xca] Member 172.17.0.5(1)<v6>:32771 is equivalent or in the same
redundancy zone. [locator] [info 2018/09/27 06:22:38.943 UTC <Pooled High
Priority Message Processor 1> tid=0x9b] Member 0c20036cd386(1)<v6>:32771 is
equivalent or in the same redundancy zone. [info 2018/09/27 06:22:38.953 UTC
<P2P message reader for 172.17.0.5(87:locator)<ec><v0>:32769 shared unordered
uid=4 port=45226> tid=0x5a] Member 172.17.0.5(87:locator)<ec><v0>:32769 is
equivalent or in the same redundancy zone. [info 2018/09/27 06:22:38.953 UTC
<P2P message reader for 172.17.0.5(286)<v5>:32770 shared unordered uid=7
port=45228> tid=0x5d] Member 172.17.0.5(286)<v5>:32770 is equivalent or in the
same redundancy zone. [info 2018/09/27 06:22:38.954 UTC <Test worker> tid=0x19]
DistributionManager 172.17.0.5(1)<v6>:32771 started on localhost[43291]. There
were 2 other DMs. others: [172.17.0.5(286)<v5>:32770,
172.17.0.5(87:locator)<ec><v0>:32769] (VERBOSE, took 721 ms) [info 2018/09/27
06:22:38.983 UTC <Thread-21 StatSampler> tid=0x5f] Disabling statistic
archival. [info 2018/09/27 06:22:39.006 UTC <Test worker> tid=0x19] No
locator(s) found with cluster configuration service [locator] [info 2018/09/27
06:22:39.116 UTC <Geode Failure Detection Scheduler> tid=0x31] Failure
detection is now watching 0c20036cd386(1)<v6>:32771 [locator] [info 2018/09/27
06:22:39.119 UTC <Geode Failure Detection thread 1> tid=0xa0] Failure detection
is now watching 0c20036cd386(286)<v5>:32770 [info 2018/09/27 06:22:39.195 UTC
<Test worker> tid=0x19] Initializing region
_monitoringRegion_172.17.0.5<v6>32771 [info 2018/09/27 06:22:39.206 UTC <Test
worker> tid=0x19] Initialization of region
_monitoringRegion_172.17.0.5<v6>32771 completed [vm0] [info 2018/09/27
06:22:39.222 UTC <Geode Failure Detection Scheduler> tid=0xb6] Failure
detection is now watching 172.17.0.5(87:locator)<ec><v0>:32769 [vm0] [info
2018/09/27 06:22:39.228 UTC <Geode Failure Detection thread 1> tid=0x125]
Failure detection is now watching 172.17.0.5(1)<v6>:32771 [info 2018/09/27
06:22:39.807 UTC <Test worker> tid=0x19] Loading previously deployed jars [info
2018/09/27 06:22:39.830 UTC <Test worker> tid=0x19] Initializing region
PdxTypes [info 2018/09/27 06:22:39.843 UTC <Test worker> tid=0x19] Region
PdxTypes requesting initial image from 172.17.0.5(286)<v5>:32770 [info
2018/09/27 06:22:39.850 UTC <Test worker> tid=0x19] PdxTypes is done getting
image from 172.17.0.5(286)<v5>:32770. isDeltaGII is false [info 2018/09/27
06:22:39.850 UTC <Test worker> tid=0x19] Initialization of region PdxTypes
completed [info 2018/09/27 06:22:39.859 UTC <Test worker> tid=0x19]
Initializing region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC [info 2018/09/27
06:22:39.865 UTC <Test worker> tid=0x19] Region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC requesting initial
image from 172.17.0.5(286)<v5>:32770 [info 2018/09/27 06:22:39.882 UTC <Test
worker> tid=0x19] DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC
is done getting image from 172.17.0.5(286)<v5>:32770. isDeltaGII is false [info
2018/09/27 06:22:39.882 UTC <Test worker> tid=0x19] Initialization of region
DistributedAckRegionCCEDUnitTest_testEntryVersionRollover-CC completed [vm0]
[info 2018/09/27 06:22:39.972 UTC <RMI TCP Connection(1)-172.17.0.5> tid=0x20]
Received method:
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run with 0 args on
object: "check conflation count" [vm0] [info 2018/09/27 06:22:39.988 UTC <RMI
TCP Connection(1)-172.17.0.5> tid=0x20] Got result: EXCEPTION_OCCURRED [vm0]
org.junit.ComparisonFailure: [conflated event count] expected:<[2]L> but
was:<[1]L> [vm0] at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [vm0] at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[vm0] at
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run(DistributedAckRegionCCEDUnitTest.java:475)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498) [vm0] at
hydra.MethExecutor.executeObject(MethExecutor.java:244) [vm0] at
org.apache.geode.test.dunit.standalone.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:70)
[vm0] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [vm0] at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[vm0] at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[vm0] at java.lang.reflect.Method.invoke(Method.java:498) [vm0] at
sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357) [vm0] at
sun.rmi.transport.Transport$1.run(Transport.java:200) [vm0] at
sun.rmi.transport.Transport$1.run(Transport.java:197) [vm0] at
java.security.AccessController.doPrivileged(Native Method) [vm0] at
sun.rmi.transport.Transport.serviceCall(Transport.java:196) [vm0] at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573) [vm0]
at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834)
[vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688)
[vm0] at java.security.AccessController.doPrivileged(Native Method) [vm0] at
sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687)
[vm0] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[vm0] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[vm0] at java.lang.Thread.run(Thread.java:748) [vm0] from
org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run with 0 args on
object: "check conflation count" (took 15 ms)
> DistributedAckRegionCCEDUnitTest.testEntryVersionRollover test failure
> ----------------------------------------------------------------------
>
> Key: GEODE-5791
> URL: https://issues.apache.org/jira/browse/GEODE-5791
> Project: Geode
> Issue Type: Bug
> Components: core
> Reporter: Mark Hanson
> Priority: Major
> Labels: swat
>
> DistributedAckRegionCCEDUnitTest.testEntryVersionRollover failed in the CI
> build below
> https://concourse.apachegeode-ci.info/teams/main/pipelines/develop/jobs/DistributedTest/builds/21
>
>
> org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest >
> testEntryVersionRollover FAILED
> org.apache.geode.test.dunit.RMIException: While invoking
> org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run in VM 0
> running on Host ce1596cd0ff4 with 4 VMs
> at org.apache.geode.test.dunit.VM.invoke(VM.java:450)
> at org.apache.geode.test.dunit.VM.invoke(VM.java:419)
> at org.apache.geode.test.dunit.VM.invoke(VM.java:362)
> at
> org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest.testEntryVersionRollover(DistributedAckRegionCCEDUnitTest.java:469)
>
> Caused by:
> org.junit.ComparisonFailure: [conflated event count] expected:<[2]L> but
> was:<[1]L>
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at
> org.apache.geode.cache30.DistributedAckRegionCCEDUnitTest$9.run(DistributedAckRegionCCEDUnitTest.java:475)
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
