You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/11/23 07:31:03 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_45) - Build #
8428 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/8428/
Java: 32bit/jdk1.7.0_45 -client -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.OverseerTest.testOverseerFailure
Error Message:
KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
Stack Trace:
org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
at __randomizedtesting.SeedInfo.seed([131B3F7AB566E8A3:1713B089A7C30782]:0)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:424)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:157)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:744)
Build Log:
[...truncated 10473 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> 1251798 T3741 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-OverseerTest-1385187699762
[junit4] 2> 1251798 T3741 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 1251801 T3741 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment
[junit4] 2> 1251801 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1251802 T3742 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1251902 T3741 oasc.ZkTestServer.run start zk server on port:46449
[junit4] 2> 1251903 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1251908 T3748 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@128bc name:ZooKeeperConnection Watcher:127.0.0.1:46449 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1251909 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1251911 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1251912 T3750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1241f4 name:ZooKeeperConnection Watcher:127.0.0.1:46449 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1251912 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1251912 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1251915 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1251916 T3752 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a5bfb6 name:ZooKeeperConnection Watcher:127.0.0.1:46449/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1251916 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1251916 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1251918 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1251919 T3754 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@db62eb name:ZooKeeperConnection Watcher:127.0.0.1:46449/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1251919 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1251920 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1251923 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1251925 T3741 oasc.Overseer.start Overseer (id=90779661091995651-127.0.0.1:46449_solr-n_0000000000) starting
[junit4] 2> 1251926 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1251928 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1251931 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1251933 T3756 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1251933 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1251933 T3755 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1251936 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1251938 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1251941 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1251942 T3758 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cdd93b name:ZooKeeperConnection Watcher:127.0.0.1:46449/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1251943 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1251944 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1251945 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 1251948 T3752 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1251948 T3758 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1251949 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1251950 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1251951 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1251951 T3755 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 1251951 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1251953 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1251953 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1251953 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1252449 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1252457 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1252461 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252463 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252463 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1252468 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core2",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1252468 T3755 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1252469 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1252472 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252574 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1252574 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1252963 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 1252968 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 1252972 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252973 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252973 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252974 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1252974 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1252980 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core3",
[junit4] 2> "core_node_name":"node3",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1252980 T3755 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1252980 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1252982 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253085 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1253085 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1253474 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 1253480 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 1253484 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253485 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253485 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253486 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253486 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1253489 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node4",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1253489 T3755 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1253489 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1253491 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253593 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1253593 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1253986 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1253992 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253992 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253993 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1253994 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1253994 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core5",
[junit4] 2> "core_node_name":"node5",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1253994 T3755 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1253995 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1253996 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1254099 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1254099 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1254492 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 1254499 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1254499 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1254499 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1254500 T3755 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1254501 T3755 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=3 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core6",
[junit4] 2> "core_node_name":"node6",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1254501 T3755 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1254501 T3755 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1254503 T3754 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1254605 T3758 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1254605 T3752 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1254999 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 1255007 T3758 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1255010 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:46449 46449
[junit4] 2> 1255277 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1255281 T3741 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 1255282 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1255282 T3759 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1255382 T3741 oasc.ZkTestServer.run start zk server on port:49064
[junit4] 2> 1255384 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1255387 T3765 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b56028 name:ZooKeeperConnection Watcher:127.0.0.1:49064/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1255387 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1255389 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1255390 T3767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19c682d name:ZooKeeperConnection Watcher:127.0.0.1:49064 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1255391 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1255417 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1255418 T3769 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10e9bc name:ZooKeeperConnection Watcher:127.0.0.1:49064 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1255419 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1255419 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1255421 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1255423 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1255424 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1255426 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1255427 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1255429 T3771 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1061325 name:ZooKeeperConnection Watcher:127.0.0.1:49064/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1255429 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1255430 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1255432 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1255433 T3765 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1255434 T3771 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1255434 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1255435 T3773 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5890f3 name:ZooKeeperConnection Watcher:127.0.0.1:49064/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1255435 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1255436 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1255439 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1255441 T3741 oasc.Overseer.start Overseer (id=90779661320192004-127.0.0.1:49064_solr-n_0000000000) starting
[junit4] 2> 1255442 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1255446 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1255449 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1255451 T3775 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1255452 T3774 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1256453 T3773 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1256455 T3774 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1256455 T3774 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1256455 T3774 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1256456 T3774 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1256508 T3758 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1256508 T3758 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard3/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1256509 T3758 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1257071 T3773 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1257072 T3765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1257072 T3771 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1257454 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1257461 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1257465 T3773 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1257466 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1257467 T3774 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1257469 T3773 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1257469 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1257470 T3774 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1257471 T3774 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1257473 T3773 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1257576 T3765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1257576 T3771 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1258630 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1258635 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1258637 T3777 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f1d52b name:ZooKeeperConnection Watcher:127.0.0.1:49064/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1258637 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1258640 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1258642 T3741 oasc.Overseer.start Overseer (id=90779661320192005-127.0.0.1:49064_solr-n_0000000001) starting
[junit4] 2> 1258646 T3779 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1258646 T3778 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1258649 T3778 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1258650 T3778 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1258650 T3778 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1258652 T3777 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1258653 T3765 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1258653 T3771 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1258706 T3777 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1258706 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1258708 T3778 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1258711 T3741 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/90779661320192003-node1_core1-n_0000000002
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:111)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1151)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:269)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:266)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:126)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] 2> at java.lang.reflect.Method.invoke(Method.java:606)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4] 2> at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4] 2> at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4] 2> at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 1258713 T3771 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1258713 T3778 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:125)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:169)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:166)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:650)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:645)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:875)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:224)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:185)
[junit4] 2> at java.lang.Thread.run(Thread.java:744)
[junit4] 2>
[junit4] 2> 1258714 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1258728 T3777 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1258731 T3777 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1258732 T3765 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1258732 T3778 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 1258735 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:49064 49064
[junit4] 2> 1258788 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=131B3F7AB566E8A3 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=iw_IL -Dtests.timezone=Israel -Dtests.file.encoding=UTF-8
[junit4] ERROR 3.53s J0 | OverseerTest.testOverseerFailure <<<
[junit4] > Throwable #1: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at __randomizedtesting.SeedInfo.seed([131B3F7AB566E8A3:1713B089A7C30782]:0)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] > at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:424)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:421)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:157)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:277)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:153)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:584)
[junit4] > at java.lang.Thread.run(Thread.java:744)
[junit4] 2> 1258812 T3741 oas.SolrTestCaseJ4.setUp ###Starting testReplay
[junit4] 2> 1258813 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1258813 T3780 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1258913 T3741 oasc.ZkTestServer.run start zk server on port:44799
[junit4] 2> 1258914 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1258916 T3786 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c1aede name:ZooKeeperConnection Watcher:127.0.0.1:44799/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1258917 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1258917 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1258918 T3788 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16ecace name:ZooKeeperConnection Watcher:127.0.0.1:44799 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1258919 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1258939 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1258940 T3790 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12f74c2 name:ZooKeeperConnection Watcher:127.0.0.1:44799 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1258940 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1258941 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1258943 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1258945 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1258947 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1258949 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1258952 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1258955 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1258956 T3792 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13b01c2 name:ZooKeeperConnection Watcher:127.0.0.1:44799/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1258956 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1258957 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1258961 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1258963 T3741 oasc.Overseer.start Overseer (id=90779661551730691-127.0.0.1:44799_solr-n_0000000000) starting
[junit4] 2> 1258964 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1258968 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1258970 T3794 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1258972 T3793 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1258973 T3793 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 1258973 T3793 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 1258976 T3786 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1258979 T3793 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core2",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 1258980 T3786 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1258981 T3793 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1258983 T3793 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1258983 T3793 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "shard":"s1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core3",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 1258985 T3792 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1258986 T3786 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1259075 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:44799 44799
[junit4] 2> 1259369 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testReplay
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1259378 T3741 oas.SolrTestCaseJ4.setUp ###Starting testDoubleAssignment
[junit4] 2> 1259379 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1259379 T3795 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1259479 T3741 oasc.ZkTestServer.run start zk server on port:36631
[junit4] 2> 1259480 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1259483 T3801 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c76558 name:ZooKeeperConnection Watcher:127.0.0.1:36631/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1259483 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1259484 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1259485 T3803 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15494e7 name:ZooKeeperConnection Watcher:127.0.0.1:36631 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1259485 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1259495 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1259496 T3805 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f57ed2 name:ZooKeeperConnection Watcher:127.0.0.1:36631 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1259496 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1259497 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1259499 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1259500 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1259502 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1259503 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1259505 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1259507 T3807 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c731b9 name:ZooKeeperConnection Watcher:127.0.0.1:36631/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1259507 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1259508 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1259510 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1259512 T3801 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1259512 T3807 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1259513 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1259514 T3809 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d11197 name:ZooKeeperConnection Watcher:127.0.0.1:36631/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1259514 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1259515 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1259520 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1259521 T3741 oasc.Overseer.start Overseer (id=90779661588627460-127.0.0.1:36631_solr-n_0000000000) starting
[junit4] 2> 1259523 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1259526 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1259529 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1259531 T3811 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1259532 T3810 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1259533 T3810 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1259534 T3810 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1259534 T3810 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1259534 T3810 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1259538 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1259539 T3807 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1259539 T3801 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1260032 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1260039 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1260043 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260043 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260044 T3810 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260045 T3801 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1260045 T3807 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1260046 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260047 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260048 T3813 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d495d name:ZooKeeperConnection Watcher:127.0.0.1:36631/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260048 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260049 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1260050 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1260054 T3801 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1260054 T3813 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1260058 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260058 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1260059 T3810 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1260059 T3810 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1260062 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260063 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1260066 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260070 T3809 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260172 T3801 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1260172 T3813 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1260173 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260176 T3801 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1260179 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:36631 36631
[junit4] 2> 1260231 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testDoubleAssignment
[junit4] 2> 1260232 T3771 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1260232 T3771 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:201)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:409)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1260233 T3771 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1260237 T3741 oas.SolrTestCaseJ4.setUp ###Starting testStateChange
[junit4] 2> 1260237 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1260237 T3814 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1260337 T3741 oasc.ZkTestServer.run start zk server on port:46933
[junit4] 2> 1260339 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260342 T3820 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c8a8ae name:ZooKeeperConnection Watcher:127.0.0.1:46933/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260342 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260343 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260344 T3822 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fcbd78 name:ZooKeeperConnection Watcher:127.0.0.1:46933 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260344 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260358 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260359 T3824 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cfb2ff name:ZooKeeperConnection Watcher:127.0.0.1:46933 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260359 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260360 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1260361 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1260363 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1260366 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1260369 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1260371 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260372 T3826 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1858d17 name:ZooKeeperConnection Watcher:127.0.0.1:46933/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260373 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260373 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1260377 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1260379 T3741 oasc.Overseer.start Overseer (id=90779661644922883-127.0.0.1:46933_solr-n_0000000000) starting
[junit4] 2> 1260381 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1260383 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1260386 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1260388 T3828 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1260389 T3827 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1260390 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260391 T3827 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260391 T3827 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"recovering"}
[junit4] 2> 1260391 T3827 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1260393 T3826 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260394 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1260441 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260443 T3826 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260444 T3827 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260445 T3827 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4] 2> "operation":"state",
[junit4] 2> "base_url":"http://127.0.0.1/solr",
[junit4] 2> "node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "core":"core1",
[junit4] 2> "roles":"",
[junit4] 2> "state":"active"}
[junit4] 2> 1260445 T3827 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered
[junit4] 2> 1260446 T3827 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1260448 T3826 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260549 T3820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 0)
[junit4] 2> 1260597 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:46933 46933
[junit4] 2> 1260795 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1260800 T3741 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
[junit4] 2> 1260800 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1260800 T3829 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1260901 T3741 oasc.ZkTestServer.run start zk server on port:42066
[junit4] 2> 1260902 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260904 T3835 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cb438 name:ZooKeeperConnection Watcher:127.0.0.1:42066/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260904 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260905 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260906 T3837 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@146ed1 name:ZooKeeperConnection Watcher:127.0.0.1:42066 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260906 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260914 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260916 T3839 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13d461c name:ZooKeeperConnection Watcher:127.0.0.1:42066 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260916 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260916 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1260920 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1260922 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1260923 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1260924 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1260926 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260927 T3841 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b4dfeb name:ZooKeeperConnection Watcher:127.0.0.1:42066/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260928 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260928 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1260930 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1260932 T3835 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1260932 T3841 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1260932 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1260934 T3843 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f3497b name:ZooKeeperConnection Watcher:127.0.0.1:42066/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1260934 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1260934 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1260938 T3741 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1260939 T3741 oasc.Overseer.start Overseer (id=90779661681819652-127.0.0.1:42066_solr-n_0000000000) starting
[junit4] 2> 1260940 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1260943 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1260948 T3741 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1260950 T3845 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1260951 T3844 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1260952 T3844 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1260953 T3844 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=12 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"recovering",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"12",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1260953 T3844 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
[junit4] 2> 1260953 T3844 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1260955 T3843 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1260956 T3841 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1260956 T3835 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1261452 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1261459 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1261463 T3843 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1261465 T3741 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1261466 T3844 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1261468 T3835 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1261468 T3841 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1261470 T3741 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42066 42066
[junit4] 2> 1261508 T3741 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1261513 T3741 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 1261513 T3741 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1261513 T3846 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1261613 T3741 oasc.ZkTestServer.run start zk server on port:46388
[junit4] 2> 1261614 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261617 T3852 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@97761d name:ZooKeeperConnection Watcher:127.0.0.1:46388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261617 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261618 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261619 T3854 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1391ed4 name:ZooKeeperConnection Watcher:127.0.0.1:46388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261619 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261640 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261642 T3856 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1444f94 name:ZooKeeperConnection Watcher:127.0.0.1:46388 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261642 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261642 T3741 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1261644 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1261647 T3857 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261647 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261649 T3861 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1dbdb0a name:ZooKeeperConnection Watcher:127.0.0.1:46388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261649 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261649 T3860 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37136b name:ZooKeeperConnection Watcher:127.0.0.1:46388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261650 T3857 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261650 T3741 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1261650 T3857 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1261652 T3741 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1261653 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1261654 T3857 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1261655 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1261656 T3857 oasc.Overseer.start Overseer (id=90779661728481284-127.0.0.1:46388_solr-n_0000000000) starting
[junit4] 2> 1261657 T3861 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1261658 T3857 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1261658 T3741 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1261660 T3857 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1261662 T3857 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1261663 T3863 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1261663 T3857 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 1261664 T3862 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1261666 T3857 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1261668 T3865 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e73990 name:ZooKeeperConnection Watcher:127.0.0.1:46388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1261668 T3857 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1261670 T3857 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1261672 T3857 oasc.Overseer.start Overseer (id=90779661728481285-127.0.0.1:46388_solr-n_0000000001) starting
[junit4] 2> 1261675 T3867 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1261675 T3866 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1261677 T3813 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1261677 T3866 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1261678 T3866 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1261678 T3866 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1261678 T3866 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1261680 T3865 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1261681 T3861 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 1262160 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1262167 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1262172 T3865 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1262174 T3865 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1262174 T3866 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1262174 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1262177 T3866 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 1262177 T3866 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1262178 T3741 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1262179 T3869 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f538e name:ZooKeeperConnection Watcher:127.0.0.1:46388/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1262179 T3741 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1262179 T3865 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1262180 T3741 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1262182 T3741 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 1262184 T3861 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1262184 T3869 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4] 2> 1262187 T3741 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1262187 T3865 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1262189 T3866 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "co
[...truncated too long message...]
hardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1273695 T4018 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1273733 T4028 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1273948 T4094 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1273949 T4094 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard5/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1273950 T4096 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1273951 T4096 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard3/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:252)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:249)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:93)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1273953 T4098 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1273990 T4114 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1274005 T4122 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1274010 T4124 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leaders
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1041)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:201)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.execute(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:198)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:409)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:378)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:365)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:102)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:165)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:109)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:138)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4] 2>
[junit4] 2> 1274011 T4124 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1275694 T3741 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene46: {}, docValues:{}, sim=DefaultSimilarity, locale=iw_IL, timezone=Israel
[junit4] 2> NOTE: Linux 3.8.0-33-generic i386/Oracle Corporation 1.7.0_45 (32-bit)/cpus=8,threads=1,free=117243344,total=340672512
[junit4] 2> NOTE: All tests run in this JVM: [DateMathParserTest, TestFieldCollectionResource, ShowFileRequestHandlerTest, TestLRUCache, TriLevelCompositeIdRoutingTest, TestBM25SimilarityFactory, LoggingHandlerTest, DocumentBuilderTest, HdfsCollectionsAPIDistributedZkTest, HdfsSyncSliceTest, SimpleFacetsTest, TestAnalyzeInfixSuggestions, SchemaVersionSpecificBehaviorTest, LukeRequestHandlerTest, PrimitiveFieldTypeTest, FileBasedSpellCheckerTest, AddSchemaFieldsUpdateProcessorFactoryTest, QueryResultKeyTest, CoreMergeIndexesAdminHandlerTest, ZkCLITest, TestManagedSchema, ZkControllerTest, EchoParamsTest, TestCloudManagedSchemaAddField, TestJoin, TestSolrIndexConfig, BasicDistributedZkTest, ResponseLogComponentTest, LeaderElectionTest, UpdateParamsTest, RangeFacetTest, TestClassNameShortening, TestGroupingSearch, TestDocumentBuilder, TestCollapseQParserPlugin, TestSurroundQueryParser, TestPseudoReturnFields, TestSystemIdResolver, ClusterStateTest, SolrXmlInZkTest, FieldMutatingUpdateProcessorTest, TestSerializedLuceneMatchVersion, TestPostingsSolrHighlighter, DeleteShardTest, TestSearchPerf, BJQParserTest, TestRemoteStreaming, UpdateRequestProcessorFactoryTest, HdfsBasicDistributedZkTest, StatelessScriptUpdateProcessorFactoryTest, EnumFieldTest, TestCharFilters, DOMUtilTest, HdfsUnloadDistributedZkTest, TestFaceting, ClusterStateUpdateTest, TestLFUCache, RegexBoostProcessorTest, TestCoreContainer, MoreLikeThisHandlerTest, LegacyHTMLStripCharFilterTest, DirectUpdateHandlerOptimizeTest, TestLMJelinekMercerSimilarityFactory, SliceStateUpdateTest, TestJmxMonitoredMap, JsonLoaderTest, TestReplicationHandler, TestDocSet, DistributedTermsComponentTest, TestSolrXMLSerializer, TestSort, CacheHeaderTest, TestSchemaNameResource, TestRealTimeGet, DocValuesTest, UUIDFieldTest, DistributedDebugComponentTest, TermVectorComponentTest, PolyFieldTest, SyncSliceTest, TestDefaultSearchFieldResource, OverseerCollectionProcessorTest, TestMaxScoreQueryParser, BasicDistributedZk2Test, UnloadDistributedZkTest, OverseerTest]
[junit4] Completed on J0 in 23.93s, 8 tests, 1 error <<< FAILURES!
[...truncated 530 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:420: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:400: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:189: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:489: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1272: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:908: There were test failures: 349 suites, 1551 tests, 1 error, 34 ignored (6 assumptions)
Total time: 63 minutes 23 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_45 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure