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-trunk-Linux (32bit/jdk1.8.0-ea-b82) - Build # 4831 - Still Failing!
Date Sat, 23 Mar 2013 03:34:24 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4831/
Java: 32bit/jdk1.8.0-ea-b82 -server -XX:+UseConcMarkSweepGC

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

Error Message:
Server at http://127.0.0.1:48188/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:48188/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([2FDCDF125753E8D4:AE3A510A200C88E8]: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:197)
	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)


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

Error Message:
Still found shard2 in collection test_unload_shard_and_collection

Stack Trace:
java.lang.AssertionError: Still found shard2 in collection test_unload_shard_and_collection
	at __randomizedtesting.SeedInfo.seed([2FDCDF125753E8D4:AE3A510A200C88E8]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:127)
	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 9216 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T1496 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 7 T1496 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470
[junit4:junit4]   2> 8 T1496 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 8 T1497 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 9 T1497 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 9 T1497 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 9 T1497 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 9 T1497 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 10 T1497 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 108 T1496 oasc.ZkTestServer.run start zk server on port:35965
[junit4:junit4]   2> 109 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f50c95
[junit4:junit4]   2> 110 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 110 T1502 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 111 T1502 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 111 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58540
[junit4:junit4]   2> 111 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58540
[junit4:junit4]   2> 111 T1500 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 213 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110000 with negotiated timeout 10000 for client /127.0.0.1:58540
[junit4:junit4]   2> 213 T1502 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110000, negotiated timeout = 10000
[junit4:junit4]   2> 214 T1503 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f50c95 name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 214 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 215 T1496 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 220 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110000
[junit4:junit4]   2> 221 T1503 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 222 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58540 which had sessionid 0x13d954740110000
[junit4:junit4]   2> 221 T1496 oaz.ZooKeeper.close Session: 0x13d954740110000 closed
[junit4:junit4]   2> 223 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@132e71b
[junit4:junit4]   2> 224 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 225 T1504 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 225 T1504 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 225 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58541
[junit4:junit4]   2> 225 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58541
[junit4:junit4]   2> 226 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110001 with negotiated timeout 10000 for client /127.0.0.1:58541
[junit4:junit4]   2> 226 T1504 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110001, negotiated timeout = 10000
[junit4:junit4]   2> 226 T1505 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@132e71b name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 226 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 227 T1496 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 229 T1496 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 231 T1496 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 233 T1496 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 235 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 235 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 238 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 239 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 241 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 242 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 243 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 244 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 246 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 246 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 248 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 248 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 251 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 251 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 253 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 253 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 255 T1496 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 256 T1496 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 258 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110001
[junit4:junit4]   2> 258 T1505 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 258 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58541 which had sessionid 0x13d954740110001
[junit4:junit4]   2> 258 T1496 oaz.ZooKeeper.close Session: 0x13d954740110001 closed
[junit4:junit4]   2> 316 T1496 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 322 T1496 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58585
[junit4:junit4]   2> 322 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 323 T1496 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 323 T1496 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722
[junit4:junit4]   2> 323 T1496 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/solr.xml
[junit4:junit4]   2> 324 T1496 oasc.CoreContainer.<init> New CoreContainer 864347
[junit4:junit4]   2> 324 T1496 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/'
[junit4:junit4]   2> 324 T1496 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/'
[junit4:junit4]   2> 340 T1496 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 340 T1496 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 340 T1496 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 341 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 341 T1496 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 341 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 342 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 342 T1496 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 342 T1496 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 343 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 348 T1496 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 361 T1496 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35965/solr
[junit4:junit4]   2> 361 T1496 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 362 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@82d980
[junit4:junit4]   2> 362 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 362 T1515 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 363 T1515 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 363 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58542
[junit4:junit4]   2> 363 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58542
[junit4:junit4]   2> 364 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110002 with negotiated timeout 20000 for client /127.0.0.1:58542
[junit4:junit4]   2> 364 T1515 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110002, negotiated timeout = 20000
[junit4:junit4]   2> 365 T1516 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@82d980 name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 365 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 366 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110002
[junit4:junit4]   2> 366 T1516 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 366 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58542 which had sessionid 0x13d954740110002
[junit4:junit4]   2> 366 T1496 oaz.ZooKeeper.close Session: 0x13d954740110002 closed
[junit4:junit4]   2> 367 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 369 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@14d9198
[junit4:junit4]   2> 370 T1517 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 370 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 370 T1517 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 370 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58543
[junit4:junit4]   2> 371 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58543
[junit4:junit4]   2> 371 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110003 with negotiated timeout 20000 for client /127.0.0.1:58543
[junit4:junit4]   2> 371 T1517 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110003, negotiated timeout = 20000
[junit4:junit4]   2> 372 T1518 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14d9198 name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 372 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 373 T1496 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 375 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 376 T1496 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 378 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 379 T1496 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58585_
[junit4:junit4]   2> 379 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:58585_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:58585_
[junit4:junit4]   2> 380 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58585_
[junit4:junit4]   2> 382 T1496 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 385 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 386 T1496 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 387 T1496 oasc.Overseer.start Overseer (id=89391700867350531-127.0.0.1:58585_-n_0000000000) starting
[junit4:junit4]   2> 388 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 388 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 389 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 389 T1496 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 391 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 392 T1520 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 393 T1496 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 394 T1496 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 395 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 397 T1519 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 399 T1521 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/collection1
[junit4:junit4]   2> 399 T1521 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 399 T1521 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 399 T1521 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 400 T1521 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/collection1/'
[junit4:junit4]   2> 400 T1521 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/collection1/lib/README' to classloader
[junit4:junit4]   2> 401 T1521 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 428 T1521 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 459 T1521 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 460 T1521 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 464 T1521 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 789 T1521 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 794 T1521 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 796 T1521 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 810 T1521 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 817 T1521 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 820 T1521 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 821 T1521 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 822 T1521 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 822 T1521 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 824 T1521 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 824 T1521 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 824 T1521 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 825 T1521 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1364009107722/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/
[junit4:junit4]   2> 825 T1521 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 825 T1521 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 826 T1521 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data
[junit4:junit4]   2> 827 T1521 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/index/
[junit4:junit4]   2> 827 T1521 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 827 T1521 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/index
[junit4:junit4]   2> 830 T1521 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@190885 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c55846),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 830 T1521 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 833 T1521 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 833 T1521 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 834 T1521 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 835 T1521 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 835 T1521 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 835 T1521 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 836 T1521 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 837 T1521 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 837 T1521 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 841 T1521 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 845 T1521 oass.SolrIndexSearcher.<init> Opening Searcher@1b750a3 main
[junit4:junit4]   2> 845 T1521 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/tlog
[junit4:junit4]   2> 845 T1521 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 845 T1521 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 849 T1522 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b750a3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 851 T1521 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 851 T1521 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1901 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1902 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58585",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58585_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 1902 T1519 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1902 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1908 T1518 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> 2853 T1521 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2853 T1521 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58585 collection:control_collection shard:shard1
[junit4:junit4]   2> 2854 T1521 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2865 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2866 T1521 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2866 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2868 T1521 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2868 T1521 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2868 T1521 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58585/collection1/
[junit4:junit4]   2> 2868 T1521 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2869 T1521 oasc.SyncStrategy.syncToMe http://127.0.0.1:58585/collection1/ has no replicas
[junit4:junit4]   2> 2869 T1521 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58585/collection1/
[junit4:junit4]   2> 2869 T1521 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2872 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3414 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3426 T1518 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> 3475 T1521 oasc.ZkController.register We are http://127.0.0.1:58585/collection1/ and leader is http://127.0.0.1:58585/collection1/
[junit4:junit4]   2> 3476 T1521 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58585
[junit4:junit4]   2> 3476 T1521 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3476 T1521 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3476 T1521 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3479 T1521 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3480 T1496 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3481 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3482 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3488 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3490 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5d1b1a
[junit4:junit4]   2> 3491 T1524 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3491 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3492 T1524 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 3492 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58544
[junit4:junit4]   2> 3492 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58544
[junit4:junit4]   2> 3493 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110004 with negotiated timeout 10000 for client /127.0.0.1:58544
[junit4:junit4]   2> 3493 T1524 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110004, negotiated timeout = 10000
[junit4:junit4]   2> 3494 T1525 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5d1b1a name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3494 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3496 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3499 T1496 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3571 T1496 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3573 T1496 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37026
[junit4:junit4]   2> 3574 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3574 T1496 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3575 T1496 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962
[junit4:junit4]   2> 3575 T1496 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/solr.xml
[junit4:junit4]   2> 3575 T1496 oasc.CoreContainer.<init> New CoreContainer 29880608
[junit4:junit4]   2> 3576 T1496 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/'
[junit4:junit4]   2> 3576 T1496 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/'
[junit4:junit4]   2> 3593 T1496 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3593 T1496 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3593 T1496 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3594 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3594 T1496 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3595 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3595 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3595 T1496 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3596 T1496 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3596 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3606 T1496 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3615 T1496 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35965/solr
[junit4:junit4]   2> 3616 T1496 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3616 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d9483c
[junit4:junit4]   2> 3617 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3617 T1535 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3618 T1535 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 3618 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58545
[junit4:junit4]   2> 3618 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58545
[junit4:junit4]   2> 3619 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110005 with negotiated timeout 20000 for client /127.0.0.1:58545
[junit4:junit4]   2> 3619 T1535 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110005, negotiated timeout = 20000
[junit4:junit4]   2> 3619 T1536 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d9483c name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3619 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3620 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110005
[junit4:junit4]   2> 3621 T1536 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3621 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58545 which had sessionid 0x13d954740110005
[junit4:junit4]   2> 3621 T1496 oaz.ZooKeeper.close Session: 0x13d954740110005 closed
[junit4:junit4]   2> 3621 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3624 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@168e3c6
[junit4:junit4]   2> 3624 T1537 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3624 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3625 T1537 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 3625 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58546
[junit4:junit4]   2> 3625 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58546
[junit4:junit4]   2> 3625 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110006 with negotiated timeout 20000 for client /127.0.0.1:58546
[junit4:junit4]   2> 3625 T1537 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110006, negotiated timeout = 20000
[junit4:junit4]   2> 3626 T1538 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@168e3c6 name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3626 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3627 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3627 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3629 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4631 T1496 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37026_
[junit4:junit4]   2> 4632 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37026_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37026_
[junit4:junit4]   2> 4633 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37026_
[junit4:junit4]   2> 4635 T1518 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> 4636 T1525 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4636 T1538 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4637 T1518 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4640 T1539 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/collection1
[junit4:junit4]   2> 4640 T1539 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4640 T1539 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4641 T1539 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4641 T1539 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/collection1/'
[junit4:junit4]   2> 4642 T1539 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/collection1/lib/README' to classloader
[junit4:junit4]   2> 4642 T1539 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4669 T1539 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4706 T1539 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4707 T1539 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4711 T1539 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4931 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4931 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58585",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58585_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 4935 T1518 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> 4935 T1538 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> 4935 T1525 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> 5041 T1539 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5046 T1539 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5052 T1539 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5062 T1539 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5065 T1539 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5067 T1539 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5068 T1539 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5068 T1539 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5069 T1539 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5069 T1539 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5069 T1539 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5070 T1539 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5070 T1539 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/
[junit4:junit4]   2> 5070 T1539 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 5071 T1539 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5071 T1539 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1
[junit4:junit4]   2> 5072 T1539 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/index/
[junit4:junit4]   2> 5072 T1539 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5072 T1539 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/index
[junit4:junit4]   2> 5074 T1539 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9ccf33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@835541),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5074 T1539 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5076 T1539 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5076 T1539 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5077 T1539 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5077 T1539 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5078 T1539 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5078 T1539 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5078 T1539 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5079 T1539 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5079 T1539 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5083 T1539 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5085 T1539 oass.SolrIndexSearcher.<init> Opening Searcher@15b124d main
[junit4:junit4]   2> 5086 T1539 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/tlog
[junit4:junit4]   2> 5086 T1539 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5086 T1539 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5090 T1540 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15b124d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5091 T1539 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5091 T1539 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6438 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6439 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 6439 T1519 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6439 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6444 T1538 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> 6444 T1518 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> 6444 T1525 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> 7093 T1539 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7093 T1539 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37026 collection:collection1 shard:shard1
[junit4:junit4]   2> 7094 T1539 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7102 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7103 T1539 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7104 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7106 T1539 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7106 T1539 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7106 T1539 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37026/collection1/
[junit4:junit4]   2> 7106 T1539 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7107 T1539 oasc.SyncStrategy.syncToMe http://127.0.0.1:37026/collection1/ has no replicas
[junit4:junit4]   2> 7107 T1539 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37026/collection1/
[junit4:junit4]   2> 7107 T1539 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7110 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7947 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7954 T1525 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> 7955 T1538 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> 7955 T1518 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> 7963 T1539 oasc.ZkController.register We are http://127.0.0.1:37026/collection1/ and leader is http://127.0.0.1:37026/collection1/
[junit4:junit4]   2> 7964 T1539 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37026
[junit4:junit4]   2> 7964 T1539 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 7964 T1539 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 7964 T1539 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7965 T1539 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7966 T1496 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 7967 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 7967 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8026 T1496 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8028 T1496 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48188
[junit4:junit4]   2> 8028 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8029 T1496 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8029 T1496 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433
[junit4:junit4]   2> 8029 T1496 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/solr.xml
[junit4:junit4]   2> 8029 T1496 oasc.CoreContainer.<init> New CoreContainer 31150284
[junit4:junit4]   2> 8030 T1496 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/'
[junit4:junit4]   2> 8030 T1496 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/'
[junit4:junit4]   2> 8051 T1496 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8051 T1496 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8052 T1496 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8052 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8052 T1496 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8053 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8053 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8053 T1496 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8053 T1496 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8054 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8059 T1496 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8068 T1496 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35965/solr
[junit4:junit4]   2> 8068 T1496 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8068 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@82e44a
[junit4:junit4]   2> 8069 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8069 T1551 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8070 T1551 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 8070 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58547
[junit4:junit4]   2> 8071 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58547
[junit4:junit4]   2> 8071 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110007 with negotiated timeout 20000 for client /127.0.0.1:58547
[junit4:junit4]   2> 8071 T1551 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110007, negotiated timeout = 20000
[junit4:junit4]   2> 8072 T1552 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@82e44a name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8072 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8073 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110007
[junit4:junit4]   2> 8073 T1552 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8074 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58547 which had sessionid 0x13d954740110007
[junit4:junit4]   2> 8073 T1496 oaz.ZooKeeper.close Session: 0x13d954740110007 closed
[junit4:junit4]   2> 8074 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8076 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@daa6ae
[junit4:junit4]   2> 8077 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8077 T1553 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8078 T1553 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 8078 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58548
[junit4:junit4]   2> 8078 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58548
[junit4:junit4]   2> 8079 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110008 with negotiated timeout 20000 for client /127.0.0.1:58548
[junit4:junit4]   2> 8079 T1553 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110008, negotiated timeout = 20000
[junit4:junit4]   2> 8079 T1554 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@daa6ae name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8079 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8080 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8081 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8082 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9084 T1496 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48188_
[junit4:junit4]   2> 9085 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:48188_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:48188_
[junit4:junit4]   2> 9086 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48188_
[junit4:junit4]   2> 9089 T1525 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9089 T1518 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9089 T1554 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9089 T1538 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9089 T1525 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> 9089 T1538 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> 9089 T1518 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> 9094 T1555 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/collection1
[junit4:junit4]   2> 9094 T1555 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9095 T1555 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9095 T1555 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9096 T1555 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/collection1/'
[junit4:junit4]   2> 9096 T1555 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/collection1/lib/README' to classloader
[junit4:junit4]   2> 9096 T1555 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9121 T1555 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9153 T1555 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9154 T1555 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9157 T1555 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9459 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9460 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 9463 T1538 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> 9463 T1518 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> 9463 T1554 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> 9463 T1525 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> 9516 T1555 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9521 T1555 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9523 T1555 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9532 T1555 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9534 T1555 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9537 T1555 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9538 T1555 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9538 T1555 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9538 T1555 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9539 T1555 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9539 T1555 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9539 T1555 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9540 T1555 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1364009115433/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2/
[junit4:junit4]   2> 9540 T1555 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 9540 T1555 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9541 T1555 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2
[junit4:junit4]   2> 9541 T1555 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2/index/
[junit4:junit4]   2> 9541 T1555 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9541 T1555 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2/index
[junit4:junit4]   2> 9542 T1555 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17cf4c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@da79e3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9542 T1555 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9544 T1555 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9544 T1555 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9545 T1555 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9545 T1555 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9545 T1555 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9545 T1555 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9546 T1555 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9546 T1555 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9546 T1555 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9548 T1555 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9550 T1555 oass.SolrIndexSearcher.<init> Opening Searcher@1f5b701 main
[junit4:junit4]   2> 9551 T1555 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty2/tlog
[junit4:junit4]   2> 9551 T1555 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9551 T1555 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9555 T1556 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f5b701 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9556 T1555 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9556 T1555 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10967 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10968 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48188",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48188_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 10968 T1519 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 10968 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 10974 T1538 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> 10974 T1554 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> 10974 T1518 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> 10974 T1525 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> 11558 T1555 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11558 T1555 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48188 collection:collection1 shard:shard2
[junit4:junit4]   2> 11559 T1555 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 11568 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 11569 T1555 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11570 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11572 T1555 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11572 T1555 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11572 T1555 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48188/collection1/
[junit4:junit4]   2> 11572 T1555 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11572 T1555 oasc.SyncStrategy.syncToMe http://127.0.0.1:48188/collection1/ has no replicas
[junit4:junit4]   2> 11572 T1555 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48188/collection1/
[junit4:junit4]   2> 11573 T1555 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 11577 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12479 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12485 T1518 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> 12485 T1525 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> 12485 T1554 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> 12485 T1538 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> 12531 T1555 oasc.ZkController.register We are http://127.0.0.1:48188/collection1/ and leader is http://127.0.0.1:48188/collection1/
[junit4:junit4]   2> 12532 T1555 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48188
[junit4:junit4]   2> 12532 T1555 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12532 T1555 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12533 T1555 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12535 T1555 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12535 T1496 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12536 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12536 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12598 T1496 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12603 T1496 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38011
[junit4:junit4]   2> 12604 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12604 T1496 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12605 T1496 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003
[junit4:junit4]   2> 12605 T1496 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/solr.xml
[junit4:junit4]   2> 12605 T1496 oasc.CoreContainer.<init> New CoreContainer 23500355
[junit4:junit4]   2> 12606 T1496 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/'
[junit4:junit4]   2> 12606 T1496 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/'
[junit4:junit4]   2> 12622 T1496 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12622 T1496 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12622 T1496 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12623 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12623 T1496 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12623 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12623 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12624 T1496 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12624 T1496 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12624 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12630 T1496 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12639 T1496 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35965/solr
[junit4:junit4]   2> 12639 T1496 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12639 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@86146
[junit4:junit4]   2> 12640 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12640 T1567 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12641 T1567 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 12641 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58551
[junit4:junit4]   2> 12641 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58551
[junit4:junit4]   2> 12642 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d954740110009 with negotiated timeout 20000 for client /127.0.0.1:58551
[junit4:junit4]   2> 12642 T1567 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d954740110009, negotiated timeout = 20000
[junit4:junit4]   2> 12642 T1568 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@86146 name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12642 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12643 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110009
[junit4:junit4]   2> 12643 T1568 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12643 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58551 which had sessionid 0x13d954740110009
[junit4:junit4]   2> 12643 T1496 oaz.ZooKeeper.close Session: 0x13d954740110009 closed
[junit4:junit4]   2> 12644 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12646 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@e8f51d
[junit4:junit4]   2> 12647 T1569 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12647 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12647 T1569 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 12647 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58552
[junit4:junit4]   2> 12647 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58552
[junit4:junit4]   2> 12648 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d95474011000a with negotiated timeout 20000 for client /127.0.0.1:58552
[junit4:junit4]   2> 12648 T1569 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d95474011000a, negotiated timeout = 20000
[junit4:junit4]   2> 12648 T1570 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e8f51d name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12648 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12649 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12650 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12653 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13655 T1496 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38011_
[junit4:junit4]   2> 13656 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:38011_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:38011_
[junit4:junit4]   2> 13658 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38011_
[junit4:junit4]   2> 13661 T1518 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> 13662 T1525 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> 13662 T1554 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13662 T1538 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13663 T1554 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> 13662 T1570 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13663 T1538 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> 13664 T1518 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13664 T1525 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13675 T1571 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/collection1
[junit4:junit4]   2> 13675 T1571 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13676 T1571 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13676 T1571 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13677 T1571 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/collection1/'
[junit4:junit4]   2> 13678 T1571 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/collection1/lib/README' to classloader
[junit4:junit4]   2> 13678 T1571 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13714 T1571 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 13746 T1571 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13747 T1571 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13750 T1571 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 13989 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13990 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48188",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48188_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 13993 T1570 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> 13993 T1518 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> 13993 T1538 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> 13993 T1554 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> 13993 T1525 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> 14092 T1571 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14097 T1571 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14099 T1571 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14110 T1571 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14112 T1571 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14115 T1571 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14116 T1571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14116 T1571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14116 T1571 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14117 T1571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14117 T1571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14117 T1571 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14118 T1571 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1364009120003/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/
[junit4:junit4]   2> 14118 T1571 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 14118 T1571 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14119 T1571 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3
[junit4:junit4]   2> 14119 T1571 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/index/
[junit4:junit4]   2> 14119 T1571 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14119 T1571 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/index
[junit4:junit4]   2> 14120 T1571 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@200cb lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b3caef),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14121 T1571 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14122 T1571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14122 T1571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14123 T1571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14123 T1571 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14124 T1571 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14124 T1571 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14124 T1571 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14124 T1571 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14125 T1571 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14127 T1571 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14129 T1571 oass.SolrIndexSearcher.<init> Opening Searcher@10ae732 main
[junit4:junit4]   2> 14129 T1571 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/tlog
[junit4:junit4]   2> 14130 T1571 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14130 T1571 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14135 T1572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10ae732 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14138 T1571 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14138 T1571 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15497 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15497 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38011",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38011_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 15498 T1519 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15498 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 15502 T1525 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> 15502 T1518 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> 15502 T1538 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> 15502 T1554 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> 15502 T1570 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> 16140 T1571 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16140 T1571 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38011 collection:collection1 shard:shard1
[junit4:junit4]   2> 16145 T1571 oasc.ZkController.register We are http://127.0.0.1:38011/collection1/ and leader is http://127.0.0.1:37026/collection1/
[junit4:junit4]   2> 16145 T1571 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38011
[junit4:junit4]   2> 16146 T1571 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16146 T1571 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C109 name=collection1 org.apache.solr.core.SolrCore@9bbfed url=http://127.0.0.1:38011/collection1 node=127.0.0.1:38011_ C109_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:38011, node_name=127.0.0.1:38011_, collection=collection1, core=collection1}
[junit4:junit4]   2> 16146 T1573 C109 P38011 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16147 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16147 T1571 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16148 T1573 C109 P38011 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16148 T1573 C109 P38011 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16149 T1496 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16150 T1573 C109 P38011 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16150 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16151 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16231 T1496 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16234 T1496 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50888
[junit4:junit4]   2> 16235 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16235 T1496 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16235 T1496 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619
[junit4:junit4]   2> 16236 T1496 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/solr.xml
[junit4:junit4]   2> 16236 T1496 oasc.CoreContainer.<init> New CoreContainer 5198727
[junit4:junit4]   2> 16236 T1496 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/'
[junit4:junit4]   2> 16237 T1496 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/'
[junit4:junit4]   2> 16253 T1496 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16253 T1496 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16253 T1496 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16254 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16254 T1496 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16254 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16255 T1496 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16255 T1496 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16255 T1496 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16256 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16262 T1496 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16271 T1496 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:35965/solr
[junit4:junit4]   2> 16271 T1496 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16271 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@d7b94
[junit4:junit4]   2> 16272 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16272 T1584 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16273 T1584 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 16273 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58554
[junit4:junit4]   2> 16273 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58554
[junit4:junit4]   2> 16274 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d95474011000b with negotiated timeout 20000 for client /127.0.0.1:58554
[junit4:junit4]   2> 16274 T1584 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d95474011000b, negotiated timeout = 20000
[junit4:junit4]   2> 16274 T1585 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d7b94 name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16274 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16275 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d95474011000b
[junit4:junit4]   2> 16275 T1585 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16276 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58554 which had sessionid 0x13d95474011000b
[junit4:junit4]   2> 16275 T1496 oaz.ZooKeeper.close Session: 0x13d95474011000b closed
[junit4:junit4]   2> 16276 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16278 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1ab5dd5
[junit4:junit4]   2> 16279 T1586 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16279 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16279 T1586 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 16279 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58555
[junit4:junit4]   2> 16280 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58555
[junit4:junit4]   2> 16280 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d95474011000c with negotiated timeout 20000 for client /127.0.0.1:58555
[junit4:junit4]   2> 16280 T1586 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d95474011000c, negotiated timeout = 20000
[junit4:junit4]   2> 16280 T1587 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ab5dd5 name:ZooKeeperConnection Watcher:127.0.0.1:35965/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16281 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16281 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16282 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16288 T1496 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17008 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17009 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38011",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38011_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 17014 T1570 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> 17014 T1518 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> 17014 T1538 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> 17015 T1587 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> 17015 T1525 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> 17014 T1554 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> 17158 T1531 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {nodeName=127.0.0.1:38011_&wt=javabin&state=recovering&version=2&checkLive=true&coreNodeName=4&onlyIfLeader=true&action=PREPRECOVERY&core=collection1} status=0 QTime=1001 
[junit4:junit4]   2> 17290 T1496 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50888_
[junit4:junit4]   2> 17291 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d95474011000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:50888_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:50888_
[junit4:junit4]   2> 17293 T1496 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50888_
[junit4:junit4]   2> 17295 T1538 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> 17295 T1554 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> 17295 T1587 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> 17295 T1525 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17295 T1518 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17295 T1525 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> 17295 T1570 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17295 T1518 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> 17296 T1570 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> 17297 T1538 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17297 T1554 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17297 T1587 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17301 T1588 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/collection1
[junit4:junit4]   2> 17301 T1588 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17301 T1588 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17302 T1588 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17303 T1588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/collection1/'
[junit4:junit4]   2> 17303 T1588 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/collection1/lib/README' to classloader
[junit4:junit4]   2> 17303 T1588 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17325 T1588 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 17364 T1588 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17365 T1588 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17368 T1588 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17717 T1588 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 17722 T1588 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 17724 T1588 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 17733 T1588 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17736 T1588 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17739 T1588 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17739 T1588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17740 T1588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17740 T1588 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17741 T1588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17741 T1588 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17741 T1588 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17742 T1588 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1364009123619/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/
[junit4:junit4]   2> 17742 T1588 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 17743 T1588 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17743 T1588 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4
[junit4:junit4]   2> 17743 T1588 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/index/
[junit4:junit4]   2> 17744 T1588 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 17744 T1588 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/index
[junit4:junit4]   2> 17746 T1588 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b4f3ce lockFactory=org.apache.lucene.store.NativeFSLockFactory@13467dc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17746 T1588 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17749 T1588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 17750 T1588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 17750 T1588 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 17751 T1588 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 17752 T1588 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 17752 T1588 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 17753 T1588 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 17753 T1588 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 17754 T1588 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 17758 T1588 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 17762 T1588 oass.SolrIndexSearcher.<init> Opening Searcher@15ab582 main
[junit4:junit4]   2> 17762 T1588 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/tlog
[junit4:junit4]   2> 17763 T1588 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 17764 T1588 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 17768 T1589 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15ab582 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 17769 T1588 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 17770 T1588 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18522 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18522 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50888",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50888_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 18522 T1519 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18523 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 18525 T1587 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> 18525 T1518 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> 18526 T1538 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> 18525 T1570 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> 18525 T1525 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> 18525 T1554 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> 18771 T1588 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 18771 T1588 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50888 collection:collection1 shard:shard2
[junit4:junit4]   2> 18773 T1588 oasc.ZkController.register We are http://127.0.0.1:50888/collection1/ and leader is http://127.0.0.1:48188/collection1/
[junit4:junit4]   2> 18773 T1588 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50888
[junit4:junit4]   2> 18773 T1588 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 18773 T1588 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C110 name=collection1 org.apache.solr.core.SolrCore@78e588 url=http://127.0.0.1:50888/collection1 node=127.0.0.1:50888_ C110_STATE=coll:collection1 core:collection1 props:{state=down, base_url=http://127.0.0.1:50888, node_name=127.0.0.1:50888_, collection=collection1, core=collection1}
[junit4:junit4]   2> 18774 T1590 C110 P50888 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 18774 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 18774 T1588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18775 T1590 C110 P50888 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 18775 T1590 C110 P50888 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18785 T1496 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 18786 T1590 C110 P50888 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18785 T1496 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 18786 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18789 T1496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18790 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18793 T1534 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/onenodecollectioncore
[junit4:junit4]   2> 18793 T1534 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 18794 T1534 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 18794 T1534 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 18795 T1534 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 18795 T1534 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 18797 T1534 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 18798 T1534 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/onenodecollectioncore/'
[junit4:junit4]   2> 18825 T1534 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 18867 T1534 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 18868 T1534 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 18871 T1534 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C109_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:38011, node_name=127.0.0.1:38011_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4]   2> 19158 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:37026/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19159 T1573 C109 P38011 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38011 START replicas=[http://127.0.0.1:37026/collection1/] nUpdates=100
[junit4:junit4]   2> 19159 T1573 C109 P38011 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19159 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19160 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19160 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19160 T1573 C109 P38011 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19160 T1573 C109 P38011 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:37026/collection1/. core=collection1
[junit4:junit4]   2> 19160 T1573 C109 P38011 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C111 name=collection1 org.apache.solr.core.SolrCore@53e558 url=http://127.0.0.1:37026/collection1 node=127.0.0.1:37026_ C111_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:37026, node_name=127.0.0.1:37026_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4]   2> 19164 T1533 C111 P37026 REQ /get {qt=/get&wt=javabin&version=2&distrib=false&getVersions=100} status=0 QTime=1 
[junit4:junit4]   2> 19169 T1531 C111 P37026 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19171 T1531 C111 P37026 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9ccf33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@835541),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19172 T1531 C111 P37026 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19173 T1531 C111 P37026 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9ccf33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@835541),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9ccf33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@835541),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19173 T1531 C111 P37026 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19173 T1531 C111 P37026 oass.SolrIndexSearcher.<init> Opening Searcher@49e0bd realtime
[junit4:junit4]   2> 19174 T1531 C111 P37026 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19174 T1531 C111 P37026 /update {softCommit=false&wt=javabin&commit_end_point=true&version=2&openSearcher=false&waitSearcher=true&commit=true} {commit=} 0 5
[junit4:junit4]   2> 19175 T1573 C109 P38011 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19175 T1573 C109 P38011 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19179 T1533 C111 P37026 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19179 T1533 C111 P37026 REQ /replication {qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=3 
[junit4:junit4]   2> 19179 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19180 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19180 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19182 T1531 C111 P37026 REQ /replication {qt=/replication&wt=javabin&version=2&command=filelist&generation=2} status=0 QTime=1 
[junit4:junit4]   2> 19182 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19183 T1573 C109 P38011 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty3/index.20130323142526645
[junit4:junit4]   2> 19183 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@9fb5bf lockFactory=org.apache.lucene.store.NativeFSLockFactory@1297628) fullCopy=false
[junit4:junit4]   2> 19185 T1532 C111 P37026 REQ /replication {qt=/replication&wt=filestream&file=segments_2&checksum=true&command=filecontent&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 19186 T1573 C109 P38011 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19186 T1573 C109 P38011 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19187 T1573 C109 P38011 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19187 T1573 C109 P38011 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@200cb lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b3caef),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@200cb lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b3caef),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19188 T1573 C109 P38011 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19188 T1573 C109 P38011 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19188 T1573 C109 P38011 oass.SolrIndexSearcher.<init> Opening Searcher@f626ee main
[junit4:junit4]   2> 19189 T1572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f626ee main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19190 T1573 C109 P38011 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19190 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19190 T1573 C109 P38011 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19190 T1573 C109 P38011 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19191 T1573 C109 P38011 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19235 T1534 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19241 T1534 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19243 T1534 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19256 T1534 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19259 T1534 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19261 T1534 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19262 T1534 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19262 T1534 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19262 T1534 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19263 T1534 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19263 T1534 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19264 T1534 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19264 T1534 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1364009110962/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/
[junit4:junit4]   2> 19264 T1534 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@62a7d0
[junit4:junit4]   2> 19265 T1534 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19265 T1534 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection
[junit4:junit4]   2> 19266 T1534 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/index/
[junit4:junit4]   2> 19266 T1534 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19266 T1534 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/index
[junit4:junit4]   2> 19268 T1534 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d0cad5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19268 T1534 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19269 T1534 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19270 T1534 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19270 T1534 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19271 T1534 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19271 T1534 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19271 T1534 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19272 T1534 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19272 T1534 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19273 T1534 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19275 T1534 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19277 T1534 oass.SolrIndexSearcher.<init> Opening Searcher@13a139 main
[junit4:junit4]   2> 19277 T1534 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/tlog
[junit4:junit4]   2> 19278 T1534 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19278 T1534 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19281 T1594 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@13a139 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19283 T1534 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20029 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20030 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50888",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50888_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 20033 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38011",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38011_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 20035 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 20035 T1519 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20036 T1519 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20038 T1518 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> 20038 T1587 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> 20038 T1538 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> 20039 T1570 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> 20038 T1525 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> 20038 T1554 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> 20285 T1534 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20285 T1534 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:37026 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20286 T1534 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20294 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:delete cxid:0xac zxid:0xc2 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 20295 T1534 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20295 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20297 T1534 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20297 T1534 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20297 T1534 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37026/onenodecollectioncore/
[junit4:junit4]   2> 20298 T1534 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20298 T1534 oasc.SyncStrategy.syncToMe http://127.0.0.1:37026/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20298 T1534 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37026/onenodecollectioncore/
[junit4:junit4]   2> 20298 T1534 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20301 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20790 T1549 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {nodeName=127.0.0.1:50888_&wt=javabin&state=recovering&version=2&checkLive=true&coreNodeName=5&onlyIfLeader=true&action=PREPRECOVERY&core=collection1} status=0 QTime=2000 
[junit4:junit4]   2> 21545 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21551 T1587 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> 21552 T1518 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> 21552 T1570 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> 21552 T1538 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> 21552 T1525 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> 21552 T1554 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> 21555 T1534 oasc.ZkController.register We are http://127.0.0.1:37026/onenodecollectioncore/ and leader is http://127.0.0.1:37026/onenodecollectioncore/
[junit4:junit4]   2> 21555 T1534 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:37026
[junit4:junit4]   2> 21555 T1534 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21556 T1534 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21557 T1534 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21558 T1534 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {name=onenodecollectioncore&wt=javabin&roles=none&version=2&collection=onenodecollection&numShards=1&action=CREATE&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection} status=0 QTime=2765 
[junit4:junit4]   2> 21559 T1496 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21559 T1496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22561 T1496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C110_STATE=coll:collection1 core:collection1 props:{state=recovering, base_url=http://127.0.0.1:50888, node_name=127.0.0.1:50888_, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4]   2> 22791 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:48188/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 22792 T1590 C110 P50888 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50888 START replicas=[http://127.0.0.1:48188/collection1/] nUpdates=100
[junit4:junit4]   2> 22792 T1590 C110 P50888 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 22792 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 22792 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 22792 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 22793 T1590 C110 P50888 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 22793 T1590 C110 P50888 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:48188/collection1/. core=collection1
[junit4:junit4]   2> 22793 T1590 C110 P50888 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C112 name=collection1 org.apache.solr.core.SolrCore@15e11bd url=http://127.0.0.1:48188/collection1 node=127.0.0.1:48188_ C112_STATE=coll:collection1 core:collection1 props:{state=active, base_url=http://127.0.0.1:48188, node_name=127.0.0.1:48188_, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4]   2> 22796 T1548 C112 P48188 REQ /get {qt=/get&wt=javabin&version=2&distrib=false&getVersions=100} status=0 QTime=0 
[junit4:junit4]   2> 22797 T1547 C112 P48188 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 22798 T1547 C112 P48188 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17cf4c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@da79e3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 22799 T1547 C112 P48188 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 22799 T1547 C112 P48188 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17cf4c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@da79e3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@17cf4c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@da79e3),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22799 T1547 C112 P48188 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22800 T1547 C112 P48188 oass.SolrIndexSearcher.<init> Opening Searcher@d1593 realtime
[junit4:junit4]   2> 22800 T1547 C112 P48188 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 22800 T1547 C112 P48188 /update {softCommit=false&wt=javabin&commit_end_point=true&version=2&openSearcher=false&waitSearcher=true&commit=true} {commit=} 0 3
[junit4:junit4]   2> 22801 T1590 C110 P50888 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22801 T1590 C110 P50888 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 22802 T1549 C112 P48188 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22802 T1549 C112 P48188 REQ /replication {qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0 
[junit4:junit4]   2> 22803 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 22803 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 22803 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 22805 T1548 C112 P48188 REQ /replication {qt=/replication&wt=javabin&version=2&command=filelist&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 22806 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 22806 T1590 C110 P50888 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty4/index.20130323142530269
[junit4:junit4]   2> 22806 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b30ece lockFactory=org.apache.lucene.store.NativeFSLockFactory@16f2628) fullCopy=false
[junit4:junit4]   2> 22808 T1547 C112 P48188 REQ /replication {qt=/replication&wt=filestream&file=segments_2&checksum=true&command=filecontent&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 22809 T1590 C110 P50888 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 22810 T1590 C110 P50888 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 22810 T1590 C110 P50888 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 22811 T1590 C110 P50888 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b4f3ce lockFactory=org.apache.lucene.store.NativeFSLockFactory@13467dc),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b4f3ce lockFactory=org.apache.lucene.store.NativeFSLockFactory@13467dc),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22811 T1590 C110 P50888 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22811 T1590 C110 P50888 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 22812 T1590 C110 P50888 oass.SolrIndexSearcher.<init> Opening Searcher@857a29 main
[junit4:junit4]   2> 22812 T1589 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@857a29 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 22813 T1590 C110 P50888 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 22813 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 22813 T1590 C110 P50888 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 22813 T1590 C110 P50888 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 22814 T1590 C110 P50888 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23056 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23057 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37026__onenodecollectioncore",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 23060 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:50888",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:50888_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 23064 T1525 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> 23064 T1538 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> 23064 T1570 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> 23064 T1518 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> 23064 T1587 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> 23064 T1554 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> 23563 T1496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23564 T1496 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23565 T1496 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23604 T1496 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:35965 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@19db53b
[junit4:junit4]   2> 23605 T1496 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23605 T1597 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:35965. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23606 T1597 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:35965, initiating session
[junit4:junit4]   2> 23606 T1498 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:58565
[junit4:junit4]   2> 23607 T1498 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:58565
[junit4:junit4]   2> 23608 T1500 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d95474011000d with negotiated timeout 10000 for client /127.0.0.1:58565
[junit4:junit4]   2> 23608 T1597 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:35965, sessionid = 0x13d95474011000d, negotiated timeout = 10000
[junit4:junit4]   2> 23608 T1598 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19db53b name:ZooKeeperConnection Watcher:127.0.0.1:35965 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23608 T1496 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23642 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d95474011000d
[junit4:junit4]   2> 23642 T1598 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23642 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58565 which had sessionid 0x13d95474011000d
[junit4:junit4]   2> 23642 T1496 oaz.ZooKeeper.close Session: 0x13d95474011000d closed
[junit4:junit4]   2> 23643 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110004
[junit4:junit4]   2> 23643 T1525 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23643 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58544 which had sessionid 0x13d954740110004
[junit4:junit4]   2> 23643 T1496 oaz.ZooKeeper.close Session: 0x13d954740110004 closed
[junit4:junit4]   2> 23646 T1496 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 58585
[junit4:junit4]   2> 23646 T1496 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=864347
[junit4:junit4]   2> 24573 T1519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24574 T1519 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58585",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58585_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 24577 T1518 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> 24577 T1587 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> 24578 T1538 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> 24577 T1570 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> 24577 T1554 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> 25647 T1496 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25648 T1496 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25650 T1496 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@b71b42
[junit4:junit4]   2> 25653 T1496 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> 25653 T1496 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25654 T1496 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25654 T1496 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25654 T1496 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25655 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data
[junit4:junit4]   2> 25655 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data
[junit4:junit4]   2> 25655 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/index
[junit4:junit4]   2> 25655 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/control/data/index
[junit4:junit4]   2> 25656 T1519 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89391700867350531-127.0.0.1:58585_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25657 T1501 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d954740110003
[junit4:junit4]   2> 25658 T1518 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> 25658 T1570 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> 25658 T1587 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> 25658 T1498 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:58543 which had sessionid 0x13d954740110003
[junit4:junit4]   2> 25658 T1496 oaz.ZooKeeper.close Session: 0x13d954740110003 closed
[junit4:junit4]   2> 25658 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:delete cxid:0xc6 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25658 T1554 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25659 T1554 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> 25659 T1538 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25659 T1587 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25660 T1570 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25661 T1538 oasc.Overseer.start Overseer (id=89391700867350534-127.0.0.1:37026_-n_0000000001) starting
[junit4:junit4]   2> 25661 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xcb zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25662 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xcc zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25663 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xce zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25664 T1501 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d954740110006 type:create cxid:0xd0 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25665 T1600 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25665 T1538 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> 25666 T1538 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25666 T1599 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25668 T1599 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25668 T1599 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58585",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58585_",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 25671 T1587 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> 25671 T1570 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> 25671 T1538 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> 25671 T1554 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> 25679 T1496 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 25731 T1496 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37026
[junit4:junit4]   2> 25731 T1496 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=29880608
[junit4:junit4]   2> 26958 T1518 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26958 T1518 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26959 T1518 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27175 T1599 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27176 T1599 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:37026__onenodecollectioncore",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 27180 T1599 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37026",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37026_",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 27185 T1587 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> 27186 T1570 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> 27186 T1554 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> 27185 T1538 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> 28734 T1496 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 28735 T1496 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 28737 T1496 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 28740 T1496 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@53e558
[junit4:junit4]   2> 28744 T1496 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 28744 T1496 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 28744 T1496 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 28745 T1496 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 28746 T1496 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 28746 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/index
[junit4:junit4]   2> 28747 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1/index
[junit4:junit4]   2> 28747 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1
[junit4:junit4]   2> 28747 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364009107470/jetty1
[junit4:junit4]   2> 28747 T1496 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@62b891
[junit4:junit4]   2> 28752 T1496 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> 28752 T1496 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 28752 T1496 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 28752 T1496 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 28753 T1496 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 28753 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection
[junit4:junit4]   2> 28754 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection
[junit4:junit4]   2> 28754 T1496 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/index
[junit4:junit4]   2> 28754 T1496 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364009107470/onenodecollection/index
[junit4:junit4]   2> 28755 T1599 oasc.Overseer$ClusterStateUpdater.amIL

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


