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/08/23 06:16:52 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 2069 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/2069/
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([A488D6E45BB4A02F:A080591749114F0E]:0)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:150)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
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:1618)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
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:65)
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:365)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
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:65)
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:365)
at java.lang.Thread.run(Thread.java:745)
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:137)
... 48 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$11.execute(SolrZkClient.java:462)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:459)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:416)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:403)
at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:142)
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
... 49 more
Build Log:
[...truncated 11086 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> Creating dataDir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solr.cloud.OverseerTest-A488D6E45BB4A02F-001/init-core-data-001
[junit4] 2> 398180 T2266 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (true)
[junit4] 2> 398180 T2266 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 398180 T2266 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 398184 T2266 oas.SolrTestCaseJ4.setUp ###Starting testShardAssignment
[junit4] 2> 398185 T2266 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 398186 T2267 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 398285 T2266 oasc.ZkTestServer.run start zk server on port:30294
[junit4] 2> 398287 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 398290 T2273 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4daa089c name:ZooKeeperConnection Watcher:127.0.0.1:30294 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 398291 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 398293 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 398295 T2275 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23f844d9 name:ZooKeeperConnection Watcher:127.0.0.1:30294 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 398295 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 398295 T2266 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 398299 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 398300 T2277 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c6ea03f name:ZooKeeperConnection Watcher:127.0.0.1:30294/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 398300 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 398301 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 398303 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 398304 T2279 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5e9e73c2 name:ZooKeeperConnection Watcher:127.0.0.1:30294/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 398304 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 398305 T2266 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 398306 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 398308 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 398310 T2266 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 398312 T2266 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:30294_solr
[junit4] 2> 398312 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 398314 T2266 oasc.Overseer.start Overseer (id=92324640360235011-127.0.0.1:30294_solr-n_0000000000) starting
[junit4] 2> 398316 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 398318 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 398321 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 398324 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 398326 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 398329 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 398334 T2266 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 398334 T2281 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 398335 T2266 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 398336 T2280 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 398337 T2266 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 398339 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 398342 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 398343 T2284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7cc29797 name:ZooKeeperConnection Watcher:127.0.0.1:30294/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 398343 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 398344 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 398347 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1
[junit4] 2> 398351 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 398353 T2280 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> 398353 T2280 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2, shard3]
[junit4] 2> 398353 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 398356 T2285 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> 398356 T2286 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> 398852 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 398860 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 398865 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 398870 T2280 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> 398870 T2280 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 398870 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 398872 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 398873 T2285 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> 398873 T2286 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> 399366 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 399372 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard3
[junit4] 2> 399376 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 399381 T2280 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> 399381 T2280 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 399382 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 399384 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 399385 T2285 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> 399385 T2286 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> 399878 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 399885 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 399889 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 399894 T2280 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> 399894 T2280 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 399894 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 399896 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 399897 T2285 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> 399897 T2286 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> 400390 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 400397 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 400399 T2280 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> 400400 T2280 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 400400 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard3
[junit4] 2> 400503 T2286 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> 400503 T2285 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> 400898 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard3/election
[junit4] 2> 400905 T2287 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 400907 T2280 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> 400907 T2280 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=3
[junit4] 2> 400908 T2280 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 401011 T2285 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> 401011 T2286 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> 401405 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 401413 T2284 oaz.ClientCnxn$EventThread.processEvent ERROR Error while calling watcher java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1a940965 rejected from java.util.concurrent.ThreadPoolExecutor@6cf4d384[Shutting down, pool size = 2, active threads = 2, queued tasks = 0, completed tasks = 8]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
[junit4] 2> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:110)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.process(SolrZkClient.java:206)
[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> 401413 T2288 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 402913 T2285 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 402917 T2266 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:30294 30294
[junit4] 2> 403143 T2267 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:30294 30294
[junit4] 2> 403144 T2266 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignment
[junit4] 2> 403145 T2266 oasc.Overseer.close Overseer (id=92324640360235011-127.0.0.1:30294_solr-n_0000000000) closing
[junit4] 2> 403145 T2280 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:30294_solr
[junit4] 2> 403147 T2290 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 403154 T2266 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 403155 T2266 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 403155 T2291 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 403255 T2266 oasc.ZkTestServer.run start zk server on port:30300
[junit4] 2> 403256 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 403259 T2297 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@56c2dbc8 name:ZooKeeperConnection Watcher:127.0.0.1:30300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 403260 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 403262 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 403263 T2299 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7dec14cb name:ZooKeeperConnection Watcher:127.0.0.1:30300 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 403263 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 403264 T2266 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 403267 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 403268 T2301 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74524b1b name:ZooKeeperConnection Watcher:127.0.0.1:30300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 403269 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 403269 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 403271 T2266 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 403273 T2266 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 403274 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 403277 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 403278 T2303 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c6c993d name:ZooKeeperConnection Watcher:127.0.0.1:30300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 403278 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 403280 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 403282 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 403284 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 403286 T2307 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50fe1b9b name:ZooKeeperConnection Watcher:127.0.0.1:30300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 403286 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 403286 T2266 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 403287 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 403289 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 403291 T2266 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 403293 T2266 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:30300_solr
[junit4] 2> 403293 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 403295 T2266 oasc.Overseer.start Overseer (id=92324640685883396-127.0.0.1:30300_solr-n_0000000000) starting
[junit4] 2> 403296 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 403299 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 403302 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 403304 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 403307 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 403310 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 403314 T2266 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 403315 T2309 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 403316 T2308 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 404318 T2311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 404320 T2308 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> 404320 T2308 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 404321 T2308 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 404323 T2305 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> 404323 T2304 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> 404818 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 404826 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 404831 T2311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 404834 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 404836 T2308 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> 404836 T2308 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 404838 T2311 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 404839 T2304 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> 404839 T2305 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> 405317 T2309 oasc.OverseerCollectionProcessor.amILeader org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.amILeader(OverseerCollectionProcessor.java:514)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:272)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 405318 T2309 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=92324640685883396-127.0.0.1:30300_solr-n_0000000000) am no longer a leader.
[junit4] 2> 405893 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 405899 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 405901 T2313 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bb68807 name:ZooKeeperConnection Watcher:127.0.0.1:30300/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 405901 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 405901 T2266 oasc.Overseer.close Overseer (id=92324640685883396-127.0.0.1:30300_solr-n_0000000000) closing
[junit4] 2> 405902 T2308 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:30300_solr
[junit4] 2> 405902 T2266 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 405903 T2314 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 405905 T2266 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 405906 T2266 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:30300_solr
[junit4] 2> 405907 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 405909 T2266 oasc.Overseer.start Overseer (id=92324640685883397-127.0.0.1:30300_solr-n_0000000001) starting
[junit4] 2> 405917 T2266 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 405918 T2316 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 405919 T2315 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 405922 T2315 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> 405922 T2315 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 405924 T2318 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 405925 T2304 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> 405925 T2305 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> 405978 T2318 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 405978 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 405983 T2266 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/92324640685883395-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$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:148)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
[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:1618)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
[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:65)
[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:365)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
[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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[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:65)
[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:365)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 405985 T2319 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 405984 T2315 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:125)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:189)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:186)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:186)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:670)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:1104)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:362)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:244)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 405983 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 405986 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 405990 T2318 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 405991 T2315 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 406094 T2319 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> 406094 T2305 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> 406989 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 406989 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 407993 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 407993 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 408996 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 408997 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 409999 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 410000 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 411002 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 411003 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 412005 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 412006 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 413008 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 413009 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 414011 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 414012 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 415014 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 415015 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 416018 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 416018 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 417021 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 417021 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 418024 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 418025 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 419027 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 419028 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 420030 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 420031 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 421033 T2304 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 421034 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 421036 T2304 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:150)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] 2> at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:137)
[junit4] 2> ... 10 more
[junit4] 2> Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$11.execute(SolrZkClient.java:462)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:459)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:416)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:403)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:142)
[junit4] 2> at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
[junit4] 2> ... 11 more
[junit4] 2>
[junit4] 2> 422538 T2304 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 422542 T2266 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:30300 30300
[junit4] 2> 423673 T2291 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:30300 30300
[junit4] 2> 423674 T2266 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 2> 423675 T2266 oasc.Overseer.close Overseer (id=92324640685883397-127.0.0.1:30300_solr-n_0000000001) closing
[junit4] 2> 423675 T2315 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:30300_solr
[junit4] 2> 423677 T2320 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=A488D6E45BB4A02F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sk -Dtests.timezone=Etc/GMT+11 -Dtests.file.encoding=US-ASCII
[junit4] ERROR 20.6s J0 | OverseerTest.testOverseerFailure <<<
[junit4] > Throwable #1: org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
[junit4] > at __randomizedtesting.SeedInfo.seed([A488D6E45BB4A02F:A080591749114F0E]:0)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:150)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:137)
[junit4] > ... 48 more
[junit4] > Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] > at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient$11.execute(SolrZkClient.java:462)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:459)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:416)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:403)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:142)
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
[junit4] > ... 49 more
[junit4] 2> 423767 T2266 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 423768 T2266 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 423769 T2321 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 423869 T2266 oasc.ZkTestServer.run start zk server on port:11446
[junit4] 2> 423870 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423873 T2327 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f15acf name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423873 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423874 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423876 T2329 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b23bca8 name:ZooKeeperConnection Watcher:127.0.0.1:11446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423876 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423878 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423879 T2331 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19e558f6 name:ZooKeeperConnection Watcher:127.0.0.1:11446 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423880 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423880 T2266 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 423883 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 423887 T2332 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423887 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423888 T2335 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d1fffbb name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423888 T2332 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423888 T2336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6fce758b name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423889 T2332 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 423889 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423890 T2332 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 423890 T2266 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 423892 T2332 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 423892 T2266 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 423894 T2332 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 423894 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 423895 T2332 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:11446_solr
[junit4] 2> 423896 T2332 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 423896 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 423897 T2332 oasc.Overseer.start Overseer (id=92324642036842499-127.0.0.1:11446_solr-n_0000000000) starting
[junit4] 2> 423899 T2332 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 423900 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 423902 T2332 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 423905 T2332 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 423907 T2332 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 423910 T2332 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 423913 T2332 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 423917 T2332 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 423918 T2339 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 423918 T2332 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 423920 T2332 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 423921 T2342 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ea94c20 name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 423921 T2332 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 423922 T2332 oasc.Overseer.close Overseer (id=92324642036842499-127.0.0.1:11446_solr-n_0000000000) closing
[junit4] 2> 423922 T2339 oasc.OverseerCollectionProcessor.run ERROR Unable to prioritize overseer org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /roles.json
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1045)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:253)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:253)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.prioritizeOverseerNodes(OverseerCollectionProcessor.java:412)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:259)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 423922 T2332 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 423925 T2332 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 423927 T2332 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:11446_solr
[junit4] 2> 423927 T2332 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 423929 T2332 oasc.Overseer.start Overseer (id=92324642036842501-127.0.0.1:11446_solr-n_0000000001) starting
[junit4] 2> 423937 T2332 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 423938 T2344 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 423939 T2343 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 423941 T2343 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 423942 T2343 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 423942 T2343 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 423944 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 423945 T2337 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> 424402 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 424410 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 424414 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 424416 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 424419 T2343 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 424420 T2343 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 424421 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 424422 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 424423 T2348 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3bb48bd7 name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 424423 T2337 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> 424423 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 424425 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 424427 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 424431 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 424431 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 424433 T2343 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 424433 T2343 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 424438 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 424439 T2343 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> 424439 T2343 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4] 2> 424439 T2343 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 424543 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 424543 T2349 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 424938 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 424945 T2336 oaz.ClientCnxn$EventThread.processEvent ERROR Error while calling watcher java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@73015c0f rejected from java.util.concurrent.ThreadPoolExecutor@5e4317c5[Shutting down, pool size = 2, active threads = 2, queued tasks = 0, completed tasks = 5]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2048)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
[junit4] 2> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:110)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.process(SolrZkClient.java:206)
[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> 424945 T2350 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 424946 T2349 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 424951 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 425056 T2349 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> 426444 T2337 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 426447 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 426448 T2352 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7af38db4 name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 426448 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 426450 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 426452 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 426455 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 426455 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 426457 T2343 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426457 T2343 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426461 T2353 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 426462 T2346 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 426462 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 426463 T2343 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426463 T2343 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426463 T2332 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 426465 T2332 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 426466 T2355 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28b612e1 name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 426466 T2332 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 426466 T2332 oasc.Overseer.close Overseer (id=92324642036842501-127.0.0.1:11446_solr-n_0000000001) closing
[junit4] 2> 426467 T2343 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:11446_solr
[junit4] 2> 426467 T2332 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 426468 T2356 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 426468 T2332 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 426469 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 426470 T2358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cf2a36e name:ZooKeeperConnection Watcher:127.0.0.1:11446/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 426470 T2332 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:11446_solr
[junit4] 2> 426470 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 426470 T2332 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 426471 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 426472 T2332 oasc.Overseer.start Overseer (id=92324642036842504-127.0.0.1:11446_solr-n_0000000002) starting
[junit4] 2> 426473 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 426476 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 426480 T2332 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 426480 T2361 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 426482 T2360 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 426482 T2360 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426483 T2360 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426483 T2353 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426483 T2359 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426485 T2360 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426485 T2360 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426486 T2359 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426486 T2353 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426499 T2360 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 426501 T2360 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426501 T2360 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426503 T2363 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 426506 T2360 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 426506 T2360 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426508 T2363 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 426509 T2359 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426509 T2353 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 426685 T2266 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 426685 T2363 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 426687 T2360 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> 426687 T2360 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 426691 T2364 oasc.LeaderElector$ElectionWatcher.process WARN org.apache.zookeeper.KeeperException$SessionExpiredExce
[...truncated too long message...]
path:null type:None
[junit4] 2> 469188 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 469188 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 469190 T3147 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1be54f54 name:ZooKeeperConnection Watcher:127.0.0.1:22416 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 469190 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 469192 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 469193 T3149 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7e433fe9 name:ZooKeeperConnection Watcher:127.0.0.1:22416 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 469193 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 469193 T2266 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 469196 T2266 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 469197 T2266 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 469199 T2266 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 469200 T2266 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 469202 T2266 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 469203 T3151 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2361b1af name:ZooKeeperConnection Watcher:127.0.0.1:22416/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 469203 T2266 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 469204 T2266 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 469204 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 469206 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 469207 T2266 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 469208 T2266 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:22416_solr
[junit4] 2> 469209 T2266 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 469210 T2266 oasc.Overseer.start Overseer (id=92324645006606339-127.0.0.1:22416_solr-n_0000000000) starting
[junit4] 2> 469211 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 469213 T2266 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 469215 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 469217 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 469219 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 469221 T2266 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 469224 T2266 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 469224 T3153 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 469225 T3152 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 469227 T3152 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> 469227 T3152 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 469229 T3155 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 469230 T3156 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> 469278 T3155 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 469279 T3152 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> 469279 T3152 oasc.Overseer$ClusterStateUpdater.updateState node=core_node1 is already registered
[junit4] 2> 469279 T3152 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 469382 T3156 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> 469432 T2266 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:22416 22416
[junit4] 2> 470671 T3139 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:22416 22416
[junit4] 2> 470672 T2266 oas.SolrTestCaseJ4.tearDown ###Ending testStateChange
[junit4] 2> 470673 T2266 oasc.Overseer.close Overseer (id=92324645006606339-127.0.0.1:22416_solr-n_0000000000) closing
[junit4] 2> 470673 T3152 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:22416_solr
[junit4] 2> 470674 T3157 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 473675 T2266 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solr.cloud.OverseerTest-A488D6E45BB4A02F-001
[junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=sk, timezone=Etc/GMT+11
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=171820816,total=509607936
[junit4] 2> NOTE: All tests run in this JVM: [TestDistributedGrouping, MBeansHandlerTest, TestRealTimeGet, HardAutoCommitTest, BasicDistributedZkTest, TestComplexPhraseQParserPlugin, TestPivotHelperCode, DocumentBuilderTest, TestDistributedMissingSort, TestReloadAndDeleteDocs, ParsingFieldUpdateProcessorsTest, OverseerTest]
[junit4] Completed on J0 in 75.52s, 9 tests, 1 error <<< FAILURES!
[...truncated 1221 lines...]
BUILD FAILED
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:485: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:465: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:48: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:494: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1343: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:958: There were test failures: 419 suites, 1733 tests, 1 error, 53 ignored (19 assumptions)
Total time: 133 minutes 19 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-Tests-4.x-Java7 #2065
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 193179332 bytes
Compression is 0.0%
Took 36 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 2072 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/2072/
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([2BFAD87E5C912CA4:2FF2578D4E34C385]:0)
at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:150)
at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
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:1618)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
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:65)
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:365)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
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:65)
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:365)
at java.lang.Thread.run(Thread.java:745)
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:137)
... 48 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$11.execute(SolrZkClient.java:462)
at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:459)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:416)
at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:403)
at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:142)
at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
... 49 more
Build Log:
[...truncated 11031 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> Creating dataDir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./temp/solr.cloud.OverseerTest-2BFAD87E5C912CA4-001/init-core-data-001
[junit4] 2> 934278 T1576 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (true)
[junit4] 2> 934279 T1576 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 934279 T1576 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 934285 T1576 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 934286 T1576 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 934286 T1577 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 934386 T1576 oasc.ZkTestServer.run start zk server on port:51907
[junit4] 2> 934387 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 934392 T1583 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43ff9e3d name:ZooKeeperConnection Watcher:127.0.0.1:51907 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 934392 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 934394 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 934396 T1585 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c1de932 name:ZooKeeperConnection Watcher:127.0.0.1:51907 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 934396 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 934396 T1576 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 934400 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 934401 T1587 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37f23034 name:ZooKeeperConnection Watcher:127.0.0.1:51907/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 934401 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 934401 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 934404 T1576 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 934405 T1576 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 934407 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 934410 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 934411 T1589 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34f55f1c name:ZooKeeperConnection Watcher:127.0.0.1:51907/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 934412 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 934413 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 934415 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 934418 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 934420 T1593 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e7f8154 name:ZooKeeperConnection Watcher:127.0.0.1:51907/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 934420 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 934420 T1576 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 934424 T1576 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 934426 T1576 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 934428 T1576 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 934430 T1576 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:51907_solr
[junit4] 2> 934430 T1576 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 934432 T1576 oasc.Overseer.start Overseer (id=92334267892236292-127.0.0.1:51907_solr-n_0000000000) starting
[junit4] 2> 934434 T1576 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 934436 T1576 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 934439 T1576 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 934442 T1576 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 934444 T1576 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 934447 T1576 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 934451 T1576 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 934452 T1595 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 934453 T1594 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 935455 T1597 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 935457 T1594 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> 935457 T1594 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 935457 T1594 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 935460 T1591 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> 935460 T1590 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> 935956 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 935963 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 935968 T1597 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 935970 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 935972 T1594 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> 935973 T1594 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 935975 T1597 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 935976 T1590 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> 935976 T1591 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> 936455 T1595 oasc.OverseerCollectionProcessor.amILeader org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.amILeader(OverseerCollectionProcessor.java:514)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:272)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 936455 T1595 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=92334267892236292-127.0.0.1:51907_solr-n_0000000000) am no longer a leader.
[junit4] 2> 937030 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 937036 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 937037 T1599 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b1de3ca name:ZooKeeperConnection Watcher:127.0.0.1:51907/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 937038 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 937038 T1576 oasc.Overseer.close Overseer (id=92334267892236292-127.0.0.1:51907_solr-n_0000000000) closing
[junit4] 2> 937039 T1594 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:51907_solr
[junit4] 2> 937040 T1576 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 937040 T1600 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 937044 T1576 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 937046 T1576 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:51907_solr
[junit4] 2> 937047 T1576 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 937048 T1576 oasc.Overseer.start Overseer (id=92334267892236293-127.0.0.1:51907_solr-n_0000000001) starting
[junit4] 2> 937057 T1576 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 937057 T1602 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 937058 T1601 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 937061 T1601 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> 937061 T1601 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 937063 T1604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 937064 T1591 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> 937064 T1590 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> 937116 T1604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 937116 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 937122 T1576 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/92334267892236291-node1_core1-n_0000000001
[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$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:148)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
[junit4] 2> at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
[junit4] 2> at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
[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:1618)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
[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:65)
[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:365)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
[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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[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:65)
[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:365)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 937123 T1605 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 937123 T1601 oasc.SolrException.log ERROR Problem cleaning up collection in zk:collection1:org.apache.zookeeper.KeeperException$NotEmptyException: KeeperErrorCode = Directory not empty for /collections/collection1/leader_elect/shard1/election
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:125)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:189)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:186)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:186)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:670)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.clean(SolrZkClient.java:665)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.removeCore(Overseer.java:1104)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.processMessage(Overseer.java:362)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.run(Overseer.java:244)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 937122 T1590 oasc.LeaderElector.checkIfIamLeader WARN Our node is no longer in line to be leader
[junit4] 2> 937124 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 937128 T1604 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 937129 T1601 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 937232 T1591 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> 937232 T1605 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> 938127 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 939130 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 940133 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 941136 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 942139 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 943142 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 944145 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 945148 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 946151 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 947154 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 948157 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 949160 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 950163 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 951166 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 952169 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 953673 T1605 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 953677 T1576 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51907 51907
[junit4] 2> 953820 T1577 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:51907 51907
[junit4] 2> 953821 T1576 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 2> 953822 T1576 oasc.Overseer.close Overseer (id=92334267892236293-127.0.0.1:51907_solr-n_0000000001) closing
[junit4] 2> 953822 T1601 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:51907_solr
[junit4] 2> 953824 T1606 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=OverseerTest -Dtests.method=testOverseerFailure -Dtests.seed=2BFAD87E5C912CA4 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_BH -Dtests.timezone=Asia/Phnom_Penh -Dtests.file.encoding=UTF-8
[junit4] ERROR 19.6s J1 | OverseerTest.testOverseerFailure <<<
[junit4] > Throwable #1: org.apache.solr.common.SolrException: Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed
[junit4] > at __randomizedtesting.SeedInfo.seed([2BFAD87E5C912CA4:2FF2578D4E34C385]:0)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:150)
[junit4] > at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] > at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:155)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:314)
[junit4] > at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:221)
[junit4] > at org.apache.solr.cloud.OverseerTest$MockZKController.publishState(OverseerTest.java:157)
[junit4] > at org.apache.solr.cloud.OverseerTest.testOverseerFailure(OverseerTest.java:662)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > Caused by: org.apache.solr.common.SolrException: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:40)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:137)
[junit4] > ... 48 more
[junit4] > Caused by: org.apache.zookeeper.KeeperException$NodeExistsException: KeeperErrorCode = NodeExists for /collections/collection1/leaders/shard1
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:119)
[junit4] > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] > at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient$11.execute(SolrZkClient.java:462)
[junit4] > at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:459)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:416)
[junit4] > at org.apache.solr.common.cloud.SolrZkClient.makePath(SolrZkClient.java:403)
[junit4] > at org.apache.solr.cloud.ShardLeaderElectionContextBase$1.execute(ElectionContext.java:142)
[junit4] > at org.apache.solr.common.util.RetryUtil.retryOnThrowable(RetryUtil.java:34)
[junit4] > ... 49 more
[junit4] 2> 953849 T1576 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 953851 T1576 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 953851 T1607 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 953951 T1576 oasc.ZkTestServer.run start zk server on port:56974
[junit4] 2> 953952 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 953955 T1613 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2067eca1 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 953955 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 953956 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 953958 T1615 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@257798ac name:ZooKeeperConnection Watcher:127.0.0.1:56974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 953958 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 953960 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 953961 T1617 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33c1ded1 name:ZooKeeperConnection Watcher:127.0.0.1:56974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 953962 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 953962 T1576 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 953965 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 953968 T1618 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 953969 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 953970 T1621 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@462c3237 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 953970 T1618 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 953970 T1622 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f94dcde name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 953970 T1618 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 953970 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 953972 T1576 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 953974 T1576 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 953974 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 953975 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 953976 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 953977 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 953977 T1618 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 953979 T1618 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:56974_solr
[junit4] 2> 953980 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 953980 T1576 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 953981 T1618 oasc.Overseer.start Overseer (id=92334269174448131-127.0.0.1:56974_solr-n_0000000000) starting
[junit4] 2> 953984 T1618 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 953986 T1618 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 953988 T1618 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 953990 T1618 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 953993 T1618 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 953997 T1618 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 953997 T1625 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 953997 T1618 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 953999 T1618 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 954000 T1628 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21d3e28 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 954000 T1618 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 954001 T1618 oasc.Overseer.close Overseer (id=92334269174448131-127.0.0.1:56974_solr-n_0000000000) closing
[junit4] 2> 954001 T1625 oasc.OverseerCollectionProcessor.run ERROR Unable to prioritize overseer org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /roles.json
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1045)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:256)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:253)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:253)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.prioritizeOverseerNodes(OverseerCollectionProcessor.java:412)
[junit4] 2> at org.apache.solr.cloud.OverseerCollectionProcessor.run(OverseerCollectionProcessor.java:259)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 954001 T1618 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 954006 T1618 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 954008 T1618 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:56974_solr
[junit4] 2> 954008 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 954010 T1618 oasc.Overseer.start Overseer (id=92334269174448133-127.0.0.1:56974_solr-n_0000000001) starting
[junit4] 2> 954017 T1618 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 954018 T1630 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 954019 T1629 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 954021 T1629 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 954021 T1629 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 954022 T1629 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 954024 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 954024 T1623 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> 954483 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 954491 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 954495 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 954496 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 954499 T1629 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 954500 T1629 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 954502 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 954502 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 954503 T1634 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@649c4933 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 954503 T1623 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> 954503 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 954505 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 954507 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 954511 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 954511 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 954513 T1629 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 954513 T1629 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 954518 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 954519 T1629 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> 954519 T1629 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4] 2> 954519 T1629 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 954622 T1635 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 954622 T1623 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 955018 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 955025 T1636 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 955026 T1635 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 955030 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 955135 T1635 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> 956525 T1623 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 956528 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 956530 T1638 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b8594e7 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 956530 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 956532 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 956534 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 956537 T1632 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 956537 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 956539 T1629 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 956539 T1629 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 956542 T1618 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 956544 T1608 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x148098752bd0005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 956544 T1618 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 956545 T1639 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 956546 T1641 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bc7fae5 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 956546 T1618 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 956546 T1618 oasc.Overseer.close Overseer (id=92334269174448133-127.0.0.1:56974_solr-n_0000000001) closing
[junit4] 2> 956547 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 956547 T1618 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 956547 T1629 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:56974_solr
[junit4] 2> 956548 T1642 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 956552 T1618 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 956553 T1618 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:56974_solr
[junit4] 2> 956553 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 956554 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 956555 T1644 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1029cad3 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 956555 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 956556 T1618 oasc.Overseer.start Overseer (id=92334269174448136-127.0.0.1:56974_solr-n_0000000002) starting
[junit4] 2> 956556 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 956559 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 956562 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 956565 T1618 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 956566 T1647 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 956568 T1646 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 956569 T1646 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 956569 T1646 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 956570 T1645 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 956570 T1639 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 956572 T1646 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 956574 T1646 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 956574 T1646 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 956576 T1649 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 956579 T1646 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 956580 T1646 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 956582 T1649 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 956582 T1639 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 956582 T1645 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 956771 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 956771 T1649 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 956773 T1646 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> 956774 T1646 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 956778 T1650 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 956778 T1645 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 956782 T1649 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 956886 T1645 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> 958277 T1639 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 958280 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 958282 T1652 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e7be58e name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 958282 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 958282 T1618 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 958284 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 958285 T1618 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 958286 T1654 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1663d25b name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 958286 T1618 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 958286 T1618 oasc.Overseer.close Overseer (id=92334269174448136-127.0.0.1:56974_solr-n_0000000002) closing
[junit4] 2> 958287 T1646 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:56974_solr
[junit4] 2> 958287 T1618 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 958288 T1655 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 958288 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 958292 T1618 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 958293 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 958293 T1618 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:56974_solr
[junit4] 2> 958293 T1618 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 958295 T1618 oasc.Overseer.start Overseer (id=92334269174448139-127.0.0.1:56974_solr-n_0000000003) starting
[junit4] 2> 958300 T1656 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 958300 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 958304 T1618 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 958305 T1658 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 958305 T1657 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 958306 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 958307 T1661 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36114410 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 958307 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 958309 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 958309 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 958309 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 958311 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 958311 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 958312 T1656 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> 958312 T1663 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> 958315 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 958316 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 958316 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 958318 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 958322 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 958322 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 958324 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 958325 T1665 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 958325 T1664 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4] 2> 958524 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 958524 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 958526 T1657 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> 958526 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 958531 T1665 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 958535 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 958639 T1665 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> 960030 T1656 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 960030 T1664 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 960034 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 960036 T1667 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@282cb5a1 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 960036 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 960038 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 960040 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 960044 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960044 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 960045 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 960046 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 960050 T1668 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 960051 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960051 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 960052 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state2",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 960052 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 960057 T1576 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 960057 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960058 T1670 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ee2d3da name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 960058 T1668 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> 960058 T1576 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 960060 T1576 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 960062 T1576 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 960065 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960065 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 960067 T1657 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "operation":"state",
[junit4] 2> "state":"state1",
[junit4] 2> "node_name":"node1",
[junit4] 2> "core":"core1",
[junit4] 2> "core_node_name":"node1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "numShards":"1",
[junit4] 2> "base_url":"http://node1/solr/"}
[junit4] 2> 960067 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 960072 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960072 T1576 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 960073 T1657 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> 960073 T1657 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 960079 T1672 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 960080 T1671 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 960084 T1662 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 960122 T1618 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 960124 T1618 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 960125 T1674 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60246025 name:ZooKeeperConnection Watcher:127.0.0.1:56974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 960126 T1618 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 960126 T1618 oasc.Overseer.close Overseer (id=92334269174448139-127.0.0.1:56974_solr-n_0000000003) closing
[junit4] 2> 960126 T1657 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:56974_solr
[junit4] 2> 960127 T1618 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 960127 T1675 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 960131 T1618 oasc.Ove
[...truncated too long message...]
2)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 1018511 T2186 oasc.LeaderElector$ElectionWatcher.process WARN java.lang.RuntimeException: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer
[junit4] 2> at org.apache.solr.cloud.Overseer.createOverseerNode(Overseer.java:1342)
[junit4] 2> at org.apache.solr.cloud.Overseer.getInQueue(Overseer.java:1293)
[junit4] 2> at org.apache.solr.cloud.Overseer.getInQueue(Overseer.java:1289)
[junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContextBase.runLeaderProcess(ElectionContext.java:161)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:163)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:125)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer
[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.create(ZooKeeper.java:783)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:342)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$10.execute(SolrZkClient.java:339)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:339)
[junit4] 2> at org.apache.solr.cloud.Overseer.createOverseerNode(Overseer.java:1333)
[junit4] 2> ... 13 more
[junit4] 2>
[junit4] 2> 1018513 T2325 oasc.LeaderElector$ElectionWatcher.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$7.execute(SolrZkClient.java:290)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$7.execute(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:287)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:94)
[junit4] 2> at org.apache.solr.cloud.LeaderElector.access$200(LeaderElector.java:55)
[junit4] 2> at org.apache.solr.cloud.LeaderElector$ElectionWatcher.process(LeaderElector.java:358)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3$1.run(SolrZkClient.java:209)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 1020013 T2189 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1020016 T1576 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:44960 44960
[junit4] 2> 1020178 T1927 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:44960 44960
[junit4] 2> 1020180 T1576 oas.SolrTestCaseJ4.tearDown ###Ending testShardAssignmentBigger
[junit4] 2> 1020181 T1576 oasc.Overseer.close Overseer (id=92334271354896387-127.0.0.1:44960_solr-n_0000000000) closing
[junit4] 2> 1020181 T1940 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:44960_solr
[junit4] 2> 1020182 T2336 oasc.Overseer$ClusterStateUpdater.checkIfIamStillLeader ERROR could not read the data org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/leader
[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.getData(ZooKeeper.java:1155)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:307)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$8.execute(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:74)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:304)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.checkIfIamStillLeader(Overseer.java:320)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater.access$300(Overseer.java:89)
[junit4] 2> at org.apache.solr.cloud.Overseer$ClusterStateUpdater$1.run(Overseer.java:292)
[junit4] 2>
[junit4] 2> 1023183 T1576 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./temp/solr.cloud.OverseerTest-2BFAD87E5C912CA4-001
[junit4] 2> NOTE: test params are: codec=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=348), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=348)), sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=ar_BH, timezone=Asia/Phnom_Penh
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=1,free=304980552,total=490733568
[junit4] 2> NOTE: All tests run in this JVM: [PeerSyncTest, TestTolerantSearch, DistributedTermsComponentTest, TestFastWriter, OpenExchangeRatesOrgProviderTest, TestGroupingSearch, TestIntervalFaceting, TestCustomSort, IndexSchemaTest, TestSolrIndexConfig, DisMaxRequestHandlerTest, TestLRUCache, AnalysisAfterCoreReloadTest, HdfsBasicDistributedZkTest, HardAutoCommitTest, ZkControllerTest, ShardRoutingCustomTest, TestIBSimilarityFactory, DocumentAnalysisRequestHandlerTest, TestStressUserVersions, OverseerCollectionProcessorTest, FileUtilsTest, TestCloudManagedSchemaConcurrent, StatsComponentTest, DistributedFacetPivotLongTailTest, SuggesterWFSTTest, WordBreakSolrSpellCheckerTest, TestCSVResponseWriter, RequiredFieldsTest, TestConfig, TestCloudManagedSchema, MBeansHandlerTest, TestUniqueKeyFieldResource, TestSolrXml, UnloadDistributedZkTest, CoreContainerCoreInitFailuresTest, TestSolr4Spatial, TestIndexingPerformance, TestExpandComponent, AssignTest, TestReversedWildcardFilterFactory, FieldMutatingUpdateProcessorTest, TestCoreDiscovery, TestOmitPositions, SpatialFilterTest, TestJmxMonitoredMap, LeaderElectionIntegrationTest, TestDefaultSearchFieldResource, OverseerTest]
[junit4] Completed on J1 in 88.94s, 9 tests, 1 error <<< FAILURES!
[...truncated 1158 lines...]
BUILD FAILED
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:485: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:465: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:48: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:494: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1343: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:958: There were test failures: 419 suites, 1734 tests, 1 error, 55 ignored (21 assumptions)
Total time: 118 minutes 56 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-Tests-4.x-Java7 #2065
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 180949961 bytes
Compression is 0.0%
Took 32 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 2071 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/2071/
All tests passed
Build Log:
[...truncated 47258 lines...]
-documentation-lint:
[echo] checking for broken html...
[jtidy] Checking for broken html (such as invalid tags)...
[delete] Deleting directory /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/build/jtidy_tmp
[echo] Checking for broken links...
[exec]
[exec] Crawl/parse...
[exec]
[exec] Verify...
[echo] Checking for missing docs...
[exec]
[exec] build/docs/suggest/org/apache/lucene/search/suggest/analyzing/AnalyzingInfixSuggester.html
[exec] missing Methods: commit()
[exec]
[exec] Missing javadocs were found!
BUILD FAILED
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:485: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:66: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/build.xml:212: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/build.xml:257: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:2419: exec returned: 1
Total time: 172 minutes 25 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-Tests-4.x-Java7 #2065
Archived 1 artifacts
Archive block size is 32768
Received 0 blocks and 464 bytes
Compression is 0.0%
Took 9 ms
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 2070 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/2070/
2 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.handler.TestReplicationHandlerBackup
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.handler.TestReplicationHandlerBackup: 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579) at java.net.Socket.connect(Socket.java:528) at sun.net.NetworkClient.doConnect(NetworkClient.java:180) at sun.net.www.http.HttpClient.openServer(HttpClient.java:432) at sun.net.www.http.HttpClient.openServer(HttpClient.java:527) at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652) at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323) at java.net.URL.openStream(URL.java:1037) at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.handler.TestReplicationHandlerBackup:
1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:579)
at java.net.Socket.connect(Socket.java:528)
at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
at java.net.URL.openStream(URL.java:1037)
at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
at __randomizedtesting.SeedInfo.seed([7DD12FBA3D9760E9]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.handler.TestReplicationHandlerBackup
Error Message:
There are still zombie threads that couldn't be terminated: 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579) at java.net.Socket.connect(Socket.java:528) at sun.net.NetworkClient.doConnect(NetworkClient.java:180) at sun.net.www.http.HttpClient.openServer(HttpClient.java:432) at sun.net.www.http.HttpClient.openServer(HttpClient.java:527) at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652) at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323) at java.net.URL.openStream(URL.java:1037) at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:579)
at java.net.Socket.connect(Socket.java:528)
at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
at java.net.URL.openStream(URL.java:1037)
at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
at __randomizedtesting.SeedInfo.seed([7DD12FBA3D9760E9]:0)
Build Log:
[...truncated 10995 lines...]
[junit4] Suite: org.apache.solr.handler.TestReplicationHandlerBackup
[junit4] 2> Creating dataDir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/init-core-data-001
[junit4] 2> 735593 T5142 oas.SolrTestCaseJ4.setUp ###Starting doTestBackup
[junit4] 2> 735605 T5142 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 735608 T5142 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:27722
[junit4] 2> 735609 T5142 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 735609 T5142 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 735609 T5142 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001
[junit4] 2> 735610 T5142 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/'
[junit4] 2> 735642 T5142 oasc.ConfigSolr.fromFile Loading container configuration from /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/solr.xml
[junit4] 2> 735714 T5142 oasc.CoreContainer.<init> New CoreContainer 308624725
[junit4] 2> 735715 T5142 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/]
[junit4] 2> 735716 T5142 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 735716 T5142 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 735716 T5142 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 735716 T5142 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 735717 T5142 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 735717 T5142 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 735717 T5142 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 735717 T5142 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 735717 T5142 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 735718 T5142 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
[junit4] 2> 735718 T5142 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 735719 T5142 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 735719 T5142 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 735723 T5152 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: './solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/'
[junit4] 2> 735760 T5152 oasc.SolrConfig.<init> Using Lucene MatchVersion: 4.11.0
[junit4] 2> 735793 T5152 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 735794 T5152 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4] 2> 735799 T5152 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 735813 T5152 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 735814 T5152 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from instancedir ./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/
[junit4] 2> 735814 T5152 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 735814 T5152 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/, dataDir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/
[junit4] 2> 735815 T5152 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 735815 T5152 oasc.CachingDirectoryFactory.get return new directory for /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data
[junit4] 2> 735815 T5152 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index/
[junit4] 2> 735815 T5152 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index' doesn't exist. Creating new index...
[junit4] 2> 735816 T5152 oasc.CachingDirectoryFactory.get return new directory for /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index
[junit4] 2> 735816 T5152 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=25, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.4210399314544174]
[junit4] 2> 735817 T5152 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@499efaef lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@70d5297f),segFN=segments_1,generation=1}
[junit4] 2> 735817 T5152 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 735818 T5152 oasc.SolrCore.loadUpdateProcessorChains no updateRequestProcessorChain defined as default, creating implicit default
[junit4] 2> 735819 T5152 oasc.RequestHandlers.initHandlersFromConfig created /update: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 735819 T5152 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 735819 T5152 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4] 2> 735820 T5152 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4] 2> 735821 T5152 oasc.RequestHandlers.initHandlersFromConfig WARN Multiple requestHandler registered to the same name: /update ignoring: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 735821 T5152 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 735833 T5152 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 735834 T5152 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 735836 T5152 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 735837 T5152 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 735838 T5152 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 735840 T5152 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 735840 T5152 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 735841 T5152 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=25, maxMergeAtOnceExplicit=38, maxMergedSegmentMB=34.779296875, floorSegmentMB=1.5166015625, forceMergeDeletesPctAllowed=5.642644846724176, segmentsPerTier=34.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 735841 T5152 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@499efaef lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@70d5297f),segFN=segments_1,generation=1}
[junit4] 2> 735841 T5152 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 735842 T5152 oass.SolrIndexSearcher.<init> Opening Searcher@59671c04[collection1] main
[junit4] 2> 735842 T5152 oasr.ManagedResourceStorage$FileStorageIO.configure File-based storage initialized to use dir: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/conf
[junit4] 2> 735842 T5152 oasr.RestManager.init Initializing RestManager with initArgs: {storageDir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/conf}
[junit4] 2> 735843 T5152 oasr.ManagedResourceStorage.load Reading _rest_managed.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/conf
[junit4] 2> 735843 T5152 oasr.ManagedResource.reloadFromStorage WARN No stored data found for /rest/managed
[junit4] 2> 735843 T5152 oasr.ManagedResourceStorage$JsonStorage.store Saved JSON object to path _rest_managed.json using file:dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/conf
[junit4] 2> 735844 T5152 oasr.RestManager.init Initializing 0 registered ManagedResources
[junit4] 2> 735844 T5152 oash.ReplicationHandler.inform Replication enabled for following config files: schema-replication2.xml:schema.xml
[junit4] 2> 735844 T5152 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4] 2> 735844 T5152 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 735844 T5153 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@59671c04[collection1] main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4] 2> 735845 T5142 oass.SolrDispatchFilter.init user.dir=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4] 2> 735845 T5142 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> ASYNC NEW_CORE C606 name=collection1 org.apache.solr.core.SolrCore@1c7c4367
[junit4] 2> 735848 T5145 C606 oasu.DirectUpdateHandler2.deleteAll [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4] 2> 735849 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 2
[junit4] 2> 735853 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[0]} 0 1
[junit4] 2> 735856 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[1]} 0 0
[junit4] 2> 735859 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[2]} 0 0
[junit4] 2> 735862 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[3]} 0 0
[junit4] 2> 735865 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[4]} 0 0
[junit4] 2> 735868 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[5]} 0 0
[junit4] 2> 735871 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[6]} 0 0
[junit4] 2> 735874 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[7]} 0 0
[junit4] 2> 735877 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[8]} 0 0
[junit4] 2> 735880 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[9]} 0 0
[junit4] 2> 735883 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[10]} 0 0
[junit4] 2> 735886 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[11]} 0 0
[junit4] 2> 735889 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[12]} 0 0
[junit4] 2> 735892 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[13]} 0 0
[junit4] 2> 735895 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[14]} 0 0
[junit4] 2> 735898 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[15]} 0 0
[junit4] 2> 735901 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[16]} 0 0
[junit4] 2> 735904 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[17]} 0 0
[junit4] 2> 735907 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[18]} 0 0
[junit4] 2> 735910 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[19]} 0 0
[junit4] 2> 735913 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[20]} 0 0
[junit4] 2> 735916 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[21]} 0 0
[junit4] 2> 735919 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[22]} 0 0
[junit4] 2> 735922 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[23]} 0 0
[junit4] 2> 735925 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[24]} 0 0
[junit4] 2> 735928 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[25]} 0 0
[junit4] 2> 735931 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[26]} 0 0
[junit4] 2> 735934 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[27]} 0 0
[junit4] 2> 735937 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[28]} 0 0
[junit4] 2> 735940 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[29]} 0 0
[junit4] 2> 735943 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[30]} 0 0
[junit4] 2> 735946 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[31]} 0 0
[junit4] 2> 735949 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[32]} 0 0
[junit4] 2> 735952 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[33]} 0 0
[junit4] 2> 735955 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[34]} 0 0
[junit4] 2> 735958 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[35]} 0 0
[junit4] 2> 735960 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[36]} 0 0
[junit4] 2> 735963 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[37]} 0 0
[junit4] 2> 735966 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[38]} 0 0
[junit4] 2> 735969 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[39]} 0 0
[junit4] 2> 735972 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[40]} 0 0
[junit4] 2> 735973 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[41]} 0 0
[junit4] 2> 735975 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[42]} 0 0
[junit4] 2> 735978 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[43]} 0 0
[junit4] 2> 735981 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[44]} 0 0
[junit4] 2> 735984 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[45]} 0 0
[junit4] 2> 735987 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[46]} 0 0
[junit4] 2> 735989 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[47]} 0 0
[junit4] 2> 735992 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[48]} 0 0
[junit4] 2> 735995 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[49]} 0 0
[junit4] 2> 735998 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[50]} 0 0
[junit4] 2> 736001 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[51]} 0 0
[junit4] 2> 736004 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[52]} 0 0
[junit4] 2> 736007 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[53]} 0 0
[junit4] 2> 736010 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[54]} 0 0
[junit4] 2> 736013 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[55]} 0 0
[junit4] 2> 736016 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[56]} 0 0
[junit4] 2> 736019 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[57]} 0 0
[junit4] 2> 736022 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[58]} 0 0
[junit4] 2> 736025 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[59]} 0 0
[junit4] 2> 736028 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[60]} 0 0
[junit4] 2> 736030 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[61]} 0 0
[junit4] 2> 736032 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[62]} 0 0
[junit4] 2> 736035 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[63]} 0 0
[junit4] 2> 736038 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[64]} 0 0
[junit4] 2> 736041 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={wt=javabin&version=2} {add=[65]} 0 0
[junit4] 2> 736044 T5145 C606 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 736047 T5145 C606 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@499efaef lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@70d5297f),segFN=segments_1,generation=1}
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory@499efaef lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@70d5297f),segFN=segments_2,generation=2}
[junit4] 2> 736048 T5145 C606 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4] 2> 736049 T5145 C606 oass.SolrIndexSearcher.<init> Opening Searcher@2e9ef9e2[collection1] main
[junit4] 2> 736050 T5145 C606 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 736050 T5153 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e9ef9e2[collection1] main{StandardDirectoryReader(segments_2:4:nrt _0(4.11.0):c66)}
[junit4] 2> 736050 T5145 C606 oasup.LogUpdateProcessor.finish [collection1] webapp=/solr path=/update params={waitSearcher=true&softCommit=false&wt=javabin&commit=true&version=2} {commit=} 0 6
[junit4] 2> 736054 T5147 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 736073 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=backup&name=qfgnxycnvyexffkpmjqp} status=0 QTime=19
[junit4] 2> 736073 T5157 oash.SnapShooter.createSnapshot Creating backup snapshot...
[junit4] 2> 736082 T5157 oash.SnapShooter.createSnapshot Done creating backup snapshot, completed at: Sat Aug 23 17:14:31 IST 2014
[junit4] 2> 736083 T5157 oash.SnapShooter.createSnapshot Done creating backup snapshot: qfgnxycnvyexffkpmjqp
[junit4] 2> 736265 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737280 T5147 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737281 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=backup&name=xby} status=0 QTime=1
[junit4] 2> 737281 T5159 oash.SnapShooter.createSnapshot Creating backup snapshot...
[junit4] 2> 737289 T5159 oash.SnapShooter.createSnapshot Done creating backup snapshot, completed at: Sat Aug 23 17:14:33 IST 2014
[junit4] 2> 737290 T5159 oash.SnapShooter.createSnapshot Done creating backup snapshot: xby
[junit4] 2> 737482 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737489 T5147 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737493 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=deletebackup&name=qfgnxycnvyexffkpmjqp} status=0 QTime=6
[junit4] 2> 737494 T5161 oash.SnapShooter.deleteNamedSnapshot Deleting snapshot: qfgnxycnvyexffkpmjqp
[junit4] 2> 737691 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737694 T5146 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=details} status=0 QTime=0
[junit4] 2> 737695 T5142 oas.SolrTestCaseJ4.tearDown ###Ending doTestBackup
[junit4] 2> 737695 T5163 oash.SnapShooter.deleteNamedSnapshot Deleting snapshot: xby
[junit4] 2> 737695 T5147 C606 oasc.SolrCore.execute [collection1] webapp=/solr path=/replication params={command=deletebackup&name=xby} status=0 QTime=1
[junit4] 2> 737696 T5142 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=308624725
[junit4] 2> 737698 T5142 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/solr,null}
[junit4] 2> 737698 T5147 C606 oasc.SolrException.log ERROR null:org.eclipse.jetty.io.EofException
[junit4] 2> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:142)
[junit4] 2> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:107)
[junit4] 2> at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
[junit4] 2> at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
[junit4] 2> at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
[junit4] 2> at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
[junit4] 2> at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
[junit4] 2> at org.apache.solr.util.FastWriter.flush(FastWriter.java:137)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.writeResponse(SolrDispatchFilter.java:766)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:426)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:207)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
[junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:137)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4] 2> at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:301)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1077)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:368)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
[junit4] 2> at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
[junit4] 2> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
[junit4] 2> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
[junit4] 2> at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
[junit4] 2> at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 737701 T5147 C606 oasc.SolrException.log ERROR null:org.eclipse.jetty.io.EofException
[junit4] 2> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:142)
[junit4] 2> at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:107)
[junit4] 2> at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
[junit4] 2> at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
[junit4] 2> at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
[junit4] 2> at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
[junit4] 2> at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
[junit4] 2> at org.apache.solr.util.FastWriter.flush(FastWriter.java:137)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.writeResponse(SolrDispatchFilter.java:766)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:426)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:207)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
[junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:137)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1419)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:455)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4] 2> at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:301)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1077)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:384)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1009)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:368)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
[junit4] 2> at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(BlockingHttpConnection.java:53)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:942)
[junit4] 2> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1004)
[junit4] 2> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:640)
[junit4] 2> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
[junit4] 2> at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
[junit4] 2> at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2>
[junit4] 2> 737725 T5147 C606 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1c7c4367
[junit4] 2> 737726 T5147 C606 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=66,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4] 2> 737727 T5147 C606 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4] 2> 737727 T5147 C606 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4] 2> 737727 T5147 C606 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4] 2> 737729 T5147 C606 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 737729 T5147 C606 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 737730 T5147 C606 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data [CachedDir<<refCount=0;path=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data;done=false>>]
[junit4] 2> 737730 T5147 C606 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data
[junit4] 2> 737731 T5147 C606 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index [CachedDir<<refCount=0;path=/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index;done=false>>]
[junit4] 2> 737731 T5147 C606 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solr.handler.TestReplicationHandlerBackup-7DD12FBA3D9760E9-001/solr-instance-001/collection1/data/index
[junit4] 2> 742707 T5142 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> 7126 T5141 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> 27273 T5141 ccr.ThreadLeakControl.checkThreadLeaks SEVERE 1 thread leaked from SUITE scope at org.apache.solr.handler.TestReplicationHandlerBackup:
[junit4] 2> 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
[junit4] 2> at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4] 2> at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4] 2> at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4] 2> at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4] 2> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4] 2> at java.net.Socket.connect(Socket.java:579)
[junit4] 2> at java.net.Socket.connect(Socket.java:528)
[junit4] 2> at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
[junit4] 2> at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
[junit4] 2> at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
[junit4] 2> at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
[junit4] 2> at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
[junit4] 2> at java.net.URL.openStream(URL.java:1037)
[junit4] 2> at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
[junit4] 2> 27273 T5141 ccr.ThreadLeakControl.tryToInterruptAll Starting to interrupt leaked threads:
[junit4] 2> 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
[junit4] 2> 30281 T5141 ccr.ThreadLeakControl.tryToInterruptAll SEVERE There are still zombie threads that couldn't be terminated:
[junit4] 2> 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
[junit4] 2> at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4] 2> at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4] 2> at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4] 2> at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4] 2> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4] 2> at java.net.Socket.connect(Socket.java:579)
[junit4] 2> at java.net.Socket.connect(Socket.java:528)
[junit4] 2> at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
[junit4] 2> at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
[junit4] 2> at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
[junit4] 2> at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
[junit4] 2> at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
[junit4] 2> at java.net.URL.openStream(URL.java:1037)
[junit4] 2> at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
[junit4] 2> NOTE: test params are: codec=Lucene410: {name=MockVariableIntBlock(baseBlockSize=8), id=MockVariableIntBlock(baseBlockSize=8)}, docValues:{}, sim=DefaultSimilarity, locale=nl, timezone=Europe/Dublin
[junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_60 (64-bit)/cpus=16,threads=2,free=348331384,total=536870912
[junit4] 2> NOTE: All tests run in this JVM: [LukeRequestHandlerTest, SSLMigrationTest, EnumFieldTest, CursorPagingTest, TestMultiCoreConfBootstrap, TestRandomDVFaceting, MultiThreadedOCPTest, CacheHeaderTest, TestReplicationHandler, TestDocBasedVersionConstraints, TestFreeTextSuggestions, DistributedFacetPivotSmallTest, TestReloadAndDeleteDocs, PeerSyncTest, SOLR749Test, TestSuggestSpellingConverter, TestReplicationHandlerBackup]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestReplicationHandlerBackup -Dtests.seed=7DD12FBA3D9760E9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=nl -Dtests.timezone=Europe/Dublin -Dtests.file.encoding=US-ASCII
[junit4] ERROR 0.00s J1 | TestReplicationHandlerBackup (suite) <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.handler.TestReplicationHandlerBackup:
[junit4] > 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
[junit4] > at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4] > at java.net.Socket.connect(Socket.java:528)
[junit4] > at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
[junit4] > at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
[junit4] > at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
[junit4] > at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
[junit4] > at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
[junit4] > at java.net.URL.openStream(URL.java:1037)
[junit4] > at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
[junit4] > at __randomizedtesting.SeedInfo.seed([7DD12FBA3D9760E9]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
[junit4] > 1) Thread[id=5162, name=Thread-1508, state=RUNNABLE, group=TGRP-TestReplicationHandlerBackup]
[junit4] > at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4] > at java.net.Socket.connect(Socket.java:528)
[junit4] > at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
[junit4] > at sun.net.www.http.HttpClient.openServer(HttpClient.java:432)
[junit4] > at sun.net.www.http.HttpClient.openServer(HttpClient.java:527)
[junit4] > at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:652)
[junit4] > at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1323)
[junit4] > at java.net.URL.openStream(URL.java:1037)
[junit4] > at org.apache.solr.handler.TestReplicationHandlerBackup$BackupThread.run(TestReplicationHandlerBackup.java:313)
[junit4] > at __randomizedtesting.SeedInfo.seed([7DD12FBA3D9760E9]:0)
[junit4] Completed on J1 in 30.35s, 1 test, 2 errors <<< FAILURES!
[...truncated 1134 lines...]
BUILD FAILED
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:485: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:465: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:48: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/extra-targets.xml:37: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:189: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:494: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1343: The following error occurred while executing this line:
/usr/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:958: There were test failures: 419 suites, 1733 tests, 2 suite-level errors, 1267 ignored (11 assumptions)
Total time: 99 minutes 50 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Sending artifact delta relative to Lucene-Solr-Tests-4.x-Java7 #2065
Archived 3 artifacts
Archive block size is 32768
Received 0 blocks and 75421526 bytes
Compression is 0.0%
Took 14 sec
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure