See
<https://builds.apache.org/job/sling-trunk-1.7/org.apache.sling$org.apache.sling.discovery.impl/721/>
------------------------------------------
[...truncated 864 lines...]
31.07.2014 01:17:32 *INFO * [main] Instance: Instance
[6bad8b59-a89f-45ce-89f1-992816e32d56] issues a heartbeat now Thu Jul 31
01:17:32 UTC 2014
31.07.2014 01:17:32 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:32 *INFO * [main] ClusterTest: testPropertyProviders: 2nd 2s
sleep
31.07.2014 01:17:33 *INFO * [pool-1-thread-3] HeartbeatHandler:
triggerHeartbeat: Could not trigger heartbeat:
org.quartz.ObjectAlreadyExistsException: Unable to store Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:33 *INFO * [pool-1-thread-2] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:33 *INFO * [pool-1-thread-5] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:34 *INFO * [pool-1-thread-1] HeartbeatHandler:
triggerHeartbeat: Could not trigger heartbeat:
org.quartz.ObjectAlreadyExistsException: Unable to store Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:34 *INFO * [main] HeartbeatHandler: triggerHeartbeat: Could
not trigger heartbeat: org.quartz.ObjectAlreadyExistsException: Unable to store
Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:34 *INFO * [pool-1-thread-1] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:34 *INFO * [main] Instance: Instance
[02577c07-f90c-4c39-8175-2375d50d578a] issues a heartbeat now Thu Jul 31
01:17:34 UTC 2014
31.07.2014 01:17:34 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:34 *INFO * [main] Instance: Instance
[3e7f2261-8c4f-410a-a35f-65f22402d087] issues a heartbeat now Thu Jul 31
01:17:34 UTC 2014
31.07.2014 01:17:34 *INFO * [main] HeartbeatHandler: triggerHeartbeat: Could
not trigger heartbeat: org.quartz.ObjectAlreadyExistsException: Unable to store
Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:34 *INFO * [pool-1-thread-3] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:34 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:34 *INFO * [main] ClusterTest: testPropertyProviders: end
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopping
slingId=6bad8b59-a89f-45ce-89f1-992816e32d56, debugName=thirdInstance
31.07.2014 01:17:34 *INFO * [main] Instance: stop: removing listener for
slingId=6bad8b59-a89f-45ce-89f1-992816e32d56:
org.apache.sling.discovery.impl.setup.Instance$1@6a1b79
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopped
slingId=6bad8b59-a89f-45ce-89f1-992816e32d56, debugName=thirdInstance
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopping
slingId=3e7f2261-8c4f-410a-a35f-65f22402d087, debugName=secondInstance
31.07.2014 01:17:34 *INFO * [main] Instance: stop: removing listener for
slingId=3e7f2261-8c4f-410a-a35f-65f22402d087:
org.apache.sling.discovery.impl.setup.Instance$1@18bd0ac
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopped
slingId=3e7f2261-8c4f-410a-a35f-65f22402d087, debugName=secondInstance
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopping
slingId=02577c07-f90c-4c39-8175-2375d50d578a, debugName=firstInstance
31.07.2014 01:17:34 *INFO * [main] Instance: stop: removing listener for
slingId=02577c07-f90c-4c39-8175-2375d50d578a:
org.apache.sling.discovery.impl.setup.Instance$1@1f1380b
31.07.2014 01:17:34 *INFO * [main] Instance: stop: stopped
slingId=02577c07-f90c-4c39-8175-2375d50d578a, debugName=firstInstance
31.07.2014 01:17:34 *INFO * [main] Instance: <init>: starting
slingId=c96d031d-166a-49ec-a2ba-b4703e71fdd5, debugName=firstInstance
31.07.2014 01:17:34 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
31.07.2014 01:17:34 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
31.07.2014 01:17:34 *INFO * [main] Instance: <init>: starting
slingId=d5c2ca5b-32df-4621-a665-fc0f2333d5e8, debugName=secondInstance
31.07.2014 01:17:35 *INFO * [main] ClusterTest: testLeaderDesc: start
31.07.2014 01:17:35 *INFO * [main] ClusterTest: doTestLeader(111,000): start
31.07.2014 01:17:35 *INFO * [main] Instance: stop: stopping
slingId=d5c2ca5b-32df-4621-a665-fc0f2333d5e8, debugName=secondInstance
31.07.2014 01:17:35 *INFO * [main] Instance: stop: removing listener for
slingId=d5c2ca5b-32df-4621-a665-fc0f2333d5e8:
org.apache.sling.discovery.impl.setup.Instance$1@ce81be
31.07.2014 01:17:35 *INFO * [main] Instance: stop: stopped
slingId=d5c2ca5b-32df-4621-a665-fc0f2333d5e8, debugName=secondInstance
31.07.2014 01:17:35 *INFO * [main] Instance: stop: stopping
slingId=c96d031d-166a-49ec-a2ba-b4703e71fdd5, debugName=firstInstance
31.07.2014 01:17:35 *INFO * [main] Instance: stop: removing listener for
slingId=c96d031d-166a-49ec-a2ba-b4703e71fdd5:
org.apache.sling.discovery.impl.setup.Instance$1@146e91a
31.07.2014 01:17:35 *INFO * [main] Instance: stop: stopped
slingId=c96d031d-166a-49ec-a2ba-b4703e71fdd5, debugName=firstInstance
31.07.2014 01:17:35 *INFO * [main] Instance: <init>: starting slingId=111,
debugName=firstInstance
31.07.2014 01:17:35 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms
31.07.2014 01:17:35 *INFO * [main] Instance: <init>: starting slingId=000,
debugName=secondInstance
31.07.2014 01:17:35 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:35 UTC 2014
31.07.2014 01:17:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:35 *INFO * [main] VotingHelper: getWinningVoting: no ongoing
votings parent resource found
31.07.2014 01:17:35 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no
ongoing votings parent resource found
31.07.2014 01:17:35 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:35 UTC 2014
31.07.2014 01:17:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:35 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms
31.07.2014 01:17:35 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:35 UTC 2014
31.07.2014 01:17:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:35 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:35 UTC 2014
31.07.2014 01:17:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:35 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms
31.07.2014 01:17:36 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:36 UTC 2014
31.07.2014 01:17:36 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:36 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:36 UTC 2014
31.07.2014 01:17:36 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:36 *INFO * [main] ClusterTest: doTestLeader(111,000): end
31.07.2014 01:17:36 *INFO * [main] ClusterTest: testLeaderDesc: end
31.07.2014 01:17:36 *INFO * [main] Instance: stop: stopping slingId=000,
debugName=secondInstance
31.07.2014 01:17:36 *INFO * [main] Instance: stop: removing listener for
slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@616408
31.07.2014 01:17:36 *INFO * [main] Instance: stop: stopped slingId=000,
debugName=secondInstance
31.07.2014 01:17:36 *INFO * [main] Instance: stop: stopping slingId=111,
debugName=firstInstance
31.07.2014 01:17:36 *INFO * [main] Instance: stop: removing listener for
slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@e807b0
31.07.2014 01:17:36 *INFO * [main] Instance: stop: stopped slingId=111,
debugName=firstInstance
31.07.2014 01:17:36 *INFO * [main] Instance: <init>: starting
slingId=9bb316d7-513f-422a-a90b-4483bd969105, debugName=firstInstance
31.07.2014 01:17:36 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
31.07.2014 01:17:36 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
31.07.2014 01:17:36 *INFO * [main] Instance: <init>: starting
slingId=ebfc9e8e-f659-4d89-940d-3ffca1e51277, debugName=secondInstance
31.07.2014 01:17:36 *INFO * [main] ClusterTest: testAdditionalInstance: start
31.07.2014 01:17:36 *INFO * [main] Instance: Instance
[9bb316d7-513f-422a-a90b-4483bd969105] issues a heartbeat now Thu Jul 31
01:17:36 UTC 2014
31.07.2014 01:17:36 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:36 *INFO * [main] VotingHelper: getWinningVoting: no ongoing
votings parent resource found
31.07.2014 01:17:36 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no
ongoing votings parent resource found
31.07.2014 01:17:36 *INFO * [main] Instance: Instance
[ebfc9e8e-f659-4d89-940d-3ffca1e51277] issues a heartbeat now Thu Jul 31
01:17:36 UTC 2014
31.07.2014 01:17:36 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:36 *INFO * [main] Instance: dumpRepo: ====== START =====
31.07.2014 01:17:36 *INFO * [main] Instance: dumpRepo: repo =
org.apache.jackrabbit.core.RepositoryImpl@1a089b3
31.07.2014 01:17:36 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown
type=7/> jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown
type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /discovery --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /impl --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /clusterInstances --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance:
/9bb316d7-513f-422a-a90b-4483bd969105 --
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
lastHeartbeat=Thu Jul 31 01:17:36 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=da85d455-6c08-4f15-b261-2ccf722ca09b
31.07.2014 01:17:36 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance:
/ebfc9e8e-f659-4d89-940d-3ffca1e51277 --
leaderElectionId=0_0000001406769456448_ebfc9e8e-f659-4d89-940d-3ffca1e51277
lastHeartbeat=Thu Jul 31 01:17:36 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=a04b899b-af4e-4da8-9a6d-e3092eb79976
31.07.2014 01:17:36 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /ongoingVotings --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /previousView --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /establishedView --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance:
/c495af28-5812-4ff9-8f15-8d5a230577ef --
leaderId=9bb316d7-513f-422a-a90b-4483bd969105 promotedAt=Thu Jul 31 01:17:36
UTC 2014 clusterId=c495af28-5812-4ff9-8f15-8d5a230577ef
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
clusterIdDefinedAt=Thu Jul 31 01:17:36 UTC 2014 votingStart=Thu Jul 31 01:17:36
UTC 2014 promotedBy=9bb316d7-513f-422a-a90b-4483bd969105
clusterIdDefinedBy=9bb316d7-513f-422a-a90b-4483bd969105
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance:
/ebfc9e8e-f659-4d89-940d-3ffca1e51277 --
leaderElectionId=0_0000001406769456448_ebfc9e8e-f659-4d89-940d-3ffca1e51277
vote=true jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance:
/9bb316d7-513f-422a-a90b-4483bd969105 -- initiator=true
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:36 *INFO * [main] Instance: dumpRepo: ====== END =====
31.07.2014 01:17:36 *INFO * [main] ClusterTest: testAdditionalInstance: 1st 2s
sleep
31.07.2014 01:17:38 *INFO * [main] Instance: Instance
[9bb316d7-513f-422a-a90b-4483bd969105] issues a heartbeat now Thu Jul 31
01:17:38 UTC 2014
31.07.2014 01:17:38 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:38 *INFO * [main] Instance: Instance
[ebfc9e8e-f659-4d89-940d-3ffca1e51277] issues a heartbeat now Thu Jul 31
01:17:38 UTC 2014
31.07.2014 01:17:38 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:38 *INFO * [main] ClusterTest: testAdditionalInstance: 2nd 2s
sleep
31.07.2014 01:17:39 *INFO * [pool-1-thread-1] HeartbeatHandler:
triggerHeartbeat: Could not trigger heartbeat:
org.quartz.ObjectAlreadyExistsException: Unable to store Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:39 *INFO * [pool-1-thread-3] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:40 *INFO * [main] Instance: dumpRepo: ====== START =====
31.07.2014 01:17:40 *INFO * [main] Instance: dumpRepo: repo =
org.apache.jackrabbit.core.RepositoryImpl@1a089b3
31.07.2014 01:17:40 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown
type=7/> jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown
type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /discovery --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /impl --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /clusterInstances --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance:
/9bb316d7-513f-422a-a90b-4483bd969105 --
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
lastHeartbeat=Thu Jul 31 01:17:39 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=da85d455-6c08-4f15-b261-2ccf722ca09b
31.07.2014 01:17:40 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance:
/ebfc9e8e-f659-4d89-940d-3ffca1e51277 --
leaderElectionId=0_0000001406769456448_ebfc9e8e-f659-4d89-940d-3ffca1e51277
lastHeartbeat=Thu Jul 31 01:17:38 UTC 2014 jcr:primaryType=<unknown type=7/>
runtimeId=a04b899b-af4e-4da8-9a6d-e3092eb79976
31.07.2014 01:17:40 *INFO * [main] Instance: /properties --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /ongoingVotings --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /previousView --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /establishedView --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance:
/c495af28-5812-4ff9-8f15-8d5a230577ef --
leaderId=9bb316d7-513f-422a-a90b-4483bd969105 promotedAt=Thu Jul 31 01:17:36
UTC 2014 clusterId=c495af28-5812-4ff9-8f15-8d5a230577ef
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
clusterIdDefinedAt=Thu Jul 31 01:17:36 UTC 2014 votingStart=Thu Jul 31 01:17:36
UTC 2014 promotedBy=9bb316d7-513f-422a-a90b-4483bd969105
clusterIdDefinedBy=9bb316d7-513f-422a-a90b-4483bd969105
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: /members --
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance:
/ebfc9e8e-f659-4d89-940d-3ffca1e51277 --
leaderElectionId=0_0000001406769456448_ebfc9e8e-f659-4d89-940d-3ffca1e51277
vote=true jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance:
/9bb316d7-513f-422a-a90b-4483bd969105 -- initiator=true
leaderElectionId=0_0000001406769456435_9bb316d7-513f-422a-a90b-4483bd969105
jcr:primaryType=<unknown type=7/>
31.07.2014 01:17:40 *INFO * [main] Instance: dumpRepo: ====== END =====
31.07.2014 01:17:40 *INFO * [main] ClusterTest:
clusterId1=c495af28-5812-4ff9-8f15-8d5a230577ef
31.07.2014 01:17:40 *INFO * [main] ClusterTest:
clusterId2=c495af28-5812-4ff9-8f15-8d5a230577ef
31.07.2014 01:17:40 *INFO * [main] Instance: <init>: starting
slingId=a4f77f29-61a8-4c12-9584-f53f9a7f7c11, debugName=thirdInstance
31.07.2014 01:17:40 *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!
31.07.2014 01:17:40 *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!
31.07.2014 01:17:40 *INFO * [main] Instance: Instance
[9bb316d7-513f-422a-a90b-4483bd969105] issues a heartbeat now Thu Jul 31
01:17:40 UTC 2014
31.07.2014 01:17:40 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:40 *INFO * [main] Instance: Instance
[ebfc9e8e-f659-4d89-940d-3ffca1e51277] issues a heartbeat now Thu Jul 31
01:17:40 UTC 2014
31.07.2014 01:17:40 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:40 *INFO * [main] Instance: Instance
[a4f77f29-61a8-4c12-9584-f53f9a7f7c11] issues a heartbeat now Thu Jul 31
01:17:40 UTC 2014
31.07.2014 01:17:40 *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!
31.07.2014 01:17:40 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:40 *INFO * [main] ClusterTest: testAdditionalInstance: 3rd 2s
sleep
31.07.2014 01:17:42 *INFO * [main] Instance: Instance
[9bb316d7-513f-422a-a90b-4483bd969105] issues a heartbeat now Thu Jul 31
01:17:42 UTC 2014
31.07.2014 01:17:42 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:42 *INFO * [main] Instance: Instance
[ebfc9e8e-f659-4d89-940d-3ffca1e51277] issues a heartbeat now Thu Jul 31
01:17:42 UTC 2014
31.07.2014 01:17:42 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:42 *INFO * [main] Instance: Instance
[a4f77f29-61a8-4c12-9584-f53f9a7f7c11] issues a heartbeat now Thu Jul 31
01:17:42 UTC 2014
31.07.2014 01:17:42 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:42 *INFO * [main] ClusterTest: testAdditionalInstance: 4th 2s
sleep
31.07.2014 01:17:43 *INFO * [pool-1-thread-4] HeartbeatHandler:
triggerHeartbeat: Could not trigger heartbeat:
org.quartz.ObjectAlreadyExistsException: Unable to store Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:17:43 *INFO * [pool-1-thread-5] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:43 *INFO * [pool-1-thread-3] HeartbeatHandler: doCheckView:
votingHandler is null!
31.07.2014 01:17:44 *INFO * [main] ClusterTest: testAdditionalInstance: end
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopping
slingId=a4f77f29-61a8-4c12-9584-f53f9a7f7c11, debugName=thirdInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: removing listener for
slingId=a4f77f29-61a8-4c12-9584-f53f9a7f7c11:
org.apache.sling.discovery.impl.setup.Instance$1@f073b3
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopped
slingId=a4f77f29-61a8-4c12-9584-f53f9a7f7c11, debugName=thirdInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopping
slingId=ebfc9e8e-f659-4d89-940d-3ffca1e51277, debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: removing listener for
slingId=ebfc9e8e-f659-4d89-940d-3ffca1e51277:
org.apache.sling.discovery.impl.setup.Instance$1@6c7f1f
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopped
slingId=ebfc9e8e-f659-4d89-940d-3ffca1e51277, debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopping
slingId=9bb316d7-513f-422a-a90b-4483bd969105, debugName=firstInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: removing listener for
slingId=9bb316d7-513f-422a-a90b-4483bd969105:
org.apache.sling.discovery.impl.setup.Instance$1@1cf91a1
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopped
slingId=9bb316d7-513f-422a-a90b-4483bd969105, debugName=firstInstance
31.07.2014 01:17:44 *INFO * [main] Instance: <init>: starting
slingId=3fcde2b1-af9a-4271-90c2-686a81d863ed, debugName=firstInstance
31.07.2014 01:17:44 *INFO * [ObservationManager] VotingHelper:
getWinningVoting: no ongoing votings parent resource found
31.07.2014 01:17:44 *INFO * [ObservationManager] VotingHelper:
listOpenNonWinningVotings: no ongoing votings parent resource found
31.07.2014 01:17:44 *INFO * [main] Instance: <init>: starting
slingId=3bbee211-4478-4499-b6e3-d5e1220f4069, debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] ClusterTest: testLeaderAsc: start
31.07.2014 01:17:44 *INFO * [main] ClusterTest: doTestLeader(000,111): start
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopping
slingId=3bbee211-4478-4499-b6e3-d5e1220f4069, debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: removing listener for
slingId=3bbee211-4478-4499-b6e3-d5e1220f4069:
org.apache.sling.discovery.impl.setup.Instance$1@11aacdb
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopped
slingId=3bbee211-4478-4499-b6e3-d5e1220f4069, debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopping
slingId=3fcde2b1-af9a-4271-90c2-686a81d863ed, debugName=firstInstance
31.07.2014 01:17:44 *INFO * [main] Instance: stop: removing listener for
slingId=3fcde2b1-af9a-4271-90c2-686a81d863ed:
org.apache.sling.discovery.impl.setup.Instance$1@1b4108a
31.07.2014 01:17:44 *INFO * [main] Instance: stop: stopped
slingId=3fcde2b1-af9a-4271-90c2-686a81d863ed, debugName=firstInstance
31.07.2014 01:17:44 *INFO * [main] Instance: <init>: starting slingId=000,
debugName=firstInstance
31.07.2014 01:17:44 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms
31.07.2014 01:17:44 *INFO * [main] Instance: <init>: starting slingId=111,
debugName=secondInstance
31.07.2014 01:17:44 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:44 UTC 2014
31.07.2014 01:17:44 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:44 *INFO * [main] VotingHelper: getWinningVoting: no ongoing
votings parent resource found
31.07.2014 01:17:44 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no
ongoing votings parent resource found
31.07.2014 01:17:45 *WARN * [main] ItemStateReferenceCache: overwriting cached
entry 759323d5-7724-4d97-bb66-f7e114a970d0/{}clusterId
31.07.2014 01:17:45 *WARN * [main] ItemStateReferenceCache: overwriting cached
entry 759323d5-7724-4d97-bb66-f7e114a970d0/{}clusterIdDefinedBy
31.07.2014 01:17:45 *WARN * [main] ItemStateReferenceCache: overwriting cached
entry 759323d5-7724-4d97-bb66-f7e114a970d0/{}votingStart
31.07.2014 01:17:45 *WARN * [ObservationManager] ItemStateReferenceCache:
overwriting cached entry a4020dec-7a7d-49af-8f8a-0532c46b78b8
31.07.2014 01:17:45 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:45 UTC 2014
31.07.2014 01:17:45 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:45 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms
31.07.2014 01:17:45 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:45 UTC 2014
31.07.2014 01:17:45 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:45 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:45 UTC 2014
31.07.2014 01:17:45 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:45 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms
31.07.2014 01:17:46 *INFO * [main] Instance: Instance [000] issues a heartbeat
now Thu Jul 31 01:17:46 UTC 2014
31.07.2014 01:17:46 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:46 *INFO * [main] Instance: Instance [111] issues a heartbeat
now Thu Jul 31 01:17:46 UTC 2014
31.07.2014 01:17:46 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler
is null!
31.07.2014 01:17:46 *INFO * [main] ClusterTest: doTestLeader(000,111): end
31.07.2014 01:17:46 *INFO * [main] ClusterTest: testLeaderAsc: end
31.07.2014 01:17:46 *INFO * [main] Instance: stop: stopping slingId=111,
debugName=secondInstance
31.07.2014 01:17:46 *INFO * [main] Instance: stop: removing listener for
slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@1949f78
31.07.2014 01:17:46 *INFO * [main] Instance: stop: stopped slingId=111,
debugName=secondInstance
31.07.2014 01:17:46 *INFO * [main] Instance: stop: stopping slingId=000,
debugName=firstInstance
31.07.2014 01:17:46 *INFO * [main] Instance: stop: removing listener for
slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@fc9124
31.07.2014 01:17:46 *INFO * [main] Instance: stop: stopped slingId=000,
debugName=firstInstance
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 24.138 sec - in
org.apache.sling.discovery.impl.cluster.ClusterTest
Running org.apache.sling.discovery.impl.cluster.ClusterLoadTest
31.07.2014 01:17:46 *INFO * [main] ClusterLoadTest: doTest(6,9): muting log
output...
log4j:WARN No appenders could be found for logger
(org.apache.jackrabbit.core.session.SessionState).
31.07.2014 01:18:07 *INFO * [main] ClusterLoadTest: doTest(6,9): not writing
muted log output due to success...
31.07.2014 01:18:07 *INFO * [main] ClusterLoadTest: doTest(6,9): unmuted log
output.
log4j:WARN No appenders could be found for logger
(org.apache.jackrabbit.core.session.SessionState).
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=ad07465a-3747-4829-b357-28dff3eaba33, debugName=firstInstance
log4j:WARN Please initialize the log4j system properly.
log4j:WARN Please initialize the log4j system properly.
31.07.2014 01:18:07 *INFO * [main] Instance: Stopping Instance
[ad07465a-3747-4829-b357-28dff3eaba33]
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=ad07465a-3747-4829-b357-28dff3eaba33:
org.apache.sling.discovery.impl.setup.Instance$1@b9683d
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=ad07465a-3747-4829-b357-28dff3eaba33, debugName=firstInstance
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=a218ecfc-0d63-4f85-8330-9c06f420ea2c, debugName=subsequentInstance-1
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=a218ecfc-0d63-4f85-8330-9c06f420ea2c:
org.apache.sling.discovery.impl.setup.Instance$1@8fa5f5
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=a218ecfc-0d63-4f85-8330-9c06f420ea2c, debugName=subsequentInstance-1
31.07.2014 01:18:07 *INFO * [Test-Heartbeat-Runner] HeartbeatHandler:
triggerHeartbeat: Could not trigger heartbeat:
org.quartz.ObjectAlreadyExistsException: Unable to store Job :
'DEFAULT.org.apache.sling.discovery.impl.common.heartbeat.HeartbeatHandler',
because one already exists with this identification.
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=1746e566-3e48-45f3-98ec-39124f48abb0, debugName=subsequentInstance-2
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=1746e566-3e48-45f3-98ec-39124f48abb0:
org.apache.sling.discovery.impl.setup.Instance$1@1abde1e
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=1746e566-3e48-45f3-98ec-39124f48abb0, debugName=subsequentInstance-2
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=70156f8a-d207-4d7b-8d4a-1ed3a5b9a95c, debugName=subsequentInstance-3
31.07.2014 01:18:07 *INFO * [main] Instance: Stopping Instance
[70156f8a-d207-4d7b-8d4a-1ed3a5b9a95c]
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=70156f8a-d207-4d7b-8d4a-1ed3a5b9a95c:
org.apache.sling.discovery.impl.setup.Instance$1@d21075
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=70156f8a-d207-4d7b-8d4a-1ed3a5b9a95c, debugName=subsequentInstance-3
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=61096171-948b-4326-8af9-c3dca37c1878, debugName=subsequentInstance-4
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=61096171-948b-4326-8af9-c3dca37c1878:
org.apache.sling.discovery.impl.setup.Instance$1@14b5b6e
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=61096171-948b-4326-8af9-c3dca37c1878, debugName=subsequentInstance-4
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopping
slingId=074ccf11-c086-4e3f-87aa-f80892542d5d, debugName=subsequentInstance-5
31.07.2014 01:18:07 *INFO * [main] Instance: stop: removing listener for
slingId=074ccf11-c086-4e3f-87aa-f80892542d5d:
org.apache.sling.discovery.impl.setup.Instance$1@135b33d
31.07.2014 01:18:07 *INFO * [main] Instance: stop: stopped
slingId=074ccf11-c086-4e3f-87aa-f80892542d5d, debugName=subsequentInstance-5
31.07.2014 01:18:07 *INFO * [main] ClusterLoadTest: doTest(3,6): muting log
output...
31.07.2014 01:18:13 *INFO * [main] ClusterLoadTest: doTest(3,6): not writing
muted log output due to success...
31.07.2014 01:18:13 *INFO * [main] ClusterLoadTest: doTest(3,6): unmuted log
output.
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopping
slingId=87a7f1c7-4ba7-4a29-b602-51f43371a406, debugName=firstInstance
31.07.2014 01:18:13 *INFO * [main] Instance: stop: removing listener for
slingId=87a7f1c7-4ba7-4a29-b602-51f43371a406:
org.apache.sling.discovery.impl.setup.Instance$1@153f590
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopped
slingId=87a7f1c7-4ba7-4a29-b602-51f43371a406, debugName=firstInstance
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopping
slingId=39372c9a-f568-4414-ad0a-df3b2ef8eaa5, debugName=subsequentInstance-1
31.07.2014 01:18:13 *INFO * [main] Instance: stop: removing listener for
slingId=39372c9a-f568-4414-ad0a-df3b2ef8eaa5:
org.apache.sling.discovery.impl.setup.Instance$1@485ab4
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopped
slingId=39372c9a-f568-4414-ad0a-df3b2ef8eaa5, debugName=subsequentInstance-1
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopping
slingId=2dea54a7-2bc1-43eb-8864-9f6bfd6e8460, debugName=subsequentInstance-2
31.07.2014 01:18:13 *INFO * [main] Instance: Stopping Instance
[2dea54a7-2bc1-43eb-8864-9f6bfd6e8460]
31.07.2014 01:18:13 *INFO * [main] Instance: stop: removing listener for
slingId=2dea54a7-2bc1-43eb-8864-9f6bfd6e8460:
org.apache.sling.discovery.impl.setup.Instance$1@10f892d
31.07.2014 01:18:13 *INFO * [main] Instance: stop: stopped
slingId=2dea54a7-2bc1-43eb-8864-9f6bfd6e8460, debugName=subsequentInstance-2
31.07.2014 01:18:13 *INFO * [main] ClusterLoadTest: doTest(7,10): muting log
output...
Killed
Results :
Tests run: 11, Failures: 0, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[JENKINS] Archiving disabled