[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=UnloadDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=2FDCDF125753E8D4 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_PY -Dtests.timezone=Africa/Dakar -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE  140s J0 | UnloadDistributedZkTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: Still found shard2 in collection test_unload_shard_and_collection
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([2FDCDF125753E8D4:AE3A510A200C88E8]:0)
[junit4:junit4]    > 	at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4]    > 	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:127)
[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> 139807 T1107 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 139819 T1106 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4]   2> 140385 T1110 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 140915 T1189 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 140915 T1189 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> 140916 T1189 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 140916 T1189 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {a_si=Lucene41(blocksize=128), text=PostingsFormat(name=SimpleText), timestamp=PostingsFormat(name=MockRandom), multiDefault=PostingsFormat(name=MockRandom), intDefault=Lucene41(blocksize=128), a_t=PostingsFormat(name=MockRandom), _version_=Lucene41(blocksize=128), range_facet_sl=PostingsFormat(name=Asserting), other_tl1=Lucene41(blocksize=128), range_facet_l=PostingsFormat(name=MockRandom), id=PostingsFormat(name=Asserting), range_facet_si=PostingsFormat(name=MockRandom)}, docValues:{timestamp=DocValuesFormat(name=CheapBastard)}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=es_PY, timezone=Africa/Dakar
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=30381624,total=115478528
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestDynamicFieldResource, PeerSyncTest, TestShardHandlerFactory, PolyFieldTest, DocValuesTest, ChaosMonkeyNothingIsSafeTest, BadComponentTest, DistributedSpellCheckComponentTest, ClusterStateUpdateTest, RegexBoostProcessorTest, SolrIndexSplitterTest, ResourceLoaderTest, MinimalSchemaTest, TestQuerySenderListener, FileBasedSpellCheckerTest, TestJoin, BasicDistributedZkTest, TestSolrIndexConfig, SuggesterFSTTest, TestFieldResource, DistributedTermsComponentTest, TestFuzzyAnalyzedSuggestions, TestExtendedDismaxParser, TestSolrCoreProperties, SuggesterTest, DirectUpdateHandlerOptimizeTest, CoreAdminHandlerTest, DocumentBuilderTest, TestSweetSpotSimilarityFactory, QueryParsingTest, TestDynamicFieldCollectionResource, UpdateRequestProcessorFactoryTest, DateFieldTest, TestPhraseSuggestions, TermsComponentTest, SearchHandlerTest, TestValueSourceCache, TestRealTimeGet, ShowFileRequestHandlerTest, QueryEqualityTest, TestPseudoReturnFields, SliceStateUpdateTest, SystemInfoHandlerTest, QueryElevationComponentTest, FieldMutatingUpdateProcessorTest, UnloadDistributedZkTest]
[junit4:junit4] Completed on J0 in 141.10s, 1 test, 1 failure <<< FAILURES!

[...truncated 497 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:375: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:355: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1209: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:873: There were test failures: 272 suites, 1146 tests, 1 error, 1 failure, 13 ignored (7 assumptions)

Total time: 40 minutes 16 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.8.0-ea-b82 -server -XX:+UseConcMarkSweepGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message