lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b79) - Build # 4695 - Still Failing!
Date Sat, 16 Mar 2013 03:46:24 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4695/
Java: 64bit/jdk1.8.0-ea-b79 -XX:+UseParallelGC

2 tests failed.
REGRESSION:  org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch

Error Message:
Server at http://127.0.0.1:58568/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update

Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:58568/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([CB869D0308989883:4A60131B7FC7F8BF]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:487)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)


REGRESSION:  org.apache.solr.cloud.UnloadDistributedZkTest.testDistribSearch

Error Message:
Still found shard

Stack Trace:
java.lang.AssertionError: Still found shard
	at __randomizedtesting.SeedInfo.seed([CB869D0308989883:4A60131B7FC7F8BF]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:124)
	at org.apache.solr.cloud.UnloadDistributedZkTest.doTest(UnloadDistributedZkTest.java:77)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:487)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)




Build Log:
[...truncated 9376 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T2315 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 4 T2315 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694
[junit4:junit4]   2> 5 T2315 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 5 T2316 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 6 T2316 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 6 T2316 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 6 T2316 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 7 T2316 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 7 T2316 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 105 T2315 oasc.ZkTestServer.run start zk server on port:59000
[junit4:junit4]   2> 106 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@32a748de
[junit4:junit4]   2> 107 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 107 T2321 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 107 T2321 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 107 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50358
[junit4:junit4]   2> 108 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50358
[junit4:junit4]   2> 108 T2319 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 164 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90000 with negotiated timeout 10000 for client /127.0.0.1:50358
[junit4:junit4]   2> 164 T2321 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90000, negotiated timeout = 10000
[junit4:junit4]   2> 166 T2322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32a748de name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 166 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 166 T2315 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 170 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90000
[junit4:junit4]   2> 171 T2322 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 171 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90000 closed
[junit4:junit4]   2> 171 T2317 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d714816e90000, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 171 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3c60b0fa
[junit4:junit4]   2> 173 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50358 which had sessionid 0x13d714816e90000
[junit4:junit4]   2> 173 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 173 T2323 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 174 T2323 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 174 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50359
[junit4:junit4]   2> 174 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50359
[junit4:junit4]   2> 175 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90001 with negotiated timeout 10000 for client /127.0.0.1:50359
[junit4:junit4]   2> 175 T2323 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90001, negotiated timeout = 10000
[junit4:junit4]   2> 175 T2324 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c60b0fa name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 176 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 177 T2315 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 180 T2315 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 182 T2315 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 185 T2315 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 188 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 189 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 192 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 193 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 197 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 197 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 200 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 201 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 203 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 204 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 209 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 209 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 213 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 214 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 217 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 217 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 219 T2315 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 220 T2315 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 221 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90001
[junit4:junit4]   2> 222 T2324 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 222 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50359 which had sessionid 0x13d714816e90001
[junit4:junit4]   2> 222 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90001 closed
[junit4:junit4]   2> 282 T2315 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 309 T2315 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40863
[junit4:junit4]   2> 310 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 311 T2315 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 311 T2315 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911
[junit4:junit4]   2> 312 T2315 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/solr.xml
[junit4:junit4]   2> 312 T2315 oasc.CoreContainer.<init> New CoreContainer 526381798
[junit4:junit4]   2> 312 T2315 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/'
[junit4:junit4]   2> 313 T2315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/'
[junit4:junit4]   2> 331 T2315 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 331 T2315 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 332 T2315 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 332 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 332 T2315 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 333 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 333 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 333 T2315 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 333 T2315 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 334 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 340 T2315 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 350 T2315 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59000/solr
[junit4:junit4]   2> 350 T2315 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 351 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5a660a7a
[junit4:junit4]   2> 351 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 352 T2334 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 352 T2334 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 353 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50360
[junit4:junit4]   2> 353 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50360
[junit4:junit4]   2> 354 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90002 with negotiated timeout 20000 for client /127.0.0.1:50360
[junit4:junit4]   2> 354 T2334 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90002, negotiated timeout = 20000
[junit4:junit4]   2> 354 T2335 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a660a7a name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 354 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 355 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90002
[junit4:junit4]   2> 356 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50360 which had sessionid 0x13d714816e90002
[junit4:junit4]   2> 356 T2335 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 356 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90002 closed
[junit4:junit4]   2> 357 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 360 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@25a3f3fc
[junit4:junit4]   2> 360 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 360 T2336 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 361 T2336 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 361 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50361
[junit4:junit4]   2> 361 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50361
[junit4:junit4]   2> 362 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90003 with negotiated timeout 20000 for client /127.0.0.1:50361
[junit4:junit4]   2> 362 T2336 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90003, negotiated timeout = 20000
[junit4:junit4]   2> 362 T2337 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25a3f3fc name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 363 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 364 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 365 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 367 T2315 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40863_
[junit4:junit4]   2> 368 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40863_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40863_
[junit4:junit4]   2> 368 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40863_
[junit4:junit4]   2> 370 T2315 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 374 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 375 T2315 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 377 T2315 oasc.Overseer.start Overseer (id=89352122053230595-127.0.0.1:40863_-n_0000000000) starting
[junit4:junit4]   2> 378 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 379 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 380 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 380 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 381 T2339 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 381 T2315 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 384 T2315 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 385 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 387 T2338 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 389 T2340 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/collection1
[junit4:junit4]   2> 389 T2340 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 390 T2340 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 390 T2340 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 391 T2340 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/collection1/'
[junit4:junit4]   2> 391 T2340 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/collection1/lib/README' to classloader
[junit4:junit4]   2> 391 T2340 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 414 T2340 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 439 T2340 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 440 T2340 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 455 T2340 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 732 T2340 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 737 T2340 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 739 T2340 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 751 T2340 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 754 T2340 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 757 T2340 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 758 T2340 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 758 T2340 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 758 T2340 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 759 T2340 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 759 T2340 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 760 T2340 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 760 T2340 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363405182911/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/
[junit4:junit4]   2> 760 T2340 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 760 T2340 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 761 T2340 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data forceNew: false
[junit4:junit4]   2> 761 T2340 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/index/
[junit4:junit4]   2> 761 T2340 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 762 T2340 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/index forceNew: false
[junit4:junit4]   2> 763 T2340 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2c4a24a0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c4d2d24),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 763 T2340 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 765 T2340 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 765 T2340 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 766 T2340 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 766 T2340 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 767 T2340 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 767 T2340 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 767 T2340 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 768 T2340 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 768 T2340 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 772 T2340 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 775 T2340 oass.SolrIndexSearcher.<init> Opening Searcher@9ae2837 main
[junit4:junit4]   2> 776 T2340 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/tlog
[junit4:junit4]   2> 776 T2340 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 777 T2340 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 780 T2341 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9ae2837 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 781 T2340 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 782 T2340 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 782 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x55 zxid:0x2a txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 1890 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1890 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40863",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40863_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 1890 T2338 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1891 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1891 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x5d zxid:0x2d txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 1894 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 2785 T2340 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2785 T2340 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40863 collection:control_collection shard:shard1
[junit4:junit4]   2> 2786 T2340 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2791 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:delete cxid:0x77 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2792 T2340 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2792 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x78 zxid:0x38 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2794 T2340 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2794 T2340 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2794 T2340 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40863/collection1/
[junit4:junit4]   2> 2794 T2340 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2795 T2340 oasc.SyncStrategy.syncToMe http://127.0.0.1:40863/collection1/ has no replicas
[junit4:junit4]   2> 2795 T2340 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40863/collection1/
[junit4:junit4]   2> 2795 T2340 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2797 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90003 type:create cxid:0x82 zxid:0x3c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3397 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3403 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 3451 T2340 oasc.ZkController.register We are http://127.0.0.1:40863/collection1/ and leader is http://127.0.0.1:40863/collection1/
[junit4:junit4]   2> 3451 T2340 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40863
[junit4:junit4]   2> 3452 T2340 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3452 T2340 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3452 T2340 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3453 T2340 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3454 T2315 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3455 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3455 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3458 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3459 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@4e900f6c
[junit4:junit4]   2> 3460 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3460 T2343 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3460 T2343 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 3461 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50362
[junit4:junit4]   2> 3461 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50362
[junit4:junit4]   2> 3462 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90004 with negotiated timeout 10000 for client /127.0.0.1:50362
[junit4:junit4]   2> 3462 T2343 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90004, negotiated timeout = 10000
[junit4:junit4]   2> 3462 T2344 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e900f6c name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3463 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3464 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3466 T2315 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3537 T2315 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3539 T2315 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36321
[junit4:junit4]   2> 3541 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3541 T2315 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3541 T2315 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156
[junit4:junit4]   2> 3542 T2315 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/solr.xml
[junit4:junit4]   2> 3542 T2315 oasc.CoreContainer.<init> New CoreContainer 889916949
[junit4:junit4]   2> 3542 T2315 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/'
[junit4:junit4]   2> 3543 T2315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/'
[junit4:junit4]   2> 3559 T2315 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3560 T2315 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3560 T2315 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3560 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3561 T2315 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3561 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3561 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3561 T2315 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3562 T2315 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3562 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3567 T2315 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3575 T2315 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59000/solr
[junit4:junit4]   2> 3576 T2315 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3576 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1bbe0326
[junit4:junit4]   2> 3577 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3577 T2354 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3578 T2354 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 3578 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50363
[junit4:junit4]   2> 3578 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50363
[junit4:junit4]   2> 3579 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90005 with negotiated timeout 20000 for client /127.0.0.1:50363
[junit4:junit4]   2> 3579 T2354 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90005, negotiated timeout = 20000
[junit4:junit4]   2> 3579 T2355 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bbe0326 name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3579 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3581 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90005
[junit4:junit4]   2> 3581 T2355 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3581 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50363 which had sessionid 0x13d714816e90005
[junit4:junit4]   2> 3581 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90005 closed
[junit4:junit4]   2> 3581 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3584 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7a2b2399
[junit4:junit4]   2> 3585 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3585 T2356 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3585 T2356 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 3586 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50364
[junit4:junit4]   2> 3586 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50364
[junit4:junit4]   2> 3587 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90006 with negotiated timeout 20000 for client /127.0.0.1:50364
[junit4:junit4]   2> 3587 T2356 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90006, negotiated timeout = 20000
[junit4:junit4]   2> 3587 T2357 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a2b2399 name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3587 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3588 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0x1 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3589 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0x2 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3590 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4593 T2315 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36321_
[junit4:junit4]   2> 4593 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:delete cxid:0xb zxid:0x4c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:36321_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:36321_
[junit4:junit4]   2> 4594 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36321_
[junit4:junit4]   2> 4596 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 4598 T2344 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4598 T2357 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4598 T2337 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4602 T2358 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/collection1
[junit4:junit4]   2> 4602 T2358 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4603 T2358 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4603 T2358 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4604 T2358 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/collection1/'
[junit4:junit4]   2> 4604 T2358 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/collection1/lib/README' to classloader
[junit4:junit4]   2> 4605 T2358 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4633 T2358 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 4663 T2358 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4664 T2358 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4668 T2358 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4907 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4907 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40863",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40863_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40863__collection1"}
[junit4:junit4]   2> 4914 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 4914 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 4914 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 4972 T2358 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4976 T2358 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4978 T2358 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 4989 T2358 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4992 T2358 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4995 T2358 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4997 T2358 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 4997 T2358 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 4997 T2358 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5000 T2358 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5001 T2358 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5001 T2358 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5001 T2358 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1/
[junit4:junit4]   2> 5001 T2358 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 5002 T2358 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5002 T2358 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1 forceNew: false
[junit4:junit4]   2> 5002 T2358 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1/index/
[junit4:junit4]   2> 5003 T2358 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5003 T2358 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1/index forceNew: false
[junit4:junit4]   2> 5004 T2358 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@26879331 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64671506),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5005 T2358 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5007 T2358 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5007 T2358 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5007 T2358 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5008 T2358 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5008 T2358 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5008 T2358 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5009 T2358 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5009 T2358 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5009 T2358 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5012 T2358 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5014 T2358 oass.SolrIndexSearcher.<init> Opening Searcher@4df0bc90 main
[junit4:junit4]   2> 5014 T2358 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty1/tlog
[junit4:junit4]   2> 5014 T2358 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5015 T2358 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5023 T2359 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4df0bc90 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5025 T2358 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5025 T2358 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6417 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6418 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36321",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36321_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 6418 T2338 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6418 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 6424 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 6424 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 6425 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 7026 T2358 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7027 T2358 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36321 collection:collection1 shard:shard2
[junit4:junit4]   2> 7028 T2358 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 7033 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:delete cxid:0x48 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7033 T2358 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7034 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0x49 zxid:0x5d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7036 T2358 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7036 T2358 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7036 T2358 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36321/collection1/
[junit4:junit4]   2> 7037 T2358 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7037 T2358 oasc.SyncStrategy.syncToMe http://127.0.0.1:36321/collection1/ has no replicas
[junit4:junit4]   2> 7037 T2358 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36321/collection1/
[junit4:junit4]   2> 7037 T2358 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 7040 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0x53 zxid:0x61 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7929 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7936 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 7936 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 7936 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 7943 T2358 oasc.ZkController.register We are http://127.0.0.1:36321/collection1/ and leader is http://127.0.0.1:36321/collection1/
[junit4:junit4]   2> 7943 T2358 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36321
[junit4:junit4]   2> 7943 T2358 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 7943 T2358 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 7944 T2358 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7945 T2358 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7946 T2315 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 7947 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 7947 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8009 T2315 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8011 T2315 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58568
[junit4:junit4]   2> 8013 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8013 T2315 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8013 T2315 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639
[junit4:junit4]   2> 8014 T2315 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/solr.xml
[junit4:junit4]   2> 8014 T2315 oasc.CoreContainer.<init> New CoreContainer 493917609
[junit4:junit4]   2> 8015 T2315 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/'
[junit4:junit4]   2> 8015 T2315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/'
[junit4:junit4]   2> 8033 T2315 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8034 T2315 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8034 T2315 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8034 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8035 T2315 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8035 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8035 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8035 T2315 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8036 T2315 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8036 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8042 T2315 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8051 T2315 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59000/solr
[junit4:junit4]   2> 8051 T2315 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8051 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@79df7d8b
[junit4:junit4]   2> 8052 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8062 T2370 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8063 T2370 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 8063 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50365
[junit4:junit4]   2> 8063 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50365
[junit4:junit4]   2> 8064 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90007 with negotiated timeout 20000 for client /127.0.0.1:50365
[junit4:junit4]   2> 8064 T2370 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90007, negotiated timeout = 20000
[junit4:junit4]   2> 8065 T2371 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79df7d8b name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8065 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8066 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90007
[junit4:junit4]   2> 8066 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50365 which had sessionid 0x13d714816e90007
[junit4:junit4]   2> 8067 T2371 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8067 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90007 closed
[junit4:junit4]   2> 8067 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8069 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@70e2e4bf
[junit4:junit4]   2> 8070 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8071 T2372 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8072 T2372 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 8072 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50366
[junit4:junit4]   2> 8072 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50366
[junit4:junit4]   2> 8074 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90008 with negotiated timeout 20000 for client /127.0.0.1:50366
[junit4:junit4]   2> 8074 T2372 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90008, negotiated timeout = 20000
[junit4:junit4]   2> 8074 T2373 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70e2e4bf name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8075 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8076 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:create cxid:0x1 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8077 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:create cxid:0x2 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8079 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9081 T2315 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58568_
[junit4:junit4]   2> 9082 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:delete cxid:0xb zxid:0x70 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:58568_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:58568_
[junit4:junit4]   2> 9082 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58568_
[junit4:junit4]   2> 9084 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 9085 T2337 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9085 T2357 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9085 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9085 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9085 T2373 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9086 T2344 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9091 T2374 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/collection1
[junit4:junit4]   2> 9091 T2374 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9092 T2374 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9092 T2374 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9093 T2374 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/collection1/'
[junit4:junit4]   2> 9093 T2374 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/collection1/lib/README' to classloader
[junit4:junit4]   2> 9093 T2374 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9120 T2374 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 9152 T2374 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9154 T2374 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9159 T2374 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9440 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9441 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36321",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36321_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36321__collection1"}
[junit4:junit4]   2> 9444 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9444 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9444 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9444 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 9455 T2374 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9462 T2374 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9465 T2374 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9487 T2374 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9490 T2374 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9494 T2374 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9495 T2374 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9495 T2374 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9495 T2374 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9496 T2374 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9496 T2374 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9497 T2374 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9497 T2374 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363405190639/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2/
[junit4:junit4]   2> 9497 T2374 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 9498 T2374 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9498 T2374 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2 forceNew: false
[junit4:junit4]   2> 9498 T2374 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2/index/
[junit4:junit4]   2> 9498 T2374 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9499 T2374 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2/index forceNew: false
[junit4:junit4]   2> 9500 T2374 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@52829a4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@61ae1356),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9500 T2374 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9502 T2374 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9502 T2374 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9503 T2374 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9503 T2374 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9504 T2374 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9504 T2374 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9504 T2374 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9505 T2374 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9505 T2374 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9508 T2374 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9511 T2374 oass.SolrIndexSearcher.<init> Opening Searcher@36c0d1ad main
[junit4:junit4]   2> 9511 T2374 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty2/tlog
[junit4:junit4]   2> 9512 T2374 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9512 T2374 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9516 T2375 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36c0d1ad main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9517 T2374 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9517 T2374 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10949 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10950 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58568",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58568_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 10950 T2338 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 10950 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 10954 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 10954 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 10954 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 10954 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 11519 T2374 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11519 T2374 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58568 collection:collection1 shard:shard1
[junit4:junit4]   2> 11520 T2374 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 11526 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:delete cxid:0x47 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 11527 T2374 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11527 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:create cxid:0x48 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11529 T2374 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11529 T2374 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11529 T2374 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58568/collection1/
[junit4:junit4]   2> 11529 T2374 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11529 T2374 oasc.SyncStrategy.syncToMe http://127.0.0.1:58568/collection1/ has no replicas
[junit4:junit4]   2> 11529 T2374 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58568/collection1/
[junit4:junit4]   2> 11530 T2374 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 11533 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90008 type:create cxid:0x51 zxid:0x83 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12458 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12463 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12464 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12464 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12464 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12487 T2374 oasc.ZkController.register We are http://127.0.0.1:58568/collection1/ and leader is http://127.0.0.1:58568/collection1/
[junit4:junit4]   2> 12487 T2374 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58568
[junit4:junit4]   2> 12487 T2374 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12487 T2374 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12487 T2374 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12489 T2374 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12491 T2315 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12491 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12491 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12544 T2315 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12547 T2315 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56590
[junit4:junit4]   2> 12548 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12548 T2315 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12548 T2315 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183
[junit4:junit4]   2> 12549 T2315 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/solr.xml
[junit4:junit4]   2> 12549 T2315 oasc.CoreContainer.<init> New CoreContainer 682433319
[junit4:junit4]   2> 12549 T2315 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/'
[junit4:junit4]   2> 12550 T2315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/'
[junit4:junit4]   2> 12567 T2315 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12567 T2315 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12567 T2315 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12568 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12568 T2315 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12568 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12569 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12569 T2315 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12569 T2315 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12569 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12575 T2315 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12583 T2315 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59000/solr
[junit4:junit4]   2> 12583 T2315 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12583 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@e7ff890
[junit4:junit4]   2> 12584 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12585 T2386 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12585 T2386 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 12585 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50371
[junit4:junit4]   2> 12586 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50371
[junit4:junit4]   2> 12615 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e90009 with negotiated timeout 20000 for client /127.0.0.1:50371
[junit4:junit4]   2> 12615 T2386 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e90009, negotiated timeout = 20000
[junit4:junit4]   2> 12616 T2387 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e7ff890 name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12616 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12617 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90009
[junit4:junit4]   2> 12618 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50371 which had sessionid 0x13d714816e90009
[junit4:junit4]   2> 12618 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90009 closed
[junit4:junit4]   2> 12618 T2387 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12618 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12621 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@6c5d61ce
[junit4:junit4]   2> 12622 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12623 T2388 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12623 T2388 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 12623 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50372
[junit4:junit4]   2> 12624 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50372
[junit4:junit4]   2> 12625 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e9000a with negotiated timeout 20000 for client /127.0.0.1:50372
[junit4:junit4]   2> 12625 T2388 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e9000a, negotiated timeout = 20000
[junit4:junit4]   2> 12625 T2389 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c5d61ce name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12625 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12626 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000a type:create cxid:0x1 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12627 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000a type:create cxid:0x2 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12628 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13631 T2315 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56590_
[junit4:junit4]   2> 13632 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000a type:delete cxid:0xb zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:56590_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:56590_
[junit4:junit4]   2> 13633 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56590_
[junit4:junit4]   2> 13635 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 13636 T2373 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13636 T2344 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13636 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13636 T2389 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13636 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13636 T2357 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13637 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13637 T2337 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13641 T2390 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/collection1
[junit4:junit4]   2> 13641 T2390 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13642 T2390 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13642 T2390 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13643 T2390 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/collection1/'
[junit4:junit4]   2> 13644 T2390 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/collection1/lib/README' to classloader
[junit4:junit4]   2> 13644 T2390 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13664 T2390 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 13688 T2390 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13689 T2390 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13694 T2390 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 13951 T2390 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 13963 T2390 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 13965 T2390 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 13968 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13969 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58568",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58568_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:58568__collection1"}
[junit4:junit4]   2> 13972 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13972 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13972 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13972 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13972 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 13978 T2390 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 13981 T2390 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 13985 T2390 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 13986 T2390 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 13987 T2390 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 13987 T2390 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 13988 T2390 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 13988 T2390 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 13988 T2390 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 13988 T2390 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363405195183/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/
[junit4:junit4]   2> 13989 T2390 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 13989 T2390 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 13990 T2390 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3 forceNew: false
[junit4:junit4]   2> 13990 T2390 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/index/
[junit4:junit4]   2> 13990 T2390 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 13991 T2390 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/index forceNew: false
[junit4:junit4]   2> 13992 T2390 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@3cd55ea5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18401d27),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 13992 T2390 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 13995 T2390 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 13995 T2390 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 13995 T2390 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 13996 T2390 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 13997 T2390 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 13997 T2390 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 13997 T2390 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 13998 T2390 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 13998 T2390 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14001 T2390 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14003 T2390 oass.SolrIndexSearcher.<init> Opening Searcher@5febd46e main
[junit4:junit4]   2> 14004 T2390 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/tlog
[junit4:junit4]   2> 14004 T2390 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14004 T2390 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14009 T2391 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5febd46e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14011 T2390 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14011 T2390 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15477 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15478 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56590",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56590_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 15478 T2338 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15478 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 15482 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 15483 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 15483 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 15483 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 15483 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 16013 T2390 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16014 T2390 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56590 collection:collection1 shard:shard2
[junit4:junit4]   2> 16017 T2390 oasc.ZkController.register We are http://127.0.0.1:56590/collection1/ and leader is http://127.0.0.1:36321/collection1/
[junit4:junit4]   2> 16017 T2390 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56590
[junit4:junit4]   2> 16017 T2390 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16018 T2390 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C382 name=collection1 org.apache.solr.core.SolrCore@1a508c42 url=http://127.0.0.1:56590/collection1 node=127.0.0.1:56590_ C382_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:56590, state=down, collection=collection1, node_name=127.0.0.1:56590_}
[junit4:junit4]   2> 16018 T2392 C382 P56590 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16018 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16018 T2390 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16018 T2392 C382 P56590 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16019 T2392 C382 P56590 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16020 T2392 C382 P56590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16020 T2315 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16020 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16021 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16075 T2315 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16078 T2315 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40173
[junit4:junit4]   2> 16078 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16079 T2315 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16079 T2315 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713
[junit4:junit4]   2> 16079 T2315 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/solr.xml
[junit4:junit4]   2> 16079 T2315 oasc.CoreContainer.<init> New CoreContainer 692384150
[junit4:junit4]   2> 16080 T2315 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/'
[junit4:junit4]   2> 16080 T2315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/'
[junit4:junit4]   2> 16096 T2315 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16096 T2315 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16097 T2315 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16097 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16097 T2315 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16097 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16098 T2315 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16098 T2315 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16098 T2315 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16099 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16104 T2315 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16112 T2315 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59000/solr
[junit4:junit4]   2> 16112 T2315 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16112 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@36cb362a
[junit4:junit4]   2> 16113 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16113 T2403 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16114 T2403 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 16114 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50377
[junit4:junit4]   2> 16115 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50377
[junit4:junit4]   2> 16115 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e9000b with negotiated timeout 20000 for client /127.0.0.1:50377
[junit4:junit4]   2> 16115 T2403 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e9000b, negotiated timeout = 20000
[junit4:junit4]   2> 16116 T2404 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36cb362a name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16116 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16117 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e9000b
[junit4:junit4]   2> 16118 T2404 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16118 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50377 which had sessionid 0x13d714816e9000b
[junit4:junit4]   2> 16118 T2315 oaz.ZooKeeper.close Session: 0x13d714816e9000b closed
[junit4:junit4]   2> 16118 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16120 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@475a5b7d
[junit4:junit4]   2> 16121 T2405 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16121 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16122 T2405 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 16122 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50378
[junit4:junit4]   2> 16122 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50378
[junit4:junit4]   2> 16123 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e9000c with negotiated timeout 20000 for client /127.0.0.1:50378
[junit4:junit4]   2> 16123 T2405 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e9000c, negotiated timeout = 20000
[junit4:junit4]   2> 16123 T2406 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@475a5b7d name:ZooKeeperConnection Watcher:127.0.0.1:59000/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16123 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16124 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000c type:create cxid:0x1 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16125 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000c type:create cxid:0x2 zxid:0xa4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16126 T2315 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 16986 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16987 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56590",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56590_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:56590__collection1"}
[junit4:junit4]   2> 17003 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17004 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17004 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17004 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17004 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17003 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17025 T2349 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {onlyIfLeader=true&core=collection1&wt=javabin&checkLive=true&coreNodeName=127.0.0.1:56590__collection1&action=PREPRECOVERY&nodeName=127.0.0.1:56590_&version=2&state=recovering} status=0 QTime=1000 
[junit4:junit4]   2> 17129 T2315 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40173_
[junit4:junit4]   2> 17130 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e9000c type:delete cxid:0xd zxid:0xa9 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40173_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40173_
[junit4:junit4]   2> 17130 T2315 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40173_
[junit4:junit4]   2> 17132 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17132 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17132 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17132 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17133 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 17133 T2344 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17133 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 17134 T2357 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17134 T2337 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17135 T2373 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17135 T2389 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17136 T2406 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17140 T2407 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/collection1
[junit4:junit4]   2> 17140 T2407 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17141 T2407 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17141 T2407 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17142 T2407 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/collection1/'
[junit4:junit4]   2> 17142 T2407 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/collection1/lib/README' to classloader
[junit4:junit4]   2> 17143 T2407 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17164 T2407 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 17191 T2407 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17191 T2407 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17197 T2407 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17465 T2407 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 17469 T2407 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 17471 T2407 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 17482 T2407 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17485 T2407 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17487 T2407 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17488 T2407 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17489 T2407 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17489 T2407 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17490 T2407 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17490 T2407 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17490 T2407 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17491 T2407 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363405198713/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/
[junit4:junit4]   2> 17491 T2407 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 17491 T2407 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17492 T2407 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4 forceNew: false
[junit4:junit4]   2> 17492 T2407 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/index/
[junit4:junit4]   2> 17492 T2407 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 17492 T2407 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/index forceNew: false
[junit4:junit4]   2> 17493 T2407 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@22f76f0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7388fe37),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17494 T2407 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17495 T2407 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 17495 T2407 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 17496 T2407 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 17496 T2407 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 17496 T2407 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 17496 T2407 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 17497 T2407 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 17497 T2407 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 17497 T2407 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 17499 T2407 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 17501 T2407 oass.SolrIndexSearcher.<init> Opening Searcher@797c4f6e main
[junit4:junit4]   2> 17501 T2407 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/tlog
[junit4:junit4]   2> 17502 T2407 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 17502 T2407 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 17505 T2408 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@797c4f6e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 17506 T2407 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 17506 T2407 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18510 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18511 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40173",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40173_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 18511 T2338 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18511 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 18515 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18515 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18515 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18515 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18515 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18515 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2>  C382_STATE=coll:collection1 core:collection1 props:{core=collection1, shard=shard2, base_url=http://127.0.0.1:56590, state=recovering, collection=collection1, node_name=127.0.0.1:56590_}
[junit4:junit4]   2> 19026 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:36321/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19027 T2392 C382 P56590 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56590 START replicas=[http://127.0.0.1:36321/collection1/] nUpdates=100
[junit4:junit4]   2> 19027 T2392 C382 P56590 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19028 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19028 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19028 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19028 T2392 C382 P56590 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19029 T2392 C382 P56590 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:36321/collection1/. core=collection1
[junit4:junit4]   2> 19029 T2392 C382 P56590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C383 name=collection1 org.apache.solr.core.SolrCore@39350b89 url=http://127.0.0.1:36321/collection1 node=127.0.0.1:36321_ C383_STATE=coll:collection1 core:collection1 props:{core=collection1, shard=shard2, base_url=http://127.0.0.1:36321, state=active, collection=collection1, node_name=127.0.0.1:36321_, leader=true}
[junit4:junit4]   2> 19031 T2349 C383 P36321 REQ /get {qt=/get&getVersions=100&distrib=false&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 19032 T2351 C383 P36321 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19033 T2351 C383 P36321 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@26879331 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64671506),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19033 T2351 C383 P36321 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19034 T2351 C383 P36321 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@26879331 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64671506),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@26879331 lockFactory=org.apache.lucene.store.NativeFSLockFactory@64671506),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19034 T2351 C383 P36321 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19035 T2351 C383 P36321 oass.SolrIndexSearcher.<init> Opening Searcher@16178751 realtime
[junit4:junit4]   2> 19035 T2351 C383 P36321 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19035 T2351 C383 P36321 /update {waitSearcher=true&commit_end_point=true&wt=javabin&commit=true&version=2&softCommit=false&openSearcher=false} {commit=} 0 3
[junit4:junit4]   2> 19036 T2392 C382 P56590 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19036 T2392 C382 P56590 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19052 T2349 C383 P36321 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19053 T2349 C383 P36321 REQ /replication {qt=/replication&command=indexversion&wt=javabin&version=2} status=0 QTime=16 
[junit4:junit4]   2> 19053 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19053 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19053 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19055 T2353 C383 P36321 REQ /replication {qt=/replication&generation=2&command=filelist&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 19056 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19056 T2392 C382 P56590 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty3/index.20130316034001745 forceNew: false
[junit4:junit4]   2> 19056 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@ab1dd78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6634cc55) fullCopy=false
[junit4:junit4]   2> 19058 T2351 C383 P36321 REQ /replication {qt=/replication&generation=2&command=filecontent&wt=filestream&file=segments_2&checksum=true} status=0 QTime=0 
[junit4:junit4]   2> 19059 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19060 T2392 C382 P56590 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19060 T2392 C382 P56590 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19060 T2392 C382 P56590 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@3cd55ea5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18401d27),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@3cd55ea5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18401d27),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19061 T2392 C382 P56590 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19061 T2392 C382 P56590 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19061 T2392 C382 P56590 oass.SolrIndexSearcher.<init> Opening Searcher@dca2bb6 main
[junit4:junit4]   2> 19062 T2391 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dca2bb6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19062 T2392 C382 P56590 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@ab1dd78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6634cc55)
[junit4:junit4]   2> 19062 T2392 C382 P56590 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19062 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19062 T2392 C382 P56590 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19063 T2392 C382 P56590 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19064 T2392 C382 P56590 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19508 T2407 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19508 T2407 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40173 collection:collection1 shard:shard1
[junit4:junit4]   2> 19511 T2407 oasc.ZkController.register We are http://127.0.0.1:40173/collection1/ and leader is http://127.0.0.1:58568/collection1/
[junit4:junit4]   2> 19512 T2407 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40173
[junit4:junit4]   2> 19512 T2407 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19512 T2407 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C384 name=collection1 org.apache.solr.core.SolrCore@75f8ac59 url=http://127.0.0.1:40173/collection1 node=127.0.0.1:40173_ C384_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=http://127.0.0.1:40173, state=down, collection=collection1, node_name=127.0.0.1:40173_}
[junit4:junit4]   2> 19512 T2411 C384 P40173 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19513 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19513 T2407 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19513 T2411 C384 P40173 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19513 T2411 C384 P40173 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19514 T2411 C384 P40173 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19514 T2315 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19514 T2315 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19515 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19518 T2315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19519 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19523 T2353 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/onenodecollectioncore
[junit4:junit4]   2> 19523 T2353 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19524 T2353 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19524 T2353 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19525 T2353 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19526 T2353 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19528 T2353 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19530 T2353 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/onenodecollectioncore/'
[junit4:junit4]   2> 19553 T2353 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 19578 T2353 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19579 T2353 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19583 T2353 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 19851 T2353 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19856 T2353 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19858 T2353 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19869 T2353 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19872 T2353 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19875 T2353 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19876 T2353 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19876 T2353 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19876 T2353 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19878 T2353 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19878 T2353 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19878 T2353 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19878 T2353 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363405186156/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection/
[junit4:junit4]   2> 19879 T2353 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2a8f9682
[junit4:junit4]   2> 19879 T2353 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19880 T2353 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection forceNew: false
[junit4:junit4]   2> 19880 T2353 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection/index/
[junit4:junit4]   2> 19880 T2353 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19881 T2353 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection/index forceNew: false
[junit4:junit4]   2> 19882 T2353 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f289987 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26884a5a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19882 T2353 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19883 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19884 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19884 T2353 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19884 T2353 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19885 T2353 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19885 T2353 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19885 T2353 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19886 T2353 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19886 T2353 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19888 T2353 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19890 T2353 oass.SolrIndexSearcher.<init> Opening Searcher@58c51e08 main
[junit4:junit4]   2> 19890 T2353 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection/tlog
[junit4:junit4]   2> 19891 T2353 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19891 T2353 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19894 T2413 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@58c51e08 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19894 T2353 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20020 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20021 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56590",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56590_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:56590__collection1"}
[junit4:junit4]   2> 20024 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40173",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40173_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40173__collection1"}
[junit4:junit4]   2> 20027 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36321",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36321_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null}
[junit4:junit4]   2> 20028 T2338 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20028 T2338 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20032 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20032 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20032 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20032 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20032 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20032 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20517 T2367 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {onlyIfLeader=true&core=collection1&wt=javabin&checkLive=true&coreNodeName=127.0.0.1:40173__collection1&action=PREPRECOVERY&nodeName=127.0.0.1:40173_&version=2&state=recovering} status=0 QTime=1000 
[junit4:junit4]   2> 20896 T2353 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20896 T2353 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:36321 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20897 T2353 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20905 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:delete cxid:0xa8 zxid:0xc4 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 20906 T2353 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20906 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xa9 zxid:0xc5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20908 T2353 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20909 T2353 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20909 T2353 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:36321/onenodecollectioncore/
[junit4:junit4]   2> 20909 T2353 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20909 T2353 oasc.SyncStrategy.syncToMe http://127.0.0.1:36321/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20910 T2353 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:36321/onenodecollectioncore/
[junit4:junit4]   2> 20910 T2353 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20914 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xb3 zxid:0xc9 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21538 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21545 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21545 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21545 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21545 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21545 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21545 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21567 T2353 oasc.ZkController.register We are http://127.0.0.1:36321/onenodecollectioncore/ and leader is http://127.0.0.1:36321/onenodecollectioncore/
[junit4:junit4]   2> 21567 T2353 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:36321
[junit4:junit4]   2> 21568 T2353 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21568 T2353 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21570 T2353 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21571 T2353 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {roles=none&name=onenodecollectioncore&wt=javabin&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363405182694/onenodecollection&action=CREATE&version=2&numShards=1&collection=onenodecollection} status=0 QTime=2048 
[junit4:junit4]   2> 21571 T2315 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21572 T2315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C384_STATE=coll:collection1 core:collection1 props:{core=collection1, shard=shard1, base_url=http://127.0.0.1:40173, state=recovering, collection=collection1, node_name=127.0.0.1:40173_}
[junit4:junit4]   2> 22518 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58568/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 22518 T2411 C384 P40173 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40173 START replicas=[http://127.0.0.1:58568/collection1/] nUpdates=100
[junit4:junit4]   2> 22519 T2411 C384 P40173 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 22519 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 22519 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 22519 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 22519 T2411 C384 P40173 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 22520 T2411 C384 P40173 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58568/collection1/. core=collection1
[junit4:junit4]   2> 22520 T2411 C384 P40173 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C385 name=collection1 org.apache.solr.core.SolrCore@13e03302 url=http://127.0.0.1:58568/collection1 node=127.0.0.1:58568_ C385_STATE=coll:collection1 core:collection1 props:{core=collection1, shard=shard1, base_url=http://127.0.0.1:58568, state=active, collection=collection1, node_name=127.0.0.1:58568_, leader=true}
[junit4:junit4]   2> 22522 T2367 C385 P58568 REQ /get {qt=/get&getVersions=100&distrib=false&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 22523 T2366 C385 P58568 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 22524 T2366 C385 P58568 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@52829a4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@61ae1356),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 22524 T2366 C385 P58568 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 22525 T2366 C385 P58568 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@52829a4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@61ae1356),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@52829a4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@61ae1356),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22525 T2366 C385 P58568 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22525 T2366 C385 P58568 oass.SolrIndexSearcher.<init> Opening Searcher@546c843c realtime
[junit4:junit4]   2> 22526 T2366 C385 P58568 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 22526 T2366 C385 P58568 /update {waitSearcher=true&commit_end_point=true&wt=javabin&commit=true&version=2&softCommit=false&openSearcher=false} {commit=} 0 3
[junit4:junit4]   2> 22527 T2411 C384 P40173 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22527 T2411 C384 P40173 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 22528 T2367 C385 P58568 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22528 T2367 C385 P58568 REQ /replication {qt=/replication&command=indexversion&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 22529 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 22529 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 22529 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 22531 T2369 C385 P58568 REQ /replication {qt=/replication&generation=2&command=filelist&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 22531 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 22532 T2411 C384 P40173 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/jetty4/index.20130316034005221 forceNew: false
[junit4:junit4]   2> 22532 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cb2d4b lockFactory=org.apache.lucene.store.NativeFSLockFactory@129c3e3e) fullCopy=false
[junit4:junit4]   2> 22534 T2366 C385 P58568 REQ /replication {qt=/replication&generation=2&command=filecontent&wt=filestream&file=segments_2&checksum=true} status=0 QTime=0 
[junit4:junit4]   2> 22535 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 22535 T2411 C384 P40173 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 22535 T2411 C384 P40173 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 22536 T2411 C384 P40173 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@22f76f0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7388fe37),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@22f76f0a lockFactory=org.apache.lucene.store.NativeFSLockFactory@7388fe37),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22536 T2411 C384 P40173 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22536 T2411 C384 P40173 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 22537 T2411 C384 P40173 oass.SolrIndexSearcher.<init> Opening Searcher@392d820d main
[junit4:junit4]   2> 22537 T2408 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@392d820d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 22538 T2411 C384 P40173 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cb2d4b lockFactory=org.apache.lucene.store.NativeFSLockFactory@129c3e3e)
[junit4:junit4]   2> 22538 T2411 C384 P40173 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 22538 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 22538 T2411 C384 P40173 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 22538 T2411 C384 P40173 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 22539 T2411 C384 P40173 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 22574 T2315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23050 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23051 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36321",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:36321_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:36321__onenodecollectioncore"}
[junit4:junit4]   2> 23055 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40173",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40173_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40173__collection1"}
[junit4:junit4]   2> 23059 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23059 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23059 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23059 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23059 T2344 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23059 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23576 T2315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23577 T2315 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23577 T2315 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23587 T2366 oejs.Response.sendError WARNING Committed before 404 Can not find: /onenodecollectioncore/update
[junit4:junit4]   2> 23587 T2315 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59000 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@68c742ed
[junit4:junit4]   2> 23587 T2366 oejs.ServletHandler.doHandle WARNING /onenodecollectioncore/update java.lang.IllegalStateException: Committed
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Response.resetBuffer(Response.java:1136)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Response.sendError(Response.java:314)
[junit4:junit4]   2> 	at org.apache.solr.client.solrj.embedded.JettySolrRunner$Servlet404.service(JettySolrRunner.java:465)
[junit4:junit4]   2> 	at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:669)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1336)
[junit4:junit4]   2> 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:379)
[junit4:junit4]   2> 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:141)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4]   2> 	at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:135)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1307)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:453)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.GzipHandler.handle(GzipHandler.java:275)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1074)
[junit4:junit4]   2> 	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:382)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1006)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.Server.handle(Server.java:365)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:485)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:937)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:998)
[junit4:junit4]   2> 	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:948)
[junit4:junit4]   2> 	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:240)
[junit4:junit4]   2> 	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
[junit4:junit4]   2> 	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628)
[junit4:junit4]   2> 	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
[junit4:junit4]   2> 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4]   2> 	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 23588 T2315 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23588 T2416 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:59000. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23589 T2416 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:59000, initiating session
[junit4:junit4]   2> 23589 T2317 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:50401
[junit4:junit4]   2> 23589 T2317 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:50401
[junit4:junit4]   2> 23590 T2319 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d714816e9000d with negotiated timeout 10000 for client /127.0.0.1:50401
[junit4:junit4]   2> 23590 T2416 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:59000, sessionid = 0x13d714816e9000d, negotiated timeout = 10000
[junit4:junit4]   2> 23590 T2417 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68c742ed name:ZooKeeperConnection Watcher:127.0.0.1:59000 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23590 T2315 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 23627 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e9000d
[junit4:junit4]   2> 23627 T2417 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23628 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50401 which had sessionid 0x13d714816e9000d
[junit4:junit4]   2> 23627 T2315 oaz.ZooKeeper.close Session: 0x13d714816e9000d closed
[junit4:junit4]   2> 23628 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90004
[junit4:junit4]   2> 23629 T2344 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23629 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50362 which had sessionid 0x13d714816e90004
[junit4:junit4]   2> 23628 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90004 closed
[junit4:junit4]   2> 23631 T2315 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40863
[junit4:junit4]   2> 23632 T2315 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=526381798
[junit4:junit4]   2> 24564 T2338 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24565 T2338 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40863",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40863_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40863__collection1"}
[junit4:junit4]   2> 24569 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24569 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24569 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24569 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24569 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 25634 T2315 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25634 T2315 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25638 T2315 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@45868682
[junit4:junit4]   2> 25641 T2315 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 25641 T2315 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25642 T2315 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25642 T2315 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25643 T2315 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25643 T2315 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data
[junit4:junit4]   2> 25643 T2315 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data
[junit4:junit4]   2> 25644 T2315 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/index
[junit4:junit4]   2> 25644 T2315 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363405182694/control/data/index
[junit4:junit4]   2> 25645 T2338 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89352122053230595-127.0.0.1:40863_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25646 T2320 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d714816e90003
[junit4:junit4]   2> 25647 T2317 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:50361 which had sessionid 0x13d714816e90003
[junit4:junit4]   2> 25647 T2315 oaz.ZooKeeper.close Session: 0x13d714816e90003 closed
[junit4:junit4]   2> 25648 T2406 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25648 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:delete cxid:0xc0 zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25648 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25648 T2389 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25648 T2373 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25648 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25649 T2357 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25649 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25650 T2357 oasc.Overseer.start Overseer (id=89352122053230598-127.0.0.1:36321_-n_0000000001) starting
[junit4:junit4]   2> 25651 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xc5 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25651 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xc6 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25652 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xc7 zxid:0xe9 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25653 T2320 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d714816e90006 type:create cxid:0xc8 zxid:0xea txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25653 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 25653 T2419 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25654 T2357 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25655 T2418 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25656 T2418 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25657 T2418 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40863",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40863_",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:40863__collection1"}
[junit4:junit4]   2> 25660 T2406 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25660 T2357 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25660 T2373 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25660 T2389 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4]   2> 25670 T2315 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 25722 T2315 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 36321
[junit4:junit4]   2> 25722 T2315 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=889916949
[junit4:junit4]   2> 26947 T2337 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26948 T2337 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 26948 T2337 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26948 T2337 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27164 T2418 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27165 T2418 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:36321",
[juni

[...truncated too long message...]

/election/89352124191539212-127.0.0.1:44660_s_ky%2Fj-n_0000000004 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89352124191539210-127.0.0.1:40465_s_ky%2Fj-n_0000000003 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89352124191539206-127.0.0.1:55429_s_ky%2Fj-n_0000000001 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89352124191539203-127.0.0.1:43525_s_ky%2Fj-n_0000000000 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89352124191539208-127.0.0.1:56850_s_ky%2Fj-n_0000000002 (0)
[junit4:junit4]   1>    /solr/overseer_elect/leader (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"id":"89352124191539203-127.0.0.1:43525_s_ky%2Fj-n_0000000000"}
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=UnloadDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=CB869D0308989883 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sk -Dtests.timezone=Africa/Timbuktu -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE  138s J1 | UnloadDistributedZkTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: Still found shard
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([CB869D0308989883:4A60131B7FC7F8BF]:0)
[junit4:junit4]    > 	at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4]    > 	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:124)
[junit4:junit4]    > 	at org.apache.solr.cloud.UnloadDistributedZkTest.doTest(UnloadDistributedZkTest.java:77)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]    > 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    > 	at java.lang.reflect.Method.invoke(Method.java:487)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 138043 T2428 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 138051 T2427 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 138686 T2431 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=sk, timezone=Africa/Timbuktu
[junit4:junit4]   2> NOTE: Linux 3.2.0-38-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=1,free=207487632,total=394264576
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestRandomFaceting, TestCollationKeyRangeQueries, NotRequiredUniqueKeyTest, TestFoldingMultitermQuery, TestFieldResource, TestRecovery, FileUtilsTest, FieldAnalysisRequestHandlerTest, TestSolrJ, UpdateParamsTest, TestSolr4Spatial, DocValuesMultiTest, TestQuerySenderNoQuery, TestMergePolicyConfig, TestBinaryResponseWriter, XmlUpdateRequestHandlerTest, CollectionsAPIDistributedZkTest, StatsComponentTest, XsltUpdateRequestHandlerTest, DirectUpdateHandlerTest, DistanceFunctionTest, TestOmitPositions, TestStressLucene, TestAnalyzedSuggestions, TestIndexingPerformance, DefaultValueUpdateProcessorTest, TestLMJelinekMercerSimilarityFactory, TestJmxIntegration, CopyFieldTest, OpenCloseCoreStressTest, TestFiltering, ShardRoutingCustomTest, TimeZoneUtilsTest, RequiredFieldsTest, CoreContainerCoreInitFailuresTest, StandardRequestHandlerTest, TestSuggestSpellingConverter, TestElisionMultitermQuery, TestCSVLoader, TestBM25SimilarityFactory, TestZkChroot, DOMUtilTest, ChaosMonkeySafeLeaderTest, SuggesterTSTTest, DirectSolrSpellCheckerTest, SpellCheckCollatorTest, URLClassifyProcessorTest, TestArbitraryIndexDir, TestSolrXMLSerializer, TestQueryTypes, TestRTGBase, DebugComponentTest, TestRangeQuery, SimplePostToolTest, TermVectorComponentDistributedTest, HardAutoCommitTest, SpellCheckComponentTest, ZkSolrClientTest, TestMultiCoreConfBootstrap, TestPartialUpdateDeduplication, SolrCoreCheckLockOnStartupTest, OpenExchangeRatesOrgProviderTest, TestJmxMonitoredMap, TestShardHandlerFactory, TestFastOutputStream, TestPropInject, BasicDistributedZk2Test, UnloadDistributedZkTest]
[junit4:junit4] Completed on J1 in 138.83s, 1 test, 1 failure <<< FAILURES!

[...truncated 410 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:361: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1213: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:877: There were test failures: 273 suites, 1147 tests, 1 error, 1 failure, 13 ignored (7 assumptions)

Total time: 93 minutes 45 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.8.0-ea-b79 -XX:+UseParallelGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message