You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/03/23 09:49:15 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1947 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1947/
1 tests failed.
REGRESSION: org.apache.solr.cloud.OverseerTest.testOverseerFailure
Error Message:
Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
Stack Trace:
org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
at __randomizedtesting.SeedInfo.seed([B88439A4D0DBD4AF:BC8CB657C27E3B8E]:0)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:135)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:164)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:108)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:156)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:289)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:156)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:667)
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:1617)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:826)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:862)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:876)
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:359)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:783)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:443)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:835)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:771)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:782)
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:359)
at java.lang.Thread.run(Thread.java:724)
Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:122)
... 45 more
Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
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:431)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:428)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:385)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:372)
at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:127)
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
... 46 more
Build Log:
[...truncated 10696 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> 1809711 T3719 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (false)
[junit4] 2> 1809712 T3719 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solrtest-OverseerTest-1395564078591
[junit4] 2> 1809713 T3719 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 1809718 T3719 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment
[junit4] 2> 1809719 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1809719 T3720 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1809820 T3719 oasc.ZkTestServer.run start zk server on port:63673
[junit4] 2> 1809821 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1809825 T3726 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49e66a45 name:ZooKeeperConnection Watcher:127.0.0.1:63673 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1809826 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1809828 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1809843 T3728 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7437fdc0 name:ZooKeeperConnection Watcher:127.0.0.1:63673 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1809843 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1809844 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1809848 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1809857 T3730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7afa9d4f name:ZooKeeperConnection Watcher:127.0.0.1:63673/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1809857 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1809858 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1809860 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1809862 T3732 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@69574b0a name:ZooKeeperConnection Watcher:127.0.0.1:63673/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1809862 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1809863 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1809865 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1809869 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63673_solr
[junit4] 2> 1809870 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1809872 T3719 oasc.Overseer.start Overseer (id=91459687455391747-127.0.0.1:63673_solr-n_0000000000) starting
[junit4] 2> 1809874 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1809877 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1809880 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1809883 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1809886 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1809889 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1809894 T3734 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1809894 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1809895 T3733 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1809895 T3734 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1809897 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1809898 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1809902 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1809903 T3736 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3935772e name:ZooKeeperConnection Watcher:127.0.0.1:63673/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1809903 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1809904 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1809906 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 1809909 T3736 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1809910 T3730 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1809912 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1809913 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1809914 T3733 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> 1809914 T3733 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 1809914 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1809916 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1809917 T3736 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> 1809917 T3730 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> 1810413 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 1810478 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 1810491 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1810493 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1810493 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1810497 T3733 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> 1810497 T3733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1810497 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1810499 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1810602 T3736 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> 1810602 T3730 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> 1810994 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1811040 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1811053 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811053 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811053 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811063 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1811064 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811075 T3733 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> 1811075 T3733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1811075 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1811077 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811180 T3730 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> 1811180 T3736 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> 1811565 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 1811583 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 1811595 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811596 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811596 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811597 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811597 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1811601 T3733 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> 1811601 T3733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1811602 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1811604 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1811706 T3730 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> 1811706 T3736 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> 1812098 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 1812115 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812116 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812116 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812117 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1812117 T3733 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> 1812118 T3733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1812118 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1812120 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812222 T3730 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> 1812222 T3736 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> 1812616 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1812635 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812636 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812636 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812637 T3733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1812637 T3733 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> 1812638 T3733 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1812638 T3733 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1812641 T3732 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1812744 T3736 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> 1812744 T3730 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> 1813136 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 1813154 T3736 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1813157 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63673 63673
[junit4] 2> 1813218 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1813226 T3719 oas.SolrTestCaseJ4.setUp ###Starting testPlaceholders
[junit4] 2> 1813227 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1813227 T3737 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1813328 T3719 oasc.ZkTestServer.run start zk server on port:63679
[junit4] 2> 1813329 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1813332 T3743 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7195348e name:ZooKeeperConnection Watcher:127.0.0.1:63679/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1813333 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1813334 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1813335 T3745 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@658eaf7b name:ZooKeeperConnection Watcher:127.0.0.1:63679 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1813335 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1813381 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1813382 T3747 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14719ef9 name:ZooKeeperConnection Watcher:127.0.0.1:63679 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1813382 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1813383 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1813385 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1813387 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1813389 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1813391 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1813393 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1813395 T3749 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74175699 name:ZooKeeperConnection Watcher:127.0.0.1:63679/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1813395 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1813396 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1813398 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1813400 T3749 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1813400 T3743 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1813401 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1813402 T3751 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@247452c8 name:ZooKeeperConnection Watcher:127.0.0.1:63679/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1813402 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1813403 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1813405 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1813409 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63679_solr
[junit4] 2> 1813409 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1813411 T3719 oasc.Overseer.start Overseer (id=91459687685488644-127.0.0.1:63679_solr-n_0000000000) starting
[junit4] 2> 1813414 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1813416 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1813419 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1813422 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1813425 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1813429 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1813434 T3753 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1813434 T3752 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1813435 T3753 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1813436 T3752 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1813437 T3752 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> 1813437 T3752 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3, shard4, shard5, shard6, shard7, shard8, shard9, shard10, shard11, shard12]
[junit4] 2> 1813438 T3752 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard8
[junit4] 2> 1813440 T3751 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1813441 T3749 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> 1813441 T3743 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> 1813937 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard8/election
[junit4] 2> 1813963 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard8
[junit4] 2> 1813968 T3751 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1813968 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1813969 T3752 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1813971 T3743 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1813971 T3749 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1813974 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63679 63679
[junit4] 2> 1814030 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testPlaceholders
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1814038 T3719 oas.SolrTestCaseJ4.setUp ###Starting testStateChange
[junit4] 2> 1814038 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1814039 T3754 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1814140 T3719 oasc.ZkTestServer.run start zk server on port:63685
[junit4] 2> 1814141 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814145 T3760 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58ca39c0 name:ZooKeeperConnection Watcher:127.0.0.1:63685/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814145 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814146 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814148 T3762 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22e960b7 name:ZooKeeperConnection Watcher:127.0.0.1:63685 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814148 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814195 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814196 T3764 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32d4fa81 name:ZooKeeperConnection Watcher:127.0.0.1:63685 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814197 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814197 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1814199 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1814202 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1814203 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1814205 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1814207 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814209 T3766 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7e509047 name:ZooKeeperConnection Watcher:127.0.0.1:63685/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814209 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814210 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1814212 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1814216 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63685_solr
[junit4] 2> 1814216 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1814218 T3719 oasc.Overseer.start Overseer (id=91459687738966019-127.0.0.1:63685_solr-n_0000000000) starting
[junit4] 2> 1814220 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1814223 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1814226 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1814229 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1814231 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1814235 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1814240 T3768 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1814240 T3767 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1814241 T3768 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1814242 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814243 T3767 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814243 T3767 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> 1814243 T3767 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1814246 T3766 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1814247 T3760 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> 1814294 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814296 T3766 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1814297 T3767 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814298 T3767 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> 1814298 T3767 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered
[junit4] 2> 1814298 T3767 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1814301 T3766 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1814403 T3760 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> 1814452 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63685 63685
[junit4] 2> 1814642 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1814649 T3719 oas.SolrTestCaseJ4.setUp ###Starting testReplay
[junit4] 2> 1814650 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1814651 T3769 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1814655 T3736 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:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[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:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 1814655 T3736 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:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[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:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 1814656 T3736 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:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[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:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 1814752 T3719 oasc.ZkTestServer.run start zk server on port:63690
[junit4] 2> 1814753 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814757 T3775 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f8e1d1 name:ZooKeeperConnection Watcher:127.0.0.1:63690/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814757 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814758 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814760 T3777 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c6b0f38 name:ZooKeeperConnection Watcher:127.0.0.1:63690 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814760 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814798 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814799 T3779 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@630dc0b9 name:ZooKeeperConnection Watcher:127.0.0.1:63690 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814800 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814800 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1814803 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1814805 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1814807 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1814808 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1814811 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1814815 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1814817 T3781 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@197b0612 name:ZooKeeperConnection Watcher:127.0.0.1:63690/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1814817 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1814818 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1814820 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1814824 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63690_solr
[junit4] 2> 1814824 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1814826 T3719 oasc.Overseer.start Overseer (id=91459687778942979-127.0.0.1:63690_solr-n_0000000000) starting
[junit4] 2> 1814828 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1814832 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1814835 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1814838 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1814841 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1814846 T3783 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1814847 T3783 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1814848 T3782 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814849 T3782 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 1814849 T3782 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> 1814850 T3775 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> 1814853 T3782 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> 1814854 T3775 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> 1814856 T3782 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1814857 T3782 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1814857 T3782 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> 1814860 T3781 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1814861 T3775 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> 1814951 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63690 63690
[junit4] 2> 1816033 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testReplay
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1816039 T3719 oas.SolrTestCaseJ4.setUp ###Starting testBadQueueItem
[junit4] 2> 1816039 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1816040 T3784 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1816141 T3719 oasc.ZkTestServer.run start zk server on port:63695
[junit4] 2> 1816141 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1816144 T3790 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48241045 name:ZooKeeperConnection Watcher:127.0.0.1:63695 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1816145 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1816172 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1816173 T3792 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7df6df90 name:ZooKeeperConnection Watcher:127.0.0.1:63695 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1816173 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1816174 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1816176 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1816177 T3794 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a212496 name:ZooKeeperConnection Watcher:127.0.0.1:63695/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1816177 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1816177 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1816179 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1816180 T3796 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72891dbd name:ZooKeeperConnection Watcher:127.0.0.1:63695/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1816180 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1816181 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1816182 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1816185 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63695_solr
[junit4] 2> 1816186 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1816187 T3719 oasc.Overseer.start Overseer (id=91459687870103555-127.0.0.1:63695_solr-n_0000000000) starting
[junit4] 2> 1816189 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1816191 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1816193 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1816196 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1816206 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1816216 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1816220 T3798 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1816221 T3797 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1816220 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1816221 T3798 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1816222 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1816224 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1816225 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1816227 T3800 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@105add2f name:ZooKeeperConnection Watcher:127.0.0.1:63695/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1816227 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1816228 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1816229 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 1816231 T3794 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1816231 T3800 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1816232 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1816233 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1816234 T3797 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> 1816234 T3797 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 1816234 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1816236 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1816237 T3800 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> 1816237 T3794 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> 1816733 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 1816825 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 1816831 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1816833 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1816833 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1816836 T3797 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> 1816837 T3797 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1816837 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1816839 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1816942 T3800 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> 1816942 T3794 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> 1817334 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1817352 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1817365 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817365 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817365 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817367 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817367 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1817371 T3797 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> 1817371 T3797 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1817372 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1817374 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817476 T3800 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> 1817476 T3794 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> 1817868 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 1817886 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 1817891 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817892 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817892 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817893 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1817896 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1817999 T3794 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> 1817999 T3800 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> 1818046 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818046 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818047 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818057 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818057 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1818058 T3797 oasc.Overseer$ClusterStateUpdater.checkKeyExistence ERROR Skipping invalid Overseer message because it has no collection specified: {
[junit4] 2> "operation":"state",
[junit4] 2> "state":"active",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core0",
[junit4] 2> "core_node_name":"node0",
[junit4] 2> "collection":"",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1818061 T3797 oasc.Overseer$ClusterStateUpdater.checkKeyExistence ERROR Skipping invalid Overseer message because it has no collection specified: {
[junit4] 2> "operation":"deletecore",
[junit4] 2> "node_name":"127.0.0.1",
[junit4] 2> "core":"core0",
[junit4] 2> "core_node_name":"node0",
[junit4] 2> "collection":""}
[junit4] 2> 1818064 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818064 T3797 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1818065 T3797 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection2 with shards [shard1, shard2, shard3]
[junit4] 2> 1818065 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 1818068 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818170 T3794 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> 1818170 T3800 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> 1818560 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard3/election
[junit4] 2> 1818596 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard3
[junit4] 2> 1818602 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818602 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818603 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818604 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818604 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1818612 T3797 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1818612 T3797 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1818613 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1818698 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1818802 T3800 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> 1818802 T3794 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> 1819105 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard1/election
[junit4] 2> 1819146 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard1
[junit4] 2> 1819159 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819159 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819159 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819169 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819170 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1819174 T3797 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":"collection2",
[junit4] 2> "numShards":"3",
[junit4] 2> "base_url":"http://127.0.0.1/solr/"}
[junit4] 2> 1819174 T3797 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 1819174 T3797 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 1819184 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819286 T3794 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> 1819286 T3800 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> 1819670 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leader_elect/shard2/election
[junit4] 2> 1819685 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection2/leaders/shard2
[junit4] 2> 1819690 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819690 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819690 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819691 T3797 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1819694 T3796 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1819796 T3800 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> 1819796 T3794 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> 1819845 T3800 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1819855 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63695 63695
[junit4] 2> 1819925 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testBadQueueItem
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1819932 T3719 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 1819933 T3719 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 2> 1819933 T3801 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 1820034 T3719 oasc.ZkTestServer.run start zk server on port:63701
[junit4] 2> 1820036 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1820038 T3807 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@337edfe7 name:ZooKeeperConnection Watcher:127.0.0.1:63701 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1820039 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1820088 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1820090 T3809 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f283a5e name:ZooKeeperConnection Watcher:127.0.0.1:63701 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1820090 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1820091 T3719 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 1820093 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1820094 T3811 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3333fee2 name:ZooKeeperConnection Watcher:127.0.0.1:63701/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1820095 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1820095 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 1820096 T3719 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 1820098 T3719 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 1820099 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1820101 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1820102 T3813 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34477bd name:ZooKeeperConnection Watcher:127.0.0.1:63701/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1820103 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1820103 T3719 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 1820105 T3719 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 1820107 T3813 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1820107 T3811 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1820107 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1820108 T3815 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2923c636 name:ZooKeeperConnection Watcher:127.0.0.1:63701/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1820108 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1820109 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 1820111 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 1820114 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63701_solr
[junit4] 2> 1820114 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1820115 T3719 oasc.Overseer.start Overseer (id=91459688126218244-127.0.0.1:63701_solr-n_0000000000) starting
[junit4] 2> 1820117 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 1820119 T3719 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 1820122 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 1820124 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 1820127 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 1820129 T3719 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 1820133 T3817 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1820134 T3816 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1820134 T3817 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1821137 T3815 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1821138 T3816 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1821139 T3816 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> 1821139 T3816 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 1821139 T3816 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 1821153 T3815 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1821153 T3811 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> 1821153 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> 1821637 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1821661 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1821666 T3815 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1821666 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1821667 T3816 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1821680 T3815 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1821680 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1821682 T3816 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> 1821682 T3816 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1821698 T3815 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1821800 T3811 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> 1821800 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> 1822872 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1822879 T3719 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 1822891 T3819 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@71fbf621 name:ZooKeeperConnection Watcher:127.0.0.1:63701/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 1822891 T3719 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 1822896 T3719 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:63701_solr
[junit4] 2> 1822896 T3719 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 1822908 T3719 oasc.Overseer.start Overseer (id=91459688126218245-127.0.0.1:63701_solr-n_0000000001) starting
[junit4] 2> 1822933 T3821 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 1822933 T3820 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 1822933 T3821 oasc.OverseerCollectionProcessor.prioritizeOverseerNodes prioritizing overseer nodes
[junit4] 2> 1822935 T3820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1822935 T3820 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> 1822935 T3820 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1822938 T3819 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1822939 T3811 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> 1822939 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> 1822992 T3819 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1822992 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1822993 T3820 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1822997 T3813 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1822998 T3719 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/91459688126218243-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:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:276)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:273)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:273)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:289)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:156)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:667)
[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:1617)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:826)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:862)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:876)
[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:359)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:783)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:443)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:835)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:737)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:771)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:782)
[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:359)
[junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4] 2>
[junit4] 2> 1823000 T3820 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collectio
[...truncated too long message...]
from ZooKeeper...
[junit4] 2> 1855947 T3719 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 1855947 T4211 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1855949 T4212 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1855950 T4212 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node2",
[junit4] 2> "core":"core4",
[junit4] 2> "core_node_name":"node2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node2/solr/"}
[junit4] 2> 1855950 T4212 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 1855962 T4211 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1855962 T4207 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1855962 T4209 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4] 2> 1855972 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1855979 T4209 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 1855991 T4211 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1855991 T4209 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> 1855992 T4212 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1855999 T4211 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 1856101 T4209 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> 1856180 T3719 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4] 2> 1856276 T4209 oascc.ZkStateReader$3.process Updating live nodes... (0)
[junit4] 2> 1856292 T3719 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63824 63824
[junit4] 2> 1856578 T3719 oas.SolrTestCaseJ4.tearDown ###Ending testShardLeaderChange
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1856580 T3719 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 1856580 T3719 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 1857472 T4207 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:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[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:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 1857473 T4207 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:1472)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:259)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:73)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:92)
[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:137)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 1859581 T3719 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: test params are: codec=Lucene42, sim=DefaultSimilarity, locale=en_SG, timezone=Africa/Tripoli
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=16,threads=1,free=122987504,total=514850816
[junit4] 2> NOTE: All tests run in this JVM: [TestImplicitCoreProperties, TestStressReorder, SchemaVersionSpecificBehaviorTest, TestJoin, TestTrie, TestCustomSort, TestCSVLoader, ChaosMonkeySafeLeaderTest, TestExceedMaxTermLength, PreAnalyzedFieldTest, AddSchemaFieldsUpdateProcessorFactoryTest, IndexSchemaTest, SampleTest, CoreMergeIndexesAdminHandlerTest, CursorMarkTest, TestSearchPerf, TestNonNRTOpen, OpenCloseCoreStressTest, TestOmitPositions, TestDFRSimilarityFactory, TestAnalyzeInfixSuggestions, TestSolrDeletionPolicy2, StatsComponentTest, TestReloadAndDeleteDocs, IndexBasedSpellCheckerTest, TestExtendedDismaxParser, TestSolr4Spatial, TestSolrXmlPersistence, TestCSVResponseWriter, SuggestComponentTest, TestRTGBase, SolrTestCaseJ4Test, OverseerCollectionProcessorTest, TestIBSimilarityFactory, TestSolrXMLSerializer, DOMUtilTest, SliceStateTest, SimplePostToolTest, OverseerStatusTest, TestPhraseSuggestions, BinaryUpdateRequestHandlerTest, TestSearcherReuse, HdfsBasicDistributedZk2Test, SynonymTokenizerTest, TestJmxMonitoredMap, BadComponentTest, BasicFunctionalityTest, TestDefaultSimilarityFactory, TestRequestStatusCollectionAPI, TestFileDictionaryLookup, TestShardHandlerFactory, QueryEqualityTest, AnalysisErrorHandlingTest, TestBlendedInfixSuggestions, TestGroupingSearch, MigrateRouteKeyTest, DisMaxRequestHandlerTest, QueryElevationComponentTest, DocumentBuilderTest, RAMDirectoryFactoryTest, TestFieldTypeCollectionResource, TestFieldCollectionResource, TestMergePolicyConfig, InfoHandlerTest, TestNoOpRegenerator, PolyFieldTest, SortByFunctionTest, TestCharFilters, SpellingQueryConverterTest, LeaderElectionTest, OpenExchangeRatesOrgProviderTest, UpdateRequestProcessorFactoryTest, CustomCollectionTest, TestReload, FieldMutatingUpdateProcessorTest, TestHighFrequencyDictionaryFactory, CursorPagingTest, MinimalSchemaTest, QueryParsingTest, CachingDirectoryFactoryTest, OutputWriterTest, TestLFUCache, TestWordDelimiterFilterFactory, TestNonDefinedSimilarityFactory, ShowFileRequestHandlerTest, ZkNodePropsTest, MoreLikeThisHandlerTest, CoreContainerCoreInitFailuresTest, WordBreakSolrSpellCheckerTest, SyncSliceTest, BasicDistributedZk2Test, ShardSplitTest, TriLevelCompositeIdRoutingTest, TestDistributedSearch, TestRandomFaceting, TestRandomDVFaceting, LeaderElectionIntegrationTest, AsyncMigrateRouteKeyTest, TestCloudManagedSchemaAddField, AliasIntegrationTest, OverseerTest]
[junit4] Completed on J0 in 49.91s, 9 tests, 1 error <<< FAILURES!
[...truncated 523 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:467: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:45: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:490: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1276: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:908: There were test failures: 378 suites, 1598 tests, 1 error, 37 ignored (16 assumptions)
Total time: 72 minutes 35 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure