You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2014/08/23 13:34:53 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk7) - Build # 10956
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/10956/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
2 tests failed.
REGRESSION: org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.testDistribSearch
Error Message:
Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet expected:<0> but was:<1>
Stack Trace:
java.lang.AssertionError: Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet expected:<0> but was:<1>
at __randomizedtesting.SeedInfo.seed([FF1D7A7A3E09F4D2:7EFBF462495694EE]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.waitForNoResults(DistribDocExpirationUpdateProcessorTest.java:189)
at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.doTest(DistribDocExpirationUpdateProcessorTest.java:95)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:871)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:94)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:619)
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:853)
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([FF1D7A7A3E09F4D2:FB15F5892CAC1BF3]: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:94)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:619)
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:853)
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 11131 lines...]
[junit4] Suite: org.apache.solr.cloud.OverseerTest
[junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solr.cloud.OverseerTest-FF1D7A7A3E09F4D2-001/init-core-data-001
[junit4] 2> 21793 T77 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (false) and clientAuth (false)
[junit4] 2> 21793 T77 oas.SolrTestCaseJ4.initCore ####initCore
[junit4] 2> 21794 T77 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4] 2> 21799 T77 oas.SolrTestCaseJ4.setUp ###Starting testOverseerFailure
[junit4] 2> 21804 T77 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 21807 T78 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 21906 T77 oasc.ZkTestServer.run start zk server on port:38571
[junit4] 2> 21943 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 21979 T86 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a691f30f name:ZooKeeperConnection Watcher:127.0.0.1:38571 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 21980 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 21995 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 21996 T79 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1480275d35d0000, 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:853)
[junit4] 2>
[junit4] 2> 22000 T88 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ab1b8383 name:ZooKeeperConnection Watcher:127.0.0.1:38571 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 22000 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 22002 T77 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 22013 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 22017 T90 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66795981 name:ZooKeeperConnection Watcher:127.0.0.1:38571/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 22017 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 22018 T77 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 22024 T77 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 22029 T77 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 22032 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 22045 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 22047 T92 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5dd3fb51 name:ZooKeeperConnection Watcher:127.0.0.1:38571/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 22048 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 22050 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 22054 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 22062 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 22064 T96 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@eae1c738 name:ZooKeeperConnection Watcher:127.0.0.1:38571/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 22065 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 22065 T77 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 22068 T77 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 22072 T77 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 22075 T77 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 22082 T77 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:38571_solr
[junit4] 2> 22083 T77 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 22087 T77 oasc.Overseer.start Overseer (id=92326497441611780-127.0.0.1:38571_solr-n_0000000000) starting
[junit4] 2> 22095 T77 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 22102 T77 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 22108 T77 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 22113 T77 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 22119 T77 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 22137 T77 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 22148 T77 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 22151 T98 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 22156 T97 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 23156 T100 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 23166 T97 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> 23167 T97 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 23174 T97 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 23192 T94 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> 23192 T93 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> 23658 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 23679 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 23690 T100 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 23706 T100 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 23706 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 23709 T97 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> 23710 T97 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 23819 T93 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> 23821 T94 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> 24161 T98 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:853)
[junit4] 2>
[junit4] 2> 24161 T98 oasc.OverseerCollectionProcessor.amILeader According to ZK I (id=92326497441611780-127.0.0.1:38571_solr-n_0000000000) am no longer a leader.
[junit4] 2> 24885 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 24907 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 24910 T102 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e83fc5d name:ZooKeeperConnection Watcher:127.0.0.1:38571/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 24911 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 24912 T77 oasc.Overseer.close Overseer (id=92326497441611780-127.0.0.1:38571_solr-n_0000000000) closing
[junit4] 2> 24914 T97 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:38571_solr
[junit4] 2> 24914 T77 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 24916 T103 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> 24918 T77 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 24925 T77 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:38571_solr
[junit4] 2> 24926 T77 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 24931 T77 oasc.Overseer.start Overseer (id=92326497441611781-127.0.0.1:38571_solr-n_0000000001) starting
[junit4] 2> 24955 T77 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 24956 T105 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 24959 T104 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 24967 T104 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> 24968 T104 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 24975 T107 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 24977 T93 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> 24977 T94 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> 25033 T107 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 25034 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 25047 T77 oasc.LeaderElector.checkIfIamLeader WARN Failed setting watch org.apache.zookeeper.KeeperException$NoNodeException: KeeperErrorCode = NoNode for /collections/collection1/leader_elect/shard1/election/92326497441611779-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:94)
[junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
[junit4] 2> at java.lang.reflect.Method.invoke(Method.java:619)
[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:853)
[junit4] 2>
[junit4] 2> 25051 T93 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 25053 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 25054 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 25053 T104 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:853)
[junit4] 2>
[junit4] 2> 25062 T107 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 25065 T104 oasc.Overseer$ClusterStateUpdater.setShardLeader ERROR Could not mark shard leader for non existing collection:collection1
[junit4] 2> 25170 T94 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> 25171 T93 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> 26061 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 26062 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 27075 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 27078 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 28081 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 28084 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 29087 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 29089 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 30095 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 30096 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 31100 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 31101 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 32106 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 32106 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 33119 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 33120 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 34129 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 34130 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 35139 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 35139 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 36148 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 36149 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 37158 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 37158 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 38167 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 38168 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 39178 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 39179 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 40187 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 40188 T108 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 40197 T108 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[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> 40203 T77 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:38571 38571
[junit4] 2> 40911 T78 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:38571 38571
[junit4] 2> 40913 T77 oas.SolrTestCaseJ4.tearDown ###Ending testOverseerFailure
[junit4] 2> 40914 T77 oasc.Overseer.close Overseer (id=92326497441611781-127.0.0.1:38571_solr-n_0000000001) closing
[junit4] 2> 40915 T104 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:38571_solr
[junit4] 2> 40917 T109 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=FF1D7A7A3E09F4D2 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=pa_IN -Dtests.timezone=Brazil/East -Dtests.file.encoding=UTF-8
[junit4] ERROR 19.2s 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([FF1D7A7A3E09F4D2:FB15F5892CAC1BF3]: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:853)
[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> 40984 T77 oas.SolrTestCaseJ4.setUp ###Starting testShardLeaderChange
[junit4] 2> 40984 T77 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 40986 T110 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 41085 T77 oasc.ZkTestServer.run start zk server on port:57827
[junit4] 2> 41087 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41091 T116 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@91bbb17e name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41092 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41094 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41098 T118 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ee86e5a name:ZooKeeperConnection Watcher:127.0.0.1:57827 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41098 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41101 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41103 T120 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59f2d330 name:ZooKeeperConnection Watcher:127.0.0.1:57827 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41103 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41104 T77 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 41107 T77 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 41111 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41111 T121 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41113 T124 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49f5179f name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41114 T121 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41114 T125 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a665673e name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41115 T121 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 41115 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41116 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 41117 T77 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 41119 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 41120 T77 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 41122 T121 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 41124 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 41125 T121 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:57827_solr
[junit4] 2> 41125 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 41128 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 41128 T121 oasc.Overseer.start Overseer (id=92326498696364035-127.0.0.1:57827_solr-n_0000000000) starting
[junit4] 2> 41131 T121 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 41133 T77 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 41136 T121 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 41140 T121 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 41144 T121 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 41149 T121 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 41154 T121 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 41161 T121 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 41162 T128 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 41162 T121 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 41165 T121 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41167 T131 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@de4d5e38 name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41167 T121 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41168 T121 oasc.Overseer.close Overseer (id=92326498696364035-127.0.0.1:57827_solr-n_0000000000) closing
[junit4] 2> 41168 T128 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:853)
[junit4] 2>
[junit4] 2> 41168 T121 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 41171 T121 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 41174 T121 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:57827_solr
[junit4] 2> 41174 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 41177 T121 oasc.Overseer.start Overseer (id=92326498696364037-127.0.0.1:57827_solr-n_0000000001) starting
[junit4] 2> 41189 T121 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 41190 T133 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 41191 T132 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 41195 T132 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> 41195 T132 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1]
[junit4] 2> 41196 T132 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 41200 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 41201 T126 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> 41637 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 41661 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 41674 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 41678 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 41693 T132 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> 41694 T132 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 41698 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 41699 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 41700 T137 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@338d9373 name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 41701 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 41702 T126 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> 41703 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 41707 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 41712 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 41712 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 41717 T132 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> 41718 T132 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 41725 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 41727 T132 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> 41728 T132 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4] 2> 41728 T132 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 41837 T126 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> 41837 T138 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> 42226 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 42247 T139 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2>
[junit4] 2> 42250 T138 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 42260 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 42371 T138 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> 43747 T126 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2>
[junit4] 2> 43754 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 43757 T141 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33cc764d name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 43758 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 43761 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 43768 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 43778 T135 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 43778 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 43784 T132 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> 43785 T132 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 43793 T121 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 43795 T143 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 43796 T121 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 43798 T145 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a3743855 name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 43798 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 43798 T121 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 43800 T121 oasc.Overseer.close Overseer (id=92326498696364037-127.0.0.1:57827_solr-n_0000000001) closing
[junit4] 2> 43800 T132 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:57827_solr
[junit4] 2> 43800 T121 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 43801 T146 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> 43802 T121 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 43805 T121 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:57827_solr
[junit4] 2> 43806 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 43808 T121 oasc.Overseer.start Overseer (id=92326498696364040-127.0.0.1:57827_solr-n_0000000002) starting
[junit4] 2> 43808 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 43810 T148 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@819bb5d1 name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 43810 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 43812 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 43815 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 43819 T121 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 43820 T151 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 43820 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 43823 T149 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 43824 T149 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> 43825 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 43827 T150 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> 43827 T143 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> 43829 T149 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 43833 T149 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> 43833 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 43836 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 43841 T149 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> 43842 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 43844 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 43846 T143 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> 43846 T150 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> 44036 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 44036 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 44041 T149 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> 44042 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 44050 T142 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2>
[junit4] 2> 44052 T154 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 44057 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 44164 T154 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> 45550 T143 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2>
[junit4] 2> 45557 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 45560 T156 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@199aadbf name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 45561 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 45565 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 45572 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node1
[junit4] 2> 45582 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 45582 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 45588 T149 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> 45589 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45609 T158 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 45610 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 45610 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 45612 T149 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> 45613 T149 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45620 T77 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 45621 T153 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 45622 T160 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78f5d24e name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 45623 T77 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 45623 T121 oasc.OverseerTest$OverseerRestarter.run Killing overseer.
[junit4] 2> 45624 T158 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> 45625 T77 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 45626 T121 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 45629 T162 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8b397e9b name:ZooKeeperConnection Watcher:127.0.0.1:57827/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 45629 T121 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 45630 T121 oasc.Overseer.close Overseer (id=92326498696364040-127.0.0.1:57827_solr-n_0000000002) closing
[junit4] 2> 45630 T121 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: retry=false
[junit4] 2> 45630 T149 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:57827_solr
[junit4] 2> 45630 T77 oascc.SolrZkClient.makePath makePath: /live_nodes/node2
[junit4] 2> 45631 T163 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> 45632 T121 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 45637 T121 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:57827_solr
[junit4] 2> 45637 T121 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 45639 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 45641 T121 oasc.Overseer.start Overseer (id=92326498696364044-127.0.0.1:57827_solr-n_0000000003) starting
[junit4] 2> 45650 T77 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 45652 T121 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 45652 T166 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 45656 T165 oasc.Overseer$ClusterStateUpdater.run Replaying operations from work queue.
[junit4] 2> 45657 T165 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> 45658 T165 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45659 T164 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> 45660 T168 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 45663 T165 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> 45663 T165 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45664 T164 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> 45668 T164 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> 45670 T165 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 45673 T165 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> 45674 T165 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45677 T169 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 45678 T165 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> 45678 T165 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4] 2> 45684 T169 oasc.DistributedQueue$LatchChildWatcher.process LatchChildWatcher fired on path: /overseer/queue state: SyncConnected type NodeChildrenChanged
[junit4] 2> 45686 T164 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> 47158 T158 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:482)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:273)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2>
[junit4] 2> 47158 T157 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
[...truncated too long message...]
0;path=./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001/tempDir-001/jetty4/index.20140823145719403;done=false>>]
[junit4] 2> 1128484 T2817 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001/tempDir-001/jetty4/index.20140823145719403
[junit4] 2> 1128484 T2817 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001/tempDir-001/jetty4 [CachedDir<<refCount=0;path=./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001/tempDir-001/jetty4;done=false>>]
[junit4] 2> 1128485 T2817 oasc.CachingDirectoryFactory.close Closing directory: ./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001/tempDir-001/jetty4
[junit4] 2> 1128485 T2817 oasup.DocExpirationUpdateProcessorFactory$2.postClose Triggering hard shutdown of DocExpiration Executor
[junit4] 2> 1128486 T2939 C1243 P47391 oasup.LogUpdateProcessor.finish [collection1] {} 0 2452
[junit4] 2> 1128486 T2939 C1243 P47391 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run ERROR Runtime error in periodic deletion of expired docs: Exception finding leader for shard shard2 org.apache.solr.common.SolrException: Exception finding leader for shard shard2
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doDeleteByQuery(DistributedUpdateProcessor.java:1301)
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.processDelete(DistributedUpdateProcessor.java:1167)
[junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.processDelete(LogUpdateProcessorFactory.java:121)
[junit4] 2> at org.apache.solr.update.processor.UpdateRequestProcessor.processDelete(UpdateRequestProcessor.java:55)
[junit4] 2> at org.apache.solr.update.processor.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run(DocExpirationUpdateProcessorFactory.java:407)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:482)
[junit4] 2> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:315)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:193)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:308)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[junit4] 2> at java.lang.Thread.run(Thread.java:853)
[junit4] 2> Caused by: java.lang.InterruptedException
[junit4] 2> at java.lang.Thread.sleep(Native Method)
[junit4] 2> at java.lang.Thread.sleep(Thread.java:977)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:566)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:551)
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doDeleteByQuery(DistributedUpdateProcessor.java:1299)
[junit4] 2> ... 11 more
[junit4] 2>
[junit4] 2> 1128487 T2817 oasc.Overseer.close Overseer (id=92326554662076429-127.0.0.1:47391_t_mv-n_0000000004) closing
[junit4] 2> 1128488 T3049 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:47391_t_mv
[junit4] 2> 1129988 T3052 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> 1129988 T3041 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4] 2> 1130010 T2817 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/t_mv,null}
[junit4] 2> 1135001 T2817 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4] 2> 1135002 T2817 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:37363 37363
[junit4] 2> 1135687 T2818 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:37363 37363
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=DistribDocExpirationUpdateProcessorTest -Dtests.method=testDistribSearch -Dtests.seed=FF1D7A7A3E09F4D2 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_BH -Dtests.timezone=Europe/Simferopol -Dtests.file.encoding=UTF-8
[junit4] FAILURE 241s J1 | DistribDocExpirationUpdateProcessorTest.testDistribSearch <<<
[junit4] > Throwable #1: java.lang.AssertionError: Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet expected:<0> but was:<1>
[junit4] > at __randomizedtesting.SeedInfo.seed([FF1D7A7A3E09F4D2:7EFBF462495694EE]:0)
[junit4] > at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.waitForNoResults(DistribDocExpirationUpdateProcessorTest.java:189)
[junit4] > at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.doTest(DistribDocExpirationUpdateProcessorTest.java:95)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:871)
[junit4] > at java.lang.Thread.run(Thread.java:853)
[junit4] 2> 1135700 T2817 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solr.cloud.DistribDocExpirationUpdateProcessorTest-FF1D7A7A3E09F4D2-001
[junit4] 2> NOTE: test params are: codec=Lucene49, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=ar_BH, timezone=Europe/Simferopol
[junit4] 2> NOTE: Linux 3.13.0-34-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=1,free=125404200,total=230359040
[junit4] 2> NOTE: All tests run in this JVM: [UUIDFieldTest, TestManagedResource, TestDistribDocBasedVersion, SolrInfoMBeanTest, TestDefaultSearchFieldResource, TestRequestStatusCollectionAPI, CopyFieldTest, TestNRTOpen, TestZkChroot, DirectUpdateHandlerOptimizeTest, NumericFieldsTest, SynonymTokenizerTest, DistributedQueryComponentCustomSortTest, ConvertedLegacyTest, HdfsCollectionsAPIDistributedZkTest, QueryParsingTest, TestRestManager, AsyncMigrateRouteKeyTest, TestIndexingPerformance, TestHighFrequencyDictionaryFactory, TestReloadAndDeleteDocs, OutputWriterTest, TestSearcherReuse, CollectionsAPIDistributedZkTest, SystemInfoHandlerTest, DocValuesTest, AddBlockUpdateTest, TestSystemIdResolver, TestFieldSortValues, TestShortCircuitedRequests, TestSolrXml, TestCollationField, AssignTest, TestRealTimeGet, SearchHandlerTest, DistributedExpandComponentTest, ChaosMonkeySafeLeaderTest, HdfsChaosMonkeySafeLeaderTest, SolrPluginUtilsTest, UniqFieldsUpdateProcessorFactoryTest, DistributedFacetPivotLargeTest, TestLFUCache, LeaderElectionIntegrationTest, BlockCacheTest, TestFieldTypeCollectionResource, DefaultValueUpdateProcessorTest, TestFileDictionaryLookup, TestMiniSolrCloudCluster, TestRecovery, SimplePostToolTest, DistributedDebugComponentTest, TestUpdate, TestAtomicUpdateErrorCases, BinaryUpdateRequestHandlerTest, TestReversedWildcardFilterFactory, SolrXmlInZkTest, TestFieldResource, ScriptEngineTest, TestPhraseSuggestions, DistribDocExpirationUpdateProcessorTest]
[junit4] Completed on J1 in 241.26s, 1 test, 1 failure <<< FAILURES!
[...truncated 888 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:485: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:478: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:48: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/extra-targets.xml:37: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:189: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:494: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1343: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:958: There were test failures: 419 suites, 1733 tests, 1 error, 1 failure, 47 ignored (18 assumptions)
Total time: 108 minutes 46 seconds
Build step 'Invoke Ant' marked build as failure
[description-setter] Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any