See
<https://builds.apache.org/job/sling-trunk-1.7/org.apache.sling$org.apache.sling.discovery.impl/898/>
------------------------------------------
[...truncated 869 lines...]
22.09.2014 18:48:55 *INFO * [main] Instance: stop: stopped
slingId=f34c86cb-a988-47d4-9b33-48513ec620cc, debugName=secondInstance
22.09.2014 18:48:55 *INFO * [main] Instance: stop: stopping
slingId=fc0889e1-341a-4465-b1ce-e52d1628335c, debugName=firstInstance
22.09.2014 18:48:55 *INFO * [main] Instance: stop: removing listener for
slingId=fc0889e1-341a-4465-b1ce-e52d1628335c:
org.apache.sling.discovery.impl.setup.Instance$1@8486b
22.09.2014 18:48:55 *INFO * [main] Instance: stop: stopped
slingId=fc0889e1-341a-4465-b1ce-e52d1628335c, debugName=firstInstance
22.09.2014 18:48:55 *INFO * [main] Instance: <init>: starting slingId=111,
debugName=firstInstance
22.09.2014 18:48:55 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms
22.09.2014 18:48:55 *INFO * [main] Instance: <init>: starting slingId=000,
debugName=secondInstance
22.09.2014 18:48:55 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:48:55 UTC 2014
22.09.2014 18:48:56 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:56 *INFO * [main] VotingHelper: getWinningVoting: no ongoing
votings parent resource found
22.09.2014 18:48:56 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no
ongoing votings parent resource found
22.09.2014 18:48:56 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:48:56 UTC 2014
22.09.2014 18:48:56 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:56 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms
22.09.2014 18:48:56 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:48:56 UTC 2014
22.09.2014 18:48:57 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:57 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:48:57 UTC 2014
22.09.2014 18:48:57 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:57 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms
22.09.2014 18:48:57 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:48:57 UTC 2014
22.09.2014 18:48:57 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:57 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:48:57 UTC 2014
22.09.2014 18:48:57 *WARN * [ObservationManager] 000: analyzeVotings: I've
already voted - but it so happened that there was a lower voting created after
I voted... so I shall change my vote from a
VotingView[viewId=c699dc88-021f-4472-8672-78b8941ced5a, initiator=111,
members=111, 000] to a VotingView[viewId=7ec34441-9899-4584-a063-94485571b459,
initiator=111, members=111, 000]
22.09.2014 18:48:57 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:58 *INFO * [main] Instance: stop: stopping slingId=000,
debugName=secondInstance
22.09.2014 18:48:58 *INFO * [main] Instance: stop: removing listener for
slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@1710e49
22.09.2014 18:48:58 *INFO * [main] Instance: stop: stopped slingId=000,
debugName=secondInstance
22.09.2014 18:48:58 *INFO * [main] Instance: stop: stopping slingId=111,
debugName=firstInstance
22.09.2014 18:48:58 *INFO * [main] Instance: stop: removing listener for
slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@145fdeb
22.09.2014 18:48:58 *INFO * [main] Instance: stop: stopped slingId=111,
debugName=firstInstance
22.09.2014 18:48:58 *INFO * [main] Instance: <init>: starting
slingId=ee49e4c9-04c8-4448-854d-0a4cb0020989, debugName=firstInstance
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] Instance: <init>: starting
slingId=1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e, debugName=secondInstance
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] ClusterTest: testAdditionalInstance: start
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] Instance: Instance
[ee49e4c9-04c8-4448-854d-0a4cb0020989] issues a heartbeat now Mon Sep 22
18:48:58 UTC 2014
22.09.2014 18:48:58 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:58 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:59 *INFO * [main] Instance: Instance
[1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e] issues a heartbeat now Mon Sep 22
18:48:59 UTC 2014
22.09.2014 18:48:59 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:48:59 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:48:59 *INFO * [main] Instance: dumpRepo: ====== START =====
22.09.2014 18:48:59 *INFO * [main] Instance: dumpRepo: repo =
org.apache.jackrabbit.core.RepositoryImpl@155e161
22.09.2014 18:48:59 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown
type=7/> jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown
type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /discovery --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /impl --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /clusterInstances --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /111 --
leaderElectionId=0_0000001411411735526_111 lastHeartbeat=Mon Sep 22 18:48:57
UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=f7675c4e-07ff-4df8-89eb-4d83ffbd7f71
22.09.2014 18:48:59 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 lastHeartbeat=Mon Sep 22 18:48:57
UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=9616a6db-0f1c-4ae1-bfc3-5ada52221669
22.09.2014 18:48:59 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/ee49e4c9-04c8-4448-854d-0a4cb0020989 --
leaderElectionId=0_0000001411411738271_ee49e4c9-04c8-4448-854d-0a4cb0020989
lastHeartbeat=Mon Sep 22 18:48:58 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=1fcbf1ec-525d-4b94-a49e-8d465e2c76d7
22.09.2014 18:48:59 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e --
leaderElectionId=0_0000001411411738585_1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e
lastHeartbeat=Mon Sep 22 18:48:59 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=31d8c37b-8104-459e-aeac-d8f5fe764c1f
22.09.2014 18:48:59 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /ongoingVotings --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/56af2e35-b438-46b5-8a05-1e8ff6454420 --
clusterId=7ec34441-9899-4584-a063-94485571b459 clusterIdDefinedAt=Mon Sep 22
18:48:57 UTC 2014 votingStart=Mon Sep 22 18:48:58 UTC 2014
clusterIdDefinedBy=111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /111 --
leaderElectionId=0_0000001411411735526_111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/ee49e4c9-04c8-4448-854d-0a4cb0020989 -- initiator=true
leaderElectionId=0_0000001411411738271_ee49e4c9-04c8-4448-854d-0a4cb0020989
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e --
leaderElectionId=0_0000001411411738585_1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e
vote=true jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /previousView --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /establishedView --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance:
/7ec34441-9899-4584-a063-94485571b459 -- leaderId=111 promotedAt=Mon Sep 22
18:48:58 UTC 2014 clusterId=7ec34441-9899-4584-a063-94485571b459
leaderElectionId=0_0000001411411735526_111 clusterIdDefinedAt=Mon Sep 22
18:48:57 UTC 2014 votingStart=Mon Sep 22 18:48:57 UTC 2014 promotedBy=111
clusterIdDefinedBy=111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /111 -- initiator=true
leaderElectionId=0_0000001411411735526_111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 vote=true jcr:primaryType=<unknown
type=7/>
22.09.2014 18:48:59 *INFO * [main] Instance: dumpRepo: ====== END =====
22.09.2014 18:48:59 *INFO * [main] ClusterTest: testAdditionalInstance: 1st 2s
sleep
22.09.2014 18:49:01 *INFO * [main] Instance: Instance
[ee49e4c9-04c8-4448-854d-0a4cb0020989] issues a heartbeat now Mon Sep 22
18:49:01 UTC 2014
22.09.2014 18:49:01 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:49:01 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:01 *INFO * [main] Instance: Instance
[1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e] issues a heartbeat now Mon Sep 22
18:49:01 UTC 2014
22.09.2014 18:49:01 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:49:01 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:01 *INFO * [main] ClusterTest: testAdditionalInstance: 2nd 2s
sleep
22.09.2014 18:49:03 *INFO * [main] Instance: dumpRepo: ====== START =====
22.09.2014 18:49:03 *INFO * [main] Instance: dumpRepo: repo =
org.apache.jackrabbit.core.RepositoryImpl@155e161
22.09.2014 18:49:03 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown
type=7/> jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown
type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /discovery --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /impl --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /clusterInstances --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /111 --
leaderElectionId=0_0000001411411735526_111 lastHeartbeat=Mon Sep 22 18:48:57
UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=f7675c4e-07ff-4df8-89eb-4d83ffbd7f71
22.09.2014 18:49:03 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 lastHeartbeat=Mon Sep 22 18:48:57
UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=9616a6db-0f1c-4ae1-bfc3-5ada52221669
22.09.2014 18:49:03 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/ee49e4c9-04c8-4448-854d-0a4cb0020989 --
leaderElectionId=0_0000001411411738271_ee49e4c9-04c8-4448-854d-0a4cb0020989
lastHeartbeat=Mon Sep 22 18:49:01 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=1fcbf1ec-525d-4b94-a49e-8d465e2c76d7
22.09.2014 18:49:03 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e --
leaderElectionId=0_0000001411411738585_1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e
lastHeartbeat=Mon Sep 22 18:49:01 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=31d8c37b-8104-459e-aeac-d8f5fe764c1f
22.09.2014 18:49:03 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /ongoingVotings --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/56af2e35-b438-46b5-8a05-1e8ff6454420 --
clusterId=7ec34441-9899-4584-a063-94485571b459 clusterIdDefinedAt=Mon Sep 22
18:48:57 UTC 2014 votingStart=Mon Sep 22 18:48:58 UTC 2014
clusterIdDefinedBy=111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /111 --
leaderElectionId=0_0000001411411735526_111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/ee49e4c9-04c8-4448-854d-0a4cb0020989 -- initiator=true
leaderElectionId=0_0000001411411738271_ee49e4c9-04c8-4448-854d-0a4cb0020989
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e --
leaderElectionId=0_0000001411411738585_1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e
vote=true jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /previousView --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /establishedView --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance:
/7ec34441-9899-4584-a063-94485571b459 -- leaderId=111 promotedAt=Mon Sep 22
18:48:58 UTC 2014 clusterId=7ec34441-9899-4584-a063-94485571b459
leaderElectionId=0_0000001411411735526_111 clusterIdDefinedAt=Mon Sep 22
18:48:57 UTC 2014 votingStart=Mon Sep 22 18:48:57 UTC 2014 promotedBy=111
clusterIdDefinedBy=111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /111 -- initiator=true
leaderElectionId=0_0000001411411735526_111 jcr:primaryType=<unknown type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: /000 --
leaderElectionId=0_0000001411411735851_000 vote=true jcr:primaryType=<unknown
type=7/>
22.09.2014 18:49:03 *INFO * [main] Instance: dumpRepo: ====== END =====
22.09.2014 18:49:03 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:49:03 *INFO * [main] ClusterTest:
clusterId1=56af2e35-b438-46b5-8a05-1e8ff6454420
22.09.2014 18:49:03 *INFO * [main] ClusterViewServiceImpl: getEstablishedView:
the existing established view does not incude the local instance yet! Assuming
isolated mode. If this occurs at runtime - other than at startup - it could
cause a pseudo-network-partition, see SLING-3432. Consider increasing
heartbeatTimeout then!
22.09.2014 18:49:03 *INFO * [main] ClusterTest:
clusterId2=6cc0d560-f1d9-4f50-b0e3-ec32326e24e3
22.09.2014 18:49:03 *INFO * [main] Instance: stop: stopping
slingId=1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e, debugName=secondInstance
22.09.2014 18:49:03 *INFO * [main] Instance: stop: removing listener for
slingId=1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e:
org.apache.sling.discovery.impl.setup.Instance$1@f9286d
22.09.2014 18:49:03 *INFO * [main] Instance: stop: stopped
slingId=1f480eb1-bc2e-4457-a6d0-0b881c8ebf7e, debugName=secondInstance
22.09.2014 18:49:03 *INFO * [main] Instance: stop: stopping
slingId=ee49e4c9-04c8-4448-854d-0a4cb0020989, debugName=firstInstance
22.09.2014 18:49:03 *INFO * [main] Instance: stop: removing listener for
slingId=ee49e4c9-04c8-4448-854d-0a4cb0020989:
org.apache.sling.discovery.impl.setup.Instance$1@377f8d
22.09.2014 18:49:03 *INFO * [main] Instance: stop: stopped
slingId=ee49e4c9-04c8-4448-854d-0a4cb0020989, debugName=firstInstance
22.09.2014 18:49:03 *INFO * [main] Instance: <init>: starting
slingId=24e3c331-9133-485c-a858-213865f1be07, debugName=firstInstance
22.09.2014 18:49:03 *ERROR* [ObservationManager] VotingView: vote: no
memberResource found for slingId=null, resource=MockedResource,
type=nt:unstructured,
path=/var/discovery/impl/ongoingVotings/56af2e35-b438-46b5-8a05-1e8ff6454420
22.09.2014 18:49:03 *ERROR* [ObservationManager] VotingView: vote: no
memberResource found for slingId=null, resource=MockedResource,
type=nt:unstructured,
path=/var/discovery/impl/ongoingVotings/56af2e35-b438-46b5-8a05-1e8ff6454420
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
22.09.2014 18:49:03 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
22.09.2014 18:49:04 *INFO * [main] Instance: <init>: starting
slingId=daf7697c-96f0-41e4-8348-712aa2d4472f, debugName=secondInstance
22.09.2014 18:49:04 *INFO * [main] ClusterTest: testLeaderAsc: start
22.09.2014 18:49:04 *INFO * [main] ClusterTest: doTestLeader(000,111): start
22.09.2014 18:49:04 *INFO * [main] Instance: stop: stopping
slingId=daf7697c-96f0-41e4-8348-712aa2d4472f, debugName=secondInstance
22.09.2014 18:49:04 *INFO * [main] Instance: stop: removing listener for
slingId=daf7697c-96f0-41e4-8348-712aa2d4472f:
org.apache.sling.discovery.impl.setup.Instance$1@c1c59b
22.09.2014 18:49:04 *INFO * [main] Instance: stop: stopped
slingId=daf7697c-96f0-41e4-8348-712aa2d4472f, debugName=secondInstance
22.09.2014 18:49:04 *INFO * [main] Instance: stop: stopping
slingId=24e3c331-9133-485c-a858-213865f1be07, debugName=firstInstance
22.09.2014 18:49:04 *INFO * [main] Instance: stop: removing listener for
slingId=24e3c331-9133-485c-a858-213865f1be07:
org.apache.sling.discovery.impl.setup.Instance$1@ddc608
22.09.2014 18:49:04 *INFO * [main] Instance: stop: stopped
slingId=24e3c331-9133-485c-a858-213865f1be07, debugName=firstInstance
22.09.2014 18:49:04 *INFO * [main] Instance: <init>: starting slingId=000,
debugName=firstInstance
22.09.2014 18:49:04 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms
22.09.2014 18:49:05 *INFO * [main] Instance: <init>: starting slingId=111,
debugName=secondInstance
22.09.2014 18:49:05 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:49:05 UTC 2014
22.09.2014 18:49:05 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:05 *INFO * [main] VotingHelper: getWinningVoting: no ongoing
votings parent resource found
22.09.2014 18:49:05 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no
ongoing votings parent resource found
22.09.2014 18:49:05 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:49:05 UTC 2014
22.09.2014 18:49:05 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:05 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms
22.09.2014 18:49:05 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:49:05 UTC 2014
22.09.2014 18:49:05 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:05 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:49:05 UTC 2014
22.09.2014 18:49:05 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:05 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms
22.09.2014 18:49:06 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Mon Sep 22 18:49:06 UTC 2014
22.09.2014 18:49:06 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:06 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Mon Sep 22 18:49:06 UTC 2014
22.09.2014 18:49:06 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
22.09.2014 18:49:06 *INFO * [main] ClusterTest: doTestLeader(000,111): end
22.09.2014 18:49:06 *INFO * [main] ClusterTest: testLeaderAsc: end
22.09.2014 18:49:06 *INFO * [main] Instance: stop: stopping slingId=111,
debugName=secondInstance
22.09.2014 18:49:06 *INFO * [main] Instance: stop: removing listener for
slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@142a80d
22.09.2014 18:49:06 *INFO * [main] Instance: stop: stopped slingId=111,
debugName=secondInstance
22.09.2014 18:49:06 *INFO * [main] Instance: stop: stopping slingId=000,
debugName=firstInstance
22.09.2014 18:49:06 *INFO * [main] Instance: stop: removing listener for
slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@1f738bc
22.09.2014 18:49:06 *INFO * [main] Instance: stop: stopped slingId=000,
debugName=firstInstance
Tests run: 6, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 35.121 sec <<<
FAILURE! - in org.apache.sling.discovery.impl.cluster.ClusterTest
testLeaderDesc(org.apache.sling.discovery.impl.cluster.ClusterTest) Time
elapsed: 4.076 sec <<< FAILURE!
java.lang.AssertionError: expected:<2> but was:<1>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:555)
at org.junit.Assert.assertEquals(Assert.java:542)
at
org.apache.sling.discovery.impl.cluster.ClusterTest.doTestLeader(ClusterTest.java:130)
at
org.apache.sling.discovery.impl.cluster.ClusterTest.testLeaderDesc(ClusterTest.java:91)
testAdditionalInstance(org.apache.sling.discovery.impl.cluster.ClusterTest)
Time elapsed: 5.554 sec <<< FAILURE!
org.junit.ComparisonFailure: expected:<[56af2e35-b438-46b5-8a05-1e8ff6454420]>
but was:<[6cc0d560-f1d9-4f50-b0e3-ec32326e24e3]>
at org.junit.Assert.assertEquals(Assert.java:115)
at org.junit.Assert.assertEquals(Assert.java:144)
at
org.apache.sling.discovery.impl.cluster.ClusterTest.testAdditionalInstance(ClusterTest.java:318)
Running org.apache.sling.discovery.impl.cluster.ClusterLoadTest
22.09.2014 18:49:06 *INFO * [main] ClusterLoadTest: doTest(6,9): muting log
output...
22.09.2014 18:51:36 *INFO * [main] ClusterLoadTest: doTest(6,9): not writing
muted log output due to success...
22.09.2014 18:51:36 *INFO * [main] ClusterLoadTest: doTest(6,9): unmuted log
output.
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=a4d13847-0ebd-40f6-82a7-a931cdd267ca, debugName=firstInstance
22.09.2014 18:51:36 *INFO * [main] Instance: Stopping Instance
[a4d13847-0ebd-40f6-82a7-a931cdd267ca]
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=a4d13847-0ebd-40f6-82a7-a931cdd267ca:
org.apache.sling.discovery.impl.setup.Instance$1@1609eea
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=a4d13847-0ebd-40f6-82a7-a931cdd267ca, debugName=firstInstance
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=98e1f2f1-c577-490f-964a-66ba11fed6cf, debugName=subsequentInstance-1
22.09.2014 18:51:36 *INFO * [main] Instance: Stopping Instance
[98e1f2f1-c577-490f-964a-66ba11fed6cf]
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=98e1f2f1-c577-490f-964a-66ba11fed6cf:
org.apache.sling.discovery.impl.setup.Instance$1@14193b6
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=98e1f2f1-c577-490f-964a-66ba11fed6cf, debugName=subsequentInstance-1
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=0f2275a4-26b2-4aeb-b58b-e95a9c2dbd4b, debugName=subsequentInstance-2
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=0f2275a4-26b2-4aeb-b58b-e95a9c2dbd4b:
org.apache.sling.discovery.impl.setup.Instance$1@14e12f5
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=0f2275a4-26b2-4aeb-b58b-e95a9c2dbd4b, debugName=subsequentInstance-2
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=865ca4e5-ed79-4c9c-8978-833ebc978a04, debugName=subsequentInstance-3
22.09.2014 18:51:36 *INFO * [main] Instance: Stopping Instance
[865ca4e5-ed79-4c9c-8978-833ebc978a04]
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=865ca4e5-ed79-4c9c-8978-833ebc978a04:
org.apache.sling.discovery.impl.setup.Instance$1@194e628
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=865ca4e5-ed79-4c9c-8978-833ebc978a04, debugName=subsequentInstance-3
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=830d1b2f-83aa-4517-9d9f-7c5b0ba224a6, debugName=subsequentInstance-4
22.09.2014 18:51:36 *INFO * [main] Instance: Stopping Instance
[830d1b2f-83aa-4517-9d9f-7c5b0ba224a6]
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=830d1b2f-83aa-4517-9d9f-7c5b0ba224a6:
org.apache.sling.discovery.impl.setup.Instance$1@18b7d0f
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=830d1b2f-83aa-4517-9d9f-7c5b0ba224a6, debugName=subsequentInstance-4
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopping
slingId=02d59d4e-a7aa-4da5-ac67-16d6fbfb7016, debugName=subsequentInstance-5
22.09.2014 18:51:36 *INFO * [main] Instance: Stopping Instance
[02d59d4e-a7aa-4da5-ac67-16d6fbfb7016]
22.09.2014 18:51:36 *INFO * [main] Instance: stop: removing listener for
slingId=02d59d4e-a7aa-4da5-ac67-16d6fbfb7016:
org.apache.sling.discovery.impl.setup.Instance$1@1dd8e99
22.09.2014 18:51:36 *INFO * [main] Instance: stop: stopped
slingId=02d59d4e-a7aa-4da5-ac67-16d6fbfb7016, debugName=subsequentInstance-5
22.09.2014 18:51:36 *INFO * [main] ClusterLoadTest: doTest(3,6): muting log
output...
22.09.2014 18:51:49 *INFO * [main] ClusterLoadTest: doTest(3,6): not writing
muted log output due to success...
22.09.2014 18:51:49 *INFO * [main] ClusterLoadTest: doTest(3,6): unmuted log
output.
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopping
slingId=74738c4d-1a33-45d1-ad67-81ef4a1b0e56, debugName=firstInstance
22.09.2014 18:51:49 *INFO * [main] Instance: Stopping Instance
[74738c4d-1a33-45d1-ad67-81ef4a1b0e56]
22.09.2014 18:51:49 *INFO * [main] Instance: stop: removing listener for
slingId=74738c4d-1a33-45d1-ad67-81ef4a1b0e56:
org.apache.sling.discovery.impl.setup.Instance$1@df0d2f
log4j:WARN No appenders could be found for logger
(org.apache.jackrabbit.core.session.SessionState).
log4j:WARN Please initialize the log4j system properly.
22.09.2014 18:51:49 *INFO * [Test-Heartbeat-Runner] ClusterViewServiceImpl:
getEstablishedView: the existing established view does not incude the local
instance yet! Assuming isolated mode. If this occurs at runtime - other than at
startup - it could cause a pseudo-network-partition, see SLING-3432. Consider
increasing heartbeatTimeout then!
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopped
slingId=74738c4d-1a33-45d1-ad67-81ef4a1b0e56, debugName=firstInstance
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopping
slingId=609968cd-c5d1-432f-afdc-67a4c344a315, debugName=subsequentInstance-1
22.09.2014 18:51:49 *INFO * [Test-Heartbeat-Runner] ClusterViewServiceImpl:
getEstablishedView: the existing established view does not incude the local
instance yet! Assuming isolated mode. If this occurs at runtime - other than at
startup - it could cause a pseudo-network-partition, see SLING-3432. Consider
increasing heartbeatTimeout then!
22.09.2014 18:51:49 *INFO * [main] Instance: Stopping Instance
[609968cd-c5d1-432f-afdc-67a4c344a315]
22.09.2014 18:51:49 *INFO * [main] Instance: stop: removing listener for
slingId=609968cd-c5d1-432f-afdc-67a4c344a315:
org.apache.sling.discovery.impl.setup.Instance$1@c30d65
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopped
slingId=609968cd-c5d1-432f-afdc-67a4c344a315, debugName=subsequentInstance-1
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopping
slingId=d078d7a0-e863-4795-a131-e19ab39292df, debugName=subsequentInstance-2
22.09.2014 18:51:49 *INFO * [main] Instance: stop: removing listener for
slingId=d078d7a0-e863-4795-a131-e19ab39292df:
org.apache.sling.discovery.impl.setup.Instance$1@19527d0
22.09.2014 18:51:49 *INFO * [main] Instance: stop: stopped
slingId=d078d7a0-e863-4795-a131-e19ab39292df, debugName=subsequentInstance-2
22.09.2014 18:51:49 *INFO * [main] ClusterLoadTest: doTest(7,10): muting log
output...
Killed
Results :
Failed tests:
ClusterTest.testLeaderDesc:91->doTestLeader:130 expected:<2> but was:<1>
ClusterTest.testAdditionalInstance:318
expected:<[56af2e35-b438-46b5-8a05-1e8ff6454420]> but
was:<[6cc0d560-f1d9-4f50-b0e3-ec32326e24e3]>
Tests run: 11, Failures: 2, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[JENKINS] Archiving disabled
