[
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:19 PM:
-------------------------------------------------------------
{noformat}
[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){noformat}
was (Author: mhansonp):
{noformat}
[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)
{noformat}
> 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)
