See <https://builds.apache.org/job/sling-trunk-1.8/org.apache.sling$org.apache.sling.discovery.impl/262/>
------------------------------------------ [...truncated 808 lines...] 08.10.2014 17:00:22 *INFO * [main] Instance: /3b05f545-585f-4252-aae0-e0b3ba803821 -- clusterId=3b05f545-585f-4252-aae0-e0b3ba803821 promotedAt=Wed Oct 08 17:00:18 UTC 2014 promotedBy=1e4db298-1d80-4fc0-9361-e493d05fab1e leaderId=1e4db298-1d80-4fc0-9361-e493d05fab1e clusterIdDefinedBy=1e4db298-1d80-4fc0-9361-e493d05fab1e sling:resourceType=sling:Folder votingStart=Wed Oct 08 17:00:18 UTC 2014 clusterIdDefinedAt=Wed Oct 08 17:00:18 UTC 2014 jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787618793_1e4db298-1d80-4fc0-9361-e493d05fab1e 08.10.2014 17:00:22 *INFO * [main] Instance: /members -- jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:22 *INFO * [main] Instance: /1e4db298-1d80-4fc0-9361-e493d05fab1e -- initiator=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787618793_1e4db298-1d80-4fc0-9361-e493d05fab1e 08.10.2014 17:00:22 *INFO * [main] Instance: /d76aab25-9262-49f5-bf3b-b82bb2088170 -- vote=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787618834_d76aab25-9262-49f5-bf3b-b82bb2088170 08.10.2014 17:00:22 *INFO * [main] Instance: /establishedView -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:22 *INFO * [main] Instance: /83b56285-4a0b-4a89-b701-c1887aa8b9a6 -- clusterId=3b05f545-585f-4252-aae0-e0b3ba803821 promotedAt=Wed Oct 08 17:00:21 UTC 2014 promotedBy=1e4db298-1d80-4fc0-9361-e493d05fab1e leaderId=1e4db298-1d80-4fc0-9361-e493d05fab1e clusterIdDefinedBy=1e4db298-1d80-4fc0-9361-e493d05fab1e sling:resourceType=sling:Folder votingStart=Wed Oct 08 17:00:21 UTC 2014 clusterIdDefinedAt=Wed Oct 08 17:00:18 UTC 2014 jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787618793_1e4db298-1d80-4fc0-9361-e493d05fab1e 08.10.2014 17:00:22 *INFO * [main] Instance: /members -- jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:22 *INFO * [main] Instance: /1e4db298-1d80-4fc0-9361-e493d05fab1e -- initiator=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787618793_1e4db298-1d80-4fc0-9361-e493d05fab1e 08.10.2014 17:00:22 *INFO * [main] Instance: dumpRepo: ====== END ===== 08.10.2014 17:00:22 *INFO * [pool-1-thread-4] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:22 *INFO * [main] ClusterTest: expected cluster id: 3b05f545-585f-4252-aae0-e0b3ba803821 08.10.2014 17:00:22 *INFO * [main] ClusterTest: actual cluster id: 3b05f545-585f-4252-aae0-e0b3ba803821 08.10.2014 17:00:22 *INFO * [main] ClusterTest: testStableClusterId: end 08.10.2014 17:00:22 *INFO * [main] Instance: stop: stopping slingId=d76aab25-9262-49f5-bf3b-b82bb2088170, debugName=secondInstance 08.10.2014 17:00:22 *INFO * [main] Instance: stop: removing listener for slingId=d76aab25-9262-49f5-bf3b-b82bb2088170: org.apache.sling.discovery.impl.setup.Instance$1@15914bb5 08.10.2014 17:00:22 *INFO * [main] Instance: stop: stopped slingId=d76aab25-9262-49f5-bf3b-b82bb2088170, debugName=secondInstance 08.10.2014 17:00:22 *INFO * [main] Instance: stop: stopping slingId=1e4db298-1d80-4fc0-9361-e493d05fab1e, debugName=firstInstance 08.10.2014 17:00:22 *INFO * [main] Instance: stop: removing listener for slingId=1e4db298-1d80-4fc0-9361-e493d05fab1e: org.apache.sling.discovery.impl.setup.Instance$1@563263a 08.10.2014 17:00:22 *INFO * [main] Instance: stop: stopped slingId=1e4db298-1d80-4fc0-9361-e493d05fab1e, debugName=firstInstance 08.10.2014 17:00:22 *INFO * [main] Instance: <init>: starting slingId=ba43d086-db24-4dd1-9995-178f6256599c, debugName=firstInstance 08.10.2014 17:00:22 *INFO * [ObservationManager] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:22 *INFO * [ObservationManager] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:22 *INFO * [main] Instance: <init>: starting slingId=7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e, debugName=secondInstance 08.10.2014 17:00:22 *INFO * [main] ClusterTest: testPropertyProviders: start 08.10.2014 17:00:22 *INFO * [main] Instance: Instance [ba43d086-db24-4dd1-9995-178f6256599c] issues a heartbeat now Wed Oct 08 17:00:22 UTC 2014 08.10.2014 17:00:22 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:22 *INFO * [main] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:22 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:22 *INFO * [main] Instance: Instance [7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e] issues a heartbeat now Wed Oct 08 17:00:22 UTC 2014 08.10.2014 17:00:22 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:22 *INFO * [main] Instance: <init>: starting slingId=5eb3c934-31f8-4eeb-903b-843ef5cb8d10, debugName=thirdInstance 08.10.2014 17:00:23 *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! 08.10.2014 17:00:23 *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! 08.10.2014 17:00:23 *INFO * [main] Instance: Instance [5eb3c934-31f8-4eeb-903b-843ef5cb8d10] issues a heartbeat now Wed Oct 08 17:00:23 UTC 2014 08.10.2014 17:00:23 *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! 08.10.2014 17:00:23 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:23 *INFO * [main] ClusterTest: testPropertyProviders: 1st 2s sleep 08.10.2014 17:00:23 *INFO * [pool-1-thread-5] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:25 *INFO * [main] Instance: Instance [ba43d086-db24-4dd1-9995-178f6256599c] issues a heartbeat now Wed Oct 08 17:00:25 UTC 2014 08.10.2014 17:00:25 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:25 *INFO * [main] Instance: Instance [7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e] issues a heartbeat now Wed Oct 08 17:00:25 UTC 2014 08.10.2014 17:00:25 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:25 *INFO * [main] Instance: Instance [5eb3c934-31f8-4eeb-903b-843ef5cb8d10] issues a heartbeat now Wed Oct 08 17:00:25 UTC 2014 08.10.2014 17:00:25 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:25 *INFO * [main] ClusterTest: testPropertyProviders: 2nd 2s sleep 08.10.2014 17:00:26 *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. 08.10.2014 17:00:26 *INFO * [pool-1-thread-1] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:27 *INFO * [pool-1-thread-2] 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. 08.10.2014 17:00:27 *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. 08.10.2014 17:00:27 *INFO * [pool-1-thread-2] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:27 *INFO * [main] Instance: Instance [ba43d086-db24-4dd1-9995-178f6256599c] issues a heartbeat now Wed Oct 08 17:00:27 UTC 2014 08.10.2014 17:00:27 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:27 *INFO * [main] Instance: Instance [7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e] issues a heartbeat now Wed Oct 08 17:00:27 UTC 2014 08.10.2014 17:00:27 *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. 08.10.2014 17:00:27 *INFO * [pool-1-thread-5] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:27 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:27 *INFO * [main] ClusterTest: testPropertyProviders: end 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopping slingId=5eb3c934-31f8-4eeb-903b-843ef5cb8d10, debugName=thirdInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: removing listener for slingId=5eb3c934-31f8-4eeb-903b-843ef5cb8d10: org.apache.sling.discovery.impl.setup.Instance$1@231d3ce 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopped slingId=5eb3c934-31f8-4eeb-903b-843ef5cb8d10, debugName=thirdInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopping slingId=7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e, debugName=secondInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: removing listener for slingId=7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e: org.apache.sling.discovery.impl.setup.Instance$1@3dd66ff5 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopped slingId=7bf5c1f1-b28b-4fba-9c5f-dddc0ece8a7e, debugName=secondInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopping slingId=ba43d086-db24-4dd1-9995-178f6256599c, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: removing listener for slingId=ba43d086-db24-4dd1-9995-178f6256599c: org.apache.sling.discovery.impl.setup.Instance$1@26612078 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopped slingId=ba43d086-db24-4dd1-9995-178f6256599c, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [main] Instance: <init>: starting slingId=14c9989f-38e4-42ba-af94-71ff1ae7b4c3, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [ObservationManager] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:27 *INFO * [ObservationManager] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:27 *INFO * [main] Instance: <init>: starting slingId=783b5ff0-bc71-4244-a054-3039ad14826d, debugName=secondInstance 08.10.2014 17:00:27 *INFO * [main] ClusterTest: testLeaderDesc: start 08.10.2014 17:00:27 *INFO * [main] ClusterTest: doTestLeader(111,000): start 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopping slingId=783b5ff0-bc71-4244-a054-3039ad14826d, debugName=secondInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: removing listener for slingId=783b5ff0-bc71-4244-a054-3039ad14826d: org.apache.sling.discovery.impl.setup.Instance$1@7c200e57 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopped slingId=783b5ff0-bc71-4244-a054-3039ad14826d, debugName=secondInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopping slingId=14c9989f-38e4-42ba-af94-71ff1ae7b4c3, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [main] Instance: stop: removing listener for slingId=14c9989f-38e4-42ba-af94-71ff1ae7b4c3: org.apache.sling.discovery.impl.setup.Instance$1@6ae32ff0 08.10.2014 17:00:27 *INFO * [main] Instance: stop: stopped slingId=14c9989f-38e4-42ba-af94-71ff1ae7b4c3, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [main] Instance: <init>: starting slingId=111, debugName=firstInstance 08.10.2014 17:00:27 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms 08.10.2014 17:00:28 *INFO * [main] Instance: <init>: starting slingId=000, debugName=secondInstance 08.10.2014 17:00:28 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:28 UTC 2014 08.10.2014 17:00:28 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:28 *INFO * [main] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:28 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:28 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:28 UTC 2014 08.10.2014 17:00:28 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:28 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms 08.10.2014 17:00:28 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:28 UTC 2014 08.10.2014 17:00:28 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:28 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:28 UTC 2014 08.10.2014 17:00:28 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:28 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms 08.10.2014 17:00:29 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:29 UTC 2014 08.10.2014 17:00:29 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:29 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:29 UTC 2014 08.10.2014 17:00:29 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:29 *INFO * [main] ClusterTest: doTestLeader(111,000): end 08.10.2014 17:00:29 *INFO * [main] ClusterTest: testLeaderDesc: end 08.10.2014 17:00:29 *INFO * [main] Instance: stop: stopping slingId=000, debugName=secondInstance 08.10.2014 17:00:29 *INFO * [main] Instance: stop: removing listener for slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@44a98a23 08.10.2014 17:00:29 *INFO * [main] Instance: stop: stopped slingId=000, debugName=secondInstance 08.10.2014 17:00:29 *INFO * [main] Instance: stop: stopping slingId=111, debugName=firstInstance 08.10.2014 17:00:29 *INFO * [main] Instance: stop: removing listener for slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@1d33e72e 08.10.2014 17:00:29 *INFO * [main] Instance: stop: stopped slingId=111, debugName=firstInstance 08.10.2014 17:00:29 *INFO * [main] Instance: <init>: starting slingId=fad2606d-81f7-4e4f-9c70-b565fc69dd60, debugName=firstInstance 08.10.2014 17:00:29 *INFO * [ObservationManager] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:29 *INFO * [ObservationManager] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:29 *INFO * [main] Instance: <init>: starting slingId=0af370ee-b4a2-4640-b95f-ed1576f2b098, debugName=secondInstance 08.10.2014 17:00:29 *INFO * [main] ClusterTest: testAdditionalInstance: start 08.10.2014 17:00:29 *INFO * [main] Instance: Instance [fad2606d-81f7-4e4f-9c70-b565fc69dd60] issues a heartbeat now Wed Oct 08 17:00:29 UTC 2014 08.10.2014 17:00:29 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:29 *INFO * [main] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:29 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:29 *INFO * [main] Instance: Instance [0af370ee-b4a2-4640-b95f-ed1576f2b098] issues a heartbeat now Wed Oct 08 17:00:29 UTC 2014 08.10.2014 17:00:29 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:29 *INFO * [main] Instance: dumpRepo: ====== START ===== 08.10.2014 17:00:29 *INFO * [main] Instance: dumpRepo: repo = org.apache.jackrabbit.core.RepositoryImpl@7a8406c2 08.10.2014 17:00:29 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown type=7/> jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:29 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /discovery -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /impl -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /clusterInstances -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /fad2606d-81f7-4e4f-9c70-b565fc69dd60 -- runtimeId=f57c2139-b2d9-4f36-baf3-2bbb8405e095 lastHeartbeat=Wed Oct 08 17:00:29 UTC 2014 sling:resourceType=sling:Folder jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:29 *INFO * [main] Instance: /properties -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /0af370ee-b4a2-4640-b95f-ed1576f2b098 -- runtimeId=0cf7eb7c-5e0d-413c-af20-10a33c8a0e38 lastHeartbeat=Wed Oct 08 17:00:29 UTC 2014 sling:resourceType=sling:Folder jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629455_0af370ee-b4a2-4640-b95f-ed1576f2b098 08.10.2014 17:00:29 *INFO * [main] Instance: /properties -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /ongoingVotings -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /775a1e2e-36aa-4cb2-943e-098254a46673 -- clusterId=775a1e2e-36aa-4cb2-943e-098254a46673 clusterIdDefinedBy=fad2606d-81f7-4e4f-9c70-b565fc69dd60 sling:resourceType=sling:Folder votingStart=Wed Oct 08 17:00:29 UTC 2014 clusterIdDefinedAt=Wed Oct 08 17:00:29 UTC 2014 jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:29 *INFO * [main] Instance: /members -- jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:29 *INFO * [main] Instance: /fad2606d-81f7-4e4f-9c70-b565fc69dd60 -- initiator=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:29 *INFO * [main] Instance: /0af370ee-b4a2-4640-b95f-ed1576f2b098 -- vote=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629455_0af370ee-b4a2-4640-b95f-ed1576f2b098 08.10.2014 17:00:29 *INFO * [main] Instance: /previousView -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /establishedView -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:29 *INFO * [main] Instance: /775a1e2e-36aa-4cb2-943e-098254a46673 -- clusterId=775a1e2e-36aa-4cb2-943e-098254a46673 promotedAt=Wed Oct 08 17:00:29 UTC 2014 promotedBy=fad2606d-81f7-4e4f-9c70-b565fc69dd60 leaderId=fad2606d-81f7-4e4f-9c70-b565fc69dd60 clusterIdDefinedBy=fad2606d-81f7-4e4f-9c70-b565fc69dd60 sling:resourceType=sling:Folder votingStart=Wed Oct 08 17:00:29 UTC 2014 clusterIdDefinedAt=Wed Oct 08 17:00:29 UTC 2014 jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:29 *INFO * [main] Instance: /members -- jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:29 *INFO * [main] Instance: /fad2606d-81f7-4e4f-9c70-b565fc69dd60 -- initiator=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:29 *INFO * [main] Instance: /0af370ee-b4a2-4640-b95f-ed1576f2b098 -- vote=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629455_0af370ee-b4a2-4640-b95f-ed1576f2b098 08.10.2014 17:00:29 *INFO * [main] Instance: dumpRepo: ====== END ===== 08.10.2014 17:00:29 *INFO * [main] ClusterTest: testAdditionalInstance: 1st 2s sleep 08.10.2014 17:00:31 *INFO * [main] Instance: Instance [fad2606d-81f7-4e4f-9c70-b565fc69dd60] issues a heartbeat now Wed Oct 08 17:00:31 UTC 2014 08.10.2014 17:00:31 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:31 *INFO * [main] Instance: Instance [0af370ee-b4a2-4640-b95f-ed1576f2b098] issues a heartbeat now Wed Oct 08 17:00:31 UTC 2014 08.10.2014 17:00:31 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:31 *INFO * [main] ClusterTest: testAdditionalInstance: 2nd 2s sleep 08.10.2014 17:00:32 *INFO * [pool-1-thread-2] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:32 *INFO * [pool-1-thread-3] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:33 *INFO * [main] Instance: dumpRepo: ====== START ===== 08.10.2014 17:00:33 *INFO * [main] Instance: dumpRepo: repo = org.apache.jackrabbit.core.RepositoryImpl@7a8406c2 08.10.2014 17:00:33 *INFO * [main] Instance: / -- jcr:mixinTypes=<unknown type=7/> jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:33 *INFO * [main] Instance: /var -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /discovery -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /impl -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /clusterInstances -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /fad2606d-81f7-4e4f-9c70-b565fc69dd60 -- runtimeId=f57c2139-b2d9-4f36-baf3-2bbb8405e095 lastHeartbeat=Wed Oct 08 17:00:32 UTC 2014 sling:resourceType=sling:Folder jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:33 *INFO * [main] Instance: /properties -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /0af370ee-b4a2-4640-b95f-ed1576f2b098 -- runtimeId=0cf7eb7c-5e0d-413c-af20-10a33c8a0e38 lastHeartbeat=Wed Oct 08 17:00:32 UTC 2014 sling:resourceType=sling:Folder jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629455_0af370ee-b4a2-4640-b95f-ed1576f2b098 08.10.2014 17:00:33 *INFO * [main] Instance: /properties -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /ongoingVotings -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /previousView -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /establishedView -- jcr:primaryType=<unknown type=7/> sling:resourceType=sling:Folder 08.10.2014 17:00:33 *INFO * [main] Instance: /775a1e2e-36aa-4cb2-943e-098254a46673 -- clusterId=775a1e2e-36aa-4cb2-943e-098254a46673 promotedAt=Wed Oct 08 17:00:29 UTC 2014 promotedBy=fad2606d-81f7-4e4f-9c70-b565fc69dd60 leaderId=fad2606d-81f7-4e4f-9c70-b565fc69dd60 clusterIdDefinedBy=fad2606d-81f7-4e4f-9c70-b565fc69dd60 sling:resourceType=sling:Folder votingStart=Wed Oct 08 17:00:29 UTC 2014 clusterIdDefinedAt=Wed Oct 08 17:00:29 UTC 2014 jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:33 *INFO * [main] Instance: /members -- jcr:primaryType=<unknown type=7/> 08.10.2014 17:00:33 *INFO * [main] Instance: /fad2606d-81f7-4e4f-9c70-b565fc69dd60 -- initiator=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629407_fad2606d-81f7-4e4f-9c70-b565fc69dd60 08.10.2014 17:00:33 *INFO * [main] Instance: /0af370ee-b4a2-4640-b95f-ed1576f2b098 -- vote=true jcr:primaryType=<unknown type=7/> leaderElectionId=0_0000001412787629455_0af370ee-b4a2-4640-b95f-ed1576f2b098 08.10.2014 17:00:33 *INFO * [main] Instance: dumpRepo: ====== END ===== 08.10.2014 17:00:33 *INFO * [main] ClusterTest: clusterId1=775a1e2e-36aa-4cb2-943e-098254a46673 08.10.2014 17:00:33 *INFO * [main] ClusterTest: clusterId2=775a1e2e-36aa-4cb2-943e-098254a46673 08.10.2014 17:00:33 *INFO * [main] Instance: <init>: starting slingId=41c0b8a3-64d3-4c04-beb4-9e7501e542ec, debugName=thirdInstance 08.10.2014 17:00:33 *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! 08.10.2014 17:00:33 *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! 08.10.2014 17:00:33 *INFO * [main] Instance: Instance [fad2606d-81f7-4e4f-9c70-b565fc69dd60] issues a heartbeat now Wed Oct 08 17:00:33 UTC 2014 08.10.2014 17:00:33 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:33 *INFO * [main] Instance: Instance [0af370ee-b4a2-4640-b95f-ed1576f2b098] issues a heartbeat now Wed Oct 08 17:00:33 UTC 2014 08.10.2014 17:00:33 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:33 *INFO * [main] Instance: Instance [41c0b8a3-64d3-4c04-beb4-9e7501e542ec] issues a heartbeat now Wed Oct 08 17:00:33 UTC 2014 08.10.2014 17:00:33 *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! 08.10.2014 17:00:33 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:33 *INFO * [main] ClusterTest: testAdditionalInstance: 3rd 2s sleep 08.10.2014 17:00:35 *INFO * [main] Instance: Instance [fad2606d-81f7-4e4f-9c70-b565fc69dd60] issues a heartbeat now Wed Oct 08 17:00:35 UTC 2014 08.10.2014 17:00:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:35 *INFO * [main] Instance: Instance [0af370ee-b4a2-4640-b95f-ed1576f2b098] issues a heartbeat now Wed Oct 08 17:00:35 UTC 2014 08.10.2014 17:00:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:35 *INFO * [main] Instance: Instance [41c0b8a3-64d3-4c04-beb4-9e7501e542ec] issues a heartbeat now Wed Oct 08 17:00:35 UTC 2014 08.10.2014 17:00:35 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:35 *INFO * [main] ClusterTest: testAdditionalInstance: 4th 2s sleep 08.10.2014 17:00:36 *INFO * [pool-1-thread-2] 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. 08.10.2014 17:00:36 *INFO * [pool-1-thread-5] 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. 08.10.2014 17:00:36 *INFO * [pool-1-thread-1] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:37 *INFO * [main] ClusterTest: testAdditionalInstance: end 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopping slingId=41c0b8a3-64d3-4c04-beb4-9e7501e542ec, debugName=thirdInstance 08.10.2014 17:00:37 *INFO * [main] Instance: stop: removing listener for slingId=41c0b8a3-64d3-4c04-beb4-9e7501e542ec: org.apache.sling.discovery.impl.setup.Instance$1@3a83cfbc 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopped slingId=41c0b8a3-64d3-4c04-beb4-9e7501e542ec, debugName=thirdInstance 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopping slingId=0af370ee-b4a2-4640-b95f-ed1576f2b098, debugName=secondInstance 08.10.2014 17:00:37 *INFO * [main] Instance: stop: removing listener for slingId=0af370ee-b4a2-4640-b95f-ed1576f2b098: org.apache.sling.discovery.impl.setup.Instance$1@22ea6051 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopped slingId=0af370ee-b4a2-4640-b95f-ed1576f2b098, debugName=secondInstance 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopping slingId=fad2606d-81f7-4e4f-9c70-b565fc69dd60, debugName=firstInstance 08.10.2014 17:00:37 *INFO * [main] Instance: stop: removing listener for slingId=fad2606d-81f7-4e4f-9c70-b565fc69dd60: org.apache.sling.discovery.impl.setup.Instance$1@3a9040f0 08.10.2014 17:00:37 *INFO * [main] Instance: stop: stopped slingId=fad2606d-81f7-4e4f-9c70-b565fc69dd60, debugName=firstInstance 08.10.2014 17:00:37 *INFO * [main] Instance: <init>: starting slingId=f6b7d406-da98-4fe0-a0df-a47ebae2f8a3, debugName=firstInstance 08.10.2014 17:00:37 *INFO * [ObservationManager] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:37 *INFO * [ObservationManager] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:37 *INFO * [main] Instance: <init>: starting slingId=381136a2-8b44-4674-94f5-3ec50be02c14, debugName=secondInstance 08.10.2014 17:00:38 *INFO * [main] ClusterTest: testLeaderAsc: start 08.10.2014 17:00:38 *INFO * [main] ClusterTest: doTestLeader(000,111): start 08.10.2014 17:00:38 *INFO * [main] Instance: stop: stopping slingId=381136a2-8b44-4674-94f5-3ec50be02c14, debugName=secondInstance 08.10.2014 17:00:38 *INFO * [main] Instance: stop: removing listener for slingId=381136a2-8b44-4674-94f5-3ec50be02c14: org.apache.sling.discovery.impl.setup.Instance$1@5b4ce00 08.10.2014 17:00:38 *INFO * [main] Instance: stop: stopped slingId=381136a2-8b44-4674-94f5-3ec50be02c14, debugName=secondInstance 08.10.2014 17:00:38 *INFO * [main] Instance: stop: stopping slingId=f6b7d406-da98-4fe0-a0df-a47ebae2f8a3, debugName=firstInstance 08.10.2014 17:00:38 *INFO * [main] Instance: stop: removing listener for slingId=f6b7d406-da98-4fe0-a0df-a47ebae2f8a3: org.apache.sling.discovery.impl.setup.Instance$1@260fffec 08.10.2014 17:00:38 *INFO * [main] Instance: stop: stopped slingId=f6b7d406-da98-4fe0-a0df-a47ebae2f8a3, debugName=firstInstance 08.10.2014 17:00:38 *INFO * [main] Instance: <init>: starting slingId=000, debugName=firstInstance 08.10.2014 17:00:38 *INFO * [main] ClusterTest: doTestLeader: 1st sleep 200ms 08.10.2014 17:00:38 *INFO * [main] Instance: <init>: starting slingId=111, debugName=secondInstance 08.10.2014 17:00:38 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:38 UTC 2014 08.10.2014 17:00:38 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:38 *INFO * [main] VotingHelper: getWinningVoting: no ongoing votings parent resource found 08.10.2014 17:00:38 *INFO * [main] VotingHelper: listOpenNonWinningVotings: no ongoing votings parent resource found 08.10.2014 17:00:38 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:38 UTC 2014 08.10.2014 17:00:38 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:38 *INFO * [main] ClusterTest: doTestLeader: 2nd sleep 500ms 08.10.2014 17:00:39 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:39 UTC 2014 08.10.2014 17:00:39 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:39 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:39 UTC 2014 08.10.2014 17:00:39 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:39 *INFO * [main] ClusterTest: doTestLeader: 3rd sleep 500ms 08.10.2014 17:00:39 *INFO * [main] Instance: Instance [000] issues a heartbeat now Wed Oct 08 17:00:39 UTC 2014 08.10.2014 17:00:39 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:39 *INFO * [main] Instance: Instance [111] issues a heartbeat now Wed Oct 08 17:00:39 UTC 2014 08.10.2014 17:00:39 *INFO * [main] HeartbeatHandler: doCheckView: votingHandler is null! 08.10.2014 17:00:39 *INFO * [main] ClusterTest: doTestLeader(000,111): end 08.10.2014 17:00:39 *INFO * [main] ClusterTest: testLeaderAsc: end 08.10.2014 17:00:39 *INFO * [main] Instance: stop: stopping slingId=111, debugName=secondInstance 08.10.2014 17:00:39 *INFO * [main] Instance: stop: removing listener for slingId=111: org.apache.sling.discovery.impl.setup.Instance$1@3514df8d 08.10.2014 17:00:39 *INFO * [main] Instance: stop: stopped slingId=111, debugName=secondInstance 08.10.2014 17:00:39 *INFO * [main] Instance: stop: stopping slingId=000, debugName=firstInstance 08.10.2014 17:00:39 *INFO * [main] Instance: stop: removing listener for slingId=000: org.apache.sling.discovery.impl.setup.Instance$1@4fe3199d 08.10.2014 17:00:39 *INFO * [main] Instance: stop: stopped slingId=000, debugName=firstInstance Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 25.388 sec - in org.apache.sling.discovery.impl.cluster.ClusterTest Running org.apache.sling.discovery.impl.cluster.ClusterLoadTest 08.10.2014 17:00:39 *INFO * [main] ClusterLoadTest: doTest(6,9): muting log output... Killed Results : Tests run: 11, Failures: 0, Errors: 0, Skipped: 0 [JENKINS] Recording test results [JENKINS] Archiving disabled
