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 # 4839 - Failure!
Date Sat, 23 Mar 2013 18:59:12 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4839/
Java: 32bit/jdk1.8.0-ea-b82 -server -XX:+UseConcMarkSweepGC

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

Error Message:
Server at http://127.0.0.1:43270/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:43270/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([925378E2E4BEC312:13B5F6FA93E1A32E]: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)




Build Log:
[...truncated 9100 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T708 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 5 T708 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-1364064353960
[junit4:junit4]   2> 6 T708 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 7 T709 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 8 T709 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 8 T709 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 8 T709 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 8 T709 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 13 T709 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-1364064353960/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 107 T708 oasc.ZkTestServer.run start zk server on port:34532
[junit4:junit4]   2> 108 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@979e86
[junit4:junit4]   2> 109 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 109 T714 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 109 T714 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 110 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57228
[junit4:junit4]   2> 110 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57228
[junit4:junit4]   2> 110 T712 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 188 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00000 with negotiated timeout 10000 for client /127.0.0.1:57228
[junit4:junit4]   2> 188 T714 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00000, negotiated timeout = 10000
[junit4:junit4]   2> 189 T715 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@979e86 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 189 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 189 T708 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 193 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00000
[junit4:junit4]   2> 193 T715 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 194 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57228 which had sessionid 0x13d98923eb00000
[junit4:junit4]   2> 193 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00000 closed
[junit4:junit4]   2> 194 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5067a4
[junit4:junit4]   2> 194 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 195 T716 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 195 T716 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 195 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57229
[junit4:junit4]   2> 195 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57229
[junit4:junit4]   2> 196 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00001 with negotiated timeout 10000 for client /127.0.0.1:57229
[junit4:junit4]   2> 196 T716 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00001, negotiated timeout = 10000
[junit4:junit4]   2> 196 T717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5067a4 name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 197 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 197 T708 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 200 T708 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 202 T708 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 204 T708 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 207 T708 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> 208 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 211 T708 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> 212 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 214 T708 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> 214 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 216 T708 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> 217 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 219 T708 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> 220 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 222 T708 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> 223 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 225 T708 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> 226 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 233 T708 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> 234 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 238 T708 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> 239 T708 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 241 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00001
[junit4:junit4]   2> 242 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57229 which had sessionid 0x13d98923eb00001
[junit4:junit4]   2> 242 T717 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 242 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00001 closed
[junit4:junit4]   2> 327 T708 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 343 T708 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53800
[junit4:junit4]   2> 344 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 345 T708 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 345 T708 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-1364064354197
[junit4:junit4]   2> 345 T708 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-1364064354197/solr.xml
[junit4:junit4]   2> 346 T708 oasc.CoreContainer.<init> New CoreContainer 31266721
[junit4:junit4]   2> 347 T708 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-1364064354197/'
[junit4:junit4]   2> 347 T708 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-1364064354197/'
[junit4:junit4]   2> 380 T708 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 380 T708 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 381 T708 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 381 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 382 T708 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 382 T708 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 383 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 383 T708 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 384 T708 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 384 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 394 T708 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 414 T708 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:34532/solr
[junit4:junit4]   2> 415 T708 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 416 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3ad0d2
[junit4:junit4]   2> 417 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 417 T727 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 418 T727 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 418 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57230
[junit4:junit4]   2> 418 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57230
[junit4:junit4]   2> 420 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00002 with negotiated timeout 20000 for client /127.0.0.1:57230
[junit4:junit4]   2> 420 T727 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00002, negotiated timeout = 20000
[junit4:junit4]   2> 420 T728 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ad0d2 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 420 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 421 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00002
[junit4:junit4]   2> 422 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57230 which had sessionid 0x13d98923eb00002
[junit4:junit4]   2> 422 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00002 closed
[junit4:junit4]   2> 422 T728 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 422 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 426 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@14d1ad3
[junit4:junit4]   2> 426 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 427 T729 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 427 T729 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 427 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57231
[junit4:junit4]   2> 428 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57231
[junit4:junit4]   2> 428 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00003 with negotiated timeout 20000 for client /127.0.0.1:57231
[junit4:junit4]   2> 428 T729 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00003, negotiated timeout = 20000
[junit4:junit4]   2> 429 T730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14d1ad3 name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 429 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 430 T708 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 432 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 433 T708 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 436 T708 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 438 T708 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53800_
[junit4:junit4]   2> 438 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:53800_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:53800_
[junit4:junit4]   2> 439 T708 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53800_
[junit4:junit4]   2> 441 T708 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 445 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 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> 446 T708 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 448 T708 oasc.Overseer.start Overseer (id=89395321501646851-127.0.0.1:53800_-n_0000000000) starting
[junit4:junit4]   2> 448 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 449 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 450 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 451 T708 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 453 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 453 T732 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 454 T708 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 456 T708 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 458 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 460 T731 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 463 T733 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-1364064354197/collection1
[junit4:junit4]   2> 463 T733 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 464 T733 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 464 T733 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 465 T733 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-1364064354197/collection1/'
[junit4:junit4]   2> 465 T733 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-1364064354197/collection1/lib/README' to classloader
[junit4:junit4]   2> 465 T733 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-1364064354197/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 494 T733 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 530 T733 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 531 T733 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 536 T733 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 952 T733 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 957 T733 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 959 T733 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 971 T733 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 974 T733 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 977 T733 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 978 T733 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 979 T733 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 979 T733 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 980 T733 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 980 T733 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 981 T733 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 981 T733 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-1364064354197/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/
[junit4:junit4]   2> 981 T733 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 981 T733 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 982 T733 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data
[junit4:junit4]   2> 982 T733 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/index/
[junit4:junit4]   2> 982 T733 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 982 T733 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/index
[junit4:junit4]   2> 983 T733 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c72f03 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d94643),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 984 T733 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 985 T733 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 985 T733 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 985 T733 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 986 T733 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 986 T733 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 986 T733 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 986 T733 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 987 T733 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 987 T733 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 989 T733 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 991 T733 oass.SolrIndexSearcher.<init> Opening Searcher@abfa88 main
[junit4:junit4]   2> 991 T733 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/tlog
[junit4:junit4]   2> 992 T733 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 992 T733 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 995 T734 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@abfa88 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 996 T733 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 996 T733 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1963 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1964 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53800",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53800_"}
[junit4:junit4]   2> 1964 T731 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1964 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1968 T730 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> 1997 T733 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1997 T733 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53800 collection:control_collection shard:shard1
[junit4:junit4]   2> 1998 T733 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2002 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 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> 2003 T733 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2003 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2005 T733 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2005 T733 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2005 T733 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53800/collection1/
[junit4:junit4]   2> 2005 T733 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2005 T733 oasc.SyncStrategy.syncToMe http://127.0.0.1:53800/collection1/ has no replicas
[junit4:junit4]   2> 2006 T733 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53800/collection1/
[junit4:junit4]   2> 2006 T733 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2008 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3471 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3695 T730 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> 3714 T733 oasc.ZkController.register We are http://127.0.0.1:53800/collection1/ and leader is http://127.0.0.1:53800/collection1/
[junit4:junit4]   2> 3715 T733 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53800
[junit4:junit4]   2> 3715 T733 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3715 T733 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3715 T733 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3717 T733 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3718 T708 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3718 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3719 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3722 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3722 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@109c10f
[junit4:junit4]   2> 3723 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3723 T736 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3724 T736 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 3724 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57232
[junit4:junit4]   2> 3724 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57232
[junit4:junit4]   2> 3725 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00004 with negotiated timeout 10000 for client /127.0.0.1:57232
[junit4:junit4]   2> 3725 T736 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00004, negotiated timeout = 10000
[junit4:junit4]   2> 3725 T737 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@109c10f name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3725 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3727 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3729 T708 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3789 T708 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3792 T708 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54151
[junit4:junit4]   2> 3792 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3792 T708 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3793 T708 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-1364064357683
[junit4:junit4]   2> 3793 T708 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-1364064357683/solr.xml
[junit4:junit4]   2> 3794 T708 oasc.CoreContainer.<init> New CoreContainer 12001865
[junit4:junit4]   2> 3794 T708 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-1364064357683/'
[junit4:junit4]   2> 3794 T708 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-1364064357683/'
[junit4:junit4]   2> 3812 T708 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3812 T708 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3812 T708 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3813 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3813 T708 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3813 T708 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3813 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3814 T708 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3814 T708 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3814 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3820 T708 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3829 T708 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:34532/solr
[junit4:junit4]   2> 3830 T708 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3830 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@9b5cae
[junit4:junit4]   2> 3831 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3831 T747 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3832 T747 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 3832 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57233
[junit4:junit4]   2> 3832 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57233
[junit4:junit4]   2> 3833 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00005 with negotiated timeout 20000 for client /127.0.0.1:57233
[junit4:junit4]   2> 3833 T747 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00005, negotiated timeout = 20000
[junit4:junit4]   2> 3833 T748 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9b5cae name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3833 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3835 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00005
[junit4:junit4]   2> 3835 T748 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3835 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57233 which had sessionid 0x13d98923eb00005
[junit4:junit4]   2> 3835 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00005 closed
[junit4:junit4]   2> 3836 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3839 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@78b187
[junit4:junit4]   2> 3840 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3840 T749 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3840 T749 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 3840 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57234
[junit4:junit4]   2> 3841 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57234
[junit4:junit4]   2> 3842 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00006 with negotiated timeout 20000 for client /127.0.0.1:57234
[junit4:junit4]   2> 3842 T749 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00006, negotiated timeout = 20000
[junit4:junit4]   2> 3842 T750 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78b187 name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3842 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3843 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3844 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3846 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4849 T708 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54151_
[junit4:junit4]   2> 4850 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54151_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54151_
[junit4:junit4]   2> 4850 T708 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54151_
[junit4:junit4]   2> 4857 T730 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> 4857 T737 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4859 T750 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4859 T730 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4863 T751 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-1364064357683/collection1
[junit4:junit4]   2> 4863 T751 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4864 T751 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4864 T751 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4865 T751 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-1364064357683/collection1/'
[junit4:junit4]   2> 4865 T751 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-1364064357683/collection1/lib/README' to classloader
[junit4:junit4]   2> 4866 T751 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-1364064357683/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4888 T751 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4920 T751 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4921 T751 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4930 T751 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 5200 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5201 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:53800__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53800",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53800_"}
[junit4:junit4]   2> 5204 T750 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> 5204 T737 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> 5204 T730 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> 5275 T751 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5280 T751 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5282 T751 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5295 T751 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5298 T751 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5301 T751 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5302 T751 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5302 T751 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5302 T751 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5303 T751 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5303 T751 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5304 T751 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5304 T751 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-1364064357683/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/
[junit4:junit4]   2> 5304 T751 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 5304 T751 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5305 T751 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1
[junit4:junit4]   2> 5305 T751 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/index/
[junit4:junit4]   2> 5305 T751 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5305 T751 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/index
[junit4:junit4]   2> 5306 T751 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19abe4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c2d4c2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5307 T751 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5308 T751 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5308 T751 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5309 T751 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5309 T751 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5309 T751 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5310 T751 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5310 T751 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5310 T751 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5310 T751 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5313 T751 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5315 T751 oass.SolrIndexSearcher.<init> Opening Searcher@9480e0 main
[junit4:junit4]   2> 5315 T751 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/tlog
[junit4:junit4]   2> 5316 T751 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5316 T751 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5320 T752 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9480e0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5321 T751 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5322 T751 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6709 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6709 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 6709 T731 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6709 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 6714 T737 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> 6714 T750 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> 6714 T730 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> 7323 T751 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7323 T751 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54151 collection:collection1 shard:shard2
[junit4:junit4]   2> 7324 T751 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 7331 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 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> 7332 T751 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7333 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7334 T751 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7335 T751 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7335 T751 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54151/collection1/
[junit4:junit4]   2> 7335 T751 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7335 T751 oasc.SyncStrategy.syncToMe http://127.0.0.1:54151/collection1/ has no replicas
[junit4:junit4]   2> 7335 T751 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54151/collection1/
[junit4:junit4]   2> 7336 T751 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 7339 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8219 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8238 T730 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> 8238 T737 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> 8238 T750 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> 8243 T751 oasc.ZkController.register We are http://127.0.0.1:54151/collection1/ and leader is http://127.0.0.1:54151/collection1/
[junit4:junit4]   2> 8243 T751 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54151
[junit4:junit4]   2> 8244 T751 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8244 T751 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8244 T751 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8245 T751 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8246 T708 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 8246 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8247 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8311 T708 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8313 T708 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43270
[junit4:junit4]   2> 8313 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8314 T708 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8314 T708 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-1364064362204
[junit4:junit4]   2> 8314 T708 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-1364064362204/solr.xml
[junit4:junit4]   2> 8315 T708 oasc.CoreContainer.<init> New CoreContainer 13155792
[junit4:junit4]   2> 8315 T708 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-1364064362204/'
[junit4:junit4]   2> 8315 T708 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-1364064362204/'
[junit4:junit4]   2> 8332 T708 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8332 T708 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8333 T708 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8333 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8333 T708 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8334 T708 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8334 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8334 T708 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8334 T708 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8335 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8341 T708 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8354 T708 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:34532/solr
[junit4:junit4]   2> 8354 T708 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8355 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@610051
[junit4:junit4]   2> 8355 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8356 T763 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8356 T763 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 8356 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57235
[junit4:junit4]   2> 8357 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57235
[junit4:junit4]   2> 8360 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00007 with negotiated timeout 20000 for client /127.0.0.1:57235
[junit4:junit4]   2> 8360 T763 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00007, negotiated timeout = 20000
[junit4:junit4]   2> 8360 T764 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@610051 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8360 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8362 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00007
[junit4:junit4]   2> 8362 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57235 which had sessionid 0x13d98923eb00007
[junit4:junit4]   2> 8362 T764 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8362 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00007 closed
[junit4:junit4]   2> 8363 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8366 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d0315a
[junit4:junit4]   2> 8366 T765 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8366 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8367 T765 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 8367 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57236
[junit4:junit4]   2> 8367 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57236
[junit4:junit4]   2> 8368 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00008 with negotiated timeout 20000 for client /127.0.0.1:57236
[junit4:junit4]   2> 8368 T765 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00008, negotiated timeout = 20000
[junit4:junit4]   2> 8368 T766 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d0315a name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8368 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8369 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8370 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8372 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9374 T708 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43270_
[junit4:junit4]   2> 9375 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43270_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43270_
[junit4:junit4]   2> 9376 T708 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43270_
[junit4:junit4]   2> 9378 T730 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4]   2> 9379 T750 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9379 T766 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9379 T750 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> 9379 T737 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9379 T737 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> 9381 T730 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9385 T767 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-1364064362204/collection1
[junit4:junit4]   2> 9385 T767 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9386 T767 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9386 T767 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9387 T767 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-1364064362204/collection1/'
[junit4:junit4]   2> 9387 T767 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-1364064362204/collection1/lib/README' to classloader
[junit4:junit4]   2> 9388 T767 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-1364064362204/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9410 T767 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9459 T767 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9460 T767 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9463 T767 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9743 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9743 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54151__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 9747 T730 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> 9748 T750 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> 9748 T766 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> 9749 T737 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> 9850 T767 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9855 T767 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9857 T767 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9870 T767 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9873 T767 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9876 T767 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9877 T767 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9877 T767 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9877 T767 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9879 T767 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9879 T767 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9879 T767 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9879 T767 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-1364064362204/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2/
[junit4:junit4]   2> 9880 T767 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 9880 T767 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9880 T767 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2
[junit4:junit4]   2> 9880 T767 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2/index/
[junit4:junit4]   2> 9881 T767 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9881 T767 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2/index
[junit4:junit4]   2> 9882 T767 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e3308e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d342cb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9883 T767 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9884 T767 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9884 T767 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9885 T767 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9885 T767 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9885 T767 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9886 T767 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9886 T767 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9886 T767 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9886 T767 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9889 T767 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9891 T767 oass.SolrIndexSearcher.<init> Opening Searcher@e239e2 main
[junit4:junit4]   2> 9891 T767 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty2/tlog
[junit4:junit4]   2> 9891 T767 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9891 T767 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9895 T768 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e239e2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9896 T767 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9896 T767 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11254 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11255 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43270",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:43270_"}
[junit4:junit4]   2> 11255 T731 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11255 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 11260 T737 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> 11260 T750 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> 11260 T730 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> 11260 T766 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> 11902 T767 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11902 T767 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43270 collection:collection1 shard:shard1
[junit4:junit4]   2> 11903 T767 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 11909 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 11909 T767 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11910 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11912 T767 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11912 T767 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11912 T767 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43270/collection1/
[junit4:junit4]   2> 11913 T767 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11913 T767 oasc.SyncStrategy.syncToMe http://127.0.0.1:43270/collection1/ has no replicas
[junit4:junit4]   2> 11913 T767 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43270/collection1/
[junit4:junit4]   2> 11913 T767 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 11917 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12764 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12771 T750 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> 12771 T766 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> 12771 T737 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> 12771 T730 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> 12821 T767 oasc.ZkController.register We are http://127.0.0.1:43270/collection1/ and leader is http://127.0.0.1:43270/collection1/
[junit4:junit4]   2> 12821 T767 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43270
[junit4:junit4]   2> 12821 T767 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12821 T767 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12822 T767 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12823 T767 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12824 T708 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12825 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12825 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12897 T708 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12899 T708 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46596
[junit4:junit4]   2> 12900 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12900 T708 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12901 T708 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-1364064366783
[junit4:junit4]   2> 12901 T708 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-1364064366783/solr.xml
[junit4:junit4]   2> 12901 T708 oasc.CoreContainer.<init> New CoreContainer 5619907
[junit4:junit4]   2> 12902 T708 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-1364064366783/'
[junit4:junit4]   2> 12902 T708 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-1364064366783/'
[junit4:junit4]   2> 12919 T708 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12920 T708 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12920 T708 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12920 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12921 T708 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12921 T708 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12921 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12921 T708 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12922 T708 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12922 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12928 T708 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12944 T708 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:34532/solr
[junit4:junit4]   2> 12945 T708 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12945 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1807c88
[junit4:junit4]   2> 12946 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12946 T779 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12947 T779 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 12947 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57237
[junit4:junit4]   2> 12947 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57237
[junit4:junit4]   2> 12948 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb00009 with negotiated timeout 20000 for client /127.0.0.1:57237
[junit4:junit4]   2> 12948 T779 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb00009, negotiated timeout = 20000
[junit4:junit4]   2> 12948 T780 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1807c88 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12949 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12951 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00009
[junit4:junit4]   2> 12952 T780 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12952 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57237 which had sessionid 0x13d98923eb00009
[junit4:junit4]   2> 12952 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00009 closed
[junit4:junit4]   2> 12952 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12955 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1e1f930
[junit4:junit4]   2> 12956 T781 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12956 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12956 T781 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 12957 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57238
[junit4:junit4]   2> 12957 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57238
[junit4:junit4]   2> 12958 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb0000a with negotiated timeout 20000 for client /127.0.0.1:57238
[junit4:junit4]   2> 12958 T781 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb0000a, negotiated timeout = 20000
[junit4:junit4]   2> 12958 T782 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e1f930 name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12958 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12959 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12960 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12961 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13964 T708 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46596_
[junit4:junit4]   2> 13965 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:46596_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:46596_
[junit4:junit4]   2> 13965 T708 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46596_
[junit4:junit4]   2> 13967 T737 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> 13968 T750 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> 13968 T730 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13968 T766 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13968 T766 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> 13968 T782 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13968 T730 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> 13970 T737 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13970 T750 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13973 T783 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-1364064366783/collection1
[junit4:junit4]   2> 13974 T783 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13974 T783 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13974 T783 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13975 T783 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-1364064366783/collection1/'
[junit4:junit4]   2> 13975 T783 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-1364064366783/collection1/lib/README' to classloader
[junit4:junit4]   2> 13976 T783 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-1364064366783/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 14005 T783 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 14036 T783 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 14037 T783 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 14041 T783 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14277 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14277 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:43270__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43270",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:43270_"}
[junit4:junit4]   2> 14286 T730 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> 14286 T750 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> 14286 T766 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> 14286 T737 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> 14286 T782 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> 14418 T783 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14423 T783 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14425 T783 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14438 T783 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14441 T783 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14444 T783 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14445 T783 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14445 T783 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14446 T783 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14446 T783 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14447 T783 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14447 T783 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14447 T783 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-1364064366783/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/
[junit4:junit4]   2> 14447 T783 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 14448 T783 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14448 T783 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3
[junit4:junit4]   2> 14448 T783 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/index/
[junit4:junit4]   2> 14448 T783 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14448 T783 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/index
[junit4:junit4]   2> 14450 T783 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12bd4cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@137f1e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14450 T783 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14451 T783 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14452 T783 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14452 T783 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14459 T783 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14459 T783 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14460 T783 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14460 T783 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14460 T783 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14460 T783 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14463 T783 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14465 T783 oass.SolrIndexSearcher.<init> Opening Searcher@1da5902 main
[junit4:junit4]   2> 14465 T783 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/tlog
[junit4:junit4]   2> 14465 T783 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14466 T783 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14470 T784 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1da5902 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14471 T783 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14472 T783 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15793 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15794 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46596",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46596_"}
[junit4:junit4]   2> 15795 T731 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15795 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 15799 T737 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> 15799 T730 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> 15799 T782 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> 15799 T766 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> 15799 T750 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> 16473 T783 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16473 T783 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46596 collection:collection1 shard:shard2
[junit4:junit4]   2> 16476 T783 oasc.ZkController.register We are http://127.0.0.1:46596/collection1/ and leader is http://127.0.0.1:54151/collection1/
[junit4:junit4]   2> 16476 T783 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46596
[junit4:junit4]   2> 16477 T783 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16477 T783 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C42 name=collection1 org.apache.solr.core.SolrCore@1e1c17c url=http://127.0.0.1:46596/collection1 node=127.0.0.1:46596_ C42_STATE=coll:collection1 core:collection1 props:{state=down, collection=collection1, base_url=http://127.0.0.1:46596, core=collection1, node_name=127.0.0.1:46596_}
[junit4:junit4]   2> 16477 T785 C42 P46596 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16477 T783 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16478 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16478 T785 C42 P46596 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16478 T785 C42 P46596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16479 T708 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16479 T785 C42 P46596 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16479 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16479 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16543 T708 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16545 T708 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38121
[junit4:junit4]   2> 16545 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16546 T708 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16546 T708 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-1364064370437
[junit4:junit4]   2> 16546 T708 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-1364064370437/solr.xml
[junit4:junit4]   2> 16546 T708 oasc.CoreContainer.<init> New CoreContainer 3264209
[junit4:junit4]   2> 16547 T708 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-1364064370437/'
[junit4:junit4]   2> 16547 T708 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-1364064370437/'
[junit4:junit4]   2> 16564 T708 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16564 T708 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16565 T708 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16565 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16565 T708 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16565 T708 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16566 T708 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16566 T708 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16566 T708 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16567 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16573 T708 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16592 T708 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:34532/solr
[junit4:junit4]   2> 16593 T708 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16594 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@f6e994
[junit4:junit4]   2> 16595 T796 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16595 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16595 T796 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 16596 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57241
[junit4:junit4]   2> 16596 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57241
[junit4:junit4]   2> 16597 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb0000b with negotiated timeout 20000 for client /127.0.0.1:57241
[junit4:junit4]   2> 16597 T796 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb0000b, negotiated timeout = 20000
[junit4:junit4]   2> 16597 T797 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f6e994 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16597 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16598 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb0000b
[junit4:junit4]   2> 16599 T797 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16599 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57241 which had sessionid 0x13d98923eb0000b
[junit4:junit4]   2> 16599 T708 oaz.ZooKeeper.close Session: 0x13d98923eb0000b closed
[junit4:junit4]   2> 16600 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16604 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@125a5ae
[junit4:junit4]   2> 16605 T798 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16605 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16605 T798 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 16606 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57242
[junit4:junit4]   2> 16606 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57242
[junit4:junit4]   2> 16607 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb0000c with negotiated timeout 20000 for client /127.0.0.1:57242
[junit4:junit4]   2> 16607 T798 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb0000c, negotiated timeout = 20000
[junit4:junit4]   2> 16607 T799 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@125a5ae name:ZooKeeperConnection Watcher:127.0.0.1:34532/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16607 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16608 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16609 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16611 T708 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17304 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17304 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:46596__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46596",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46596_"}
[junit4:junit4]   2> 17310 T799 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> 17310 T782 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> 17311 T737 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> 17310 T730 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> 17310 T766 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> 17310 T750 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> 17484 T746 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {state=recovering&action=PREPRECOVERY&checkLive=true&nodeName=127.0.0.1:46596_&version=2&coreNodeName=127.0.0.1:46596__collection1&core=collection1&wt=javabin&onlyIfLeader=true} status=0 QTime=1000 
[junit4:junit4]   2> 17613 T708 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38121_
[junit4:junit4]   2> 17614 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:38121_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:38121_
[junit4:junit4]   2> 17615 T708 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38121_
[junit4:junit4]   2> 17616 T799 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> 17616 T766 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> 17617 T730 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> 17617 T750 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17617 T750 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> 17618 T737 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17618 T782 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17618 T782 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> 17618 T737 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> 17620 T766 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17620 T730 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17620 T799 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17624 T800 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-1364064370437/collection1
[junit4:junit4]   2> 17624 T800 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17625 T800 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17625 T800 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17626 T800 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-1364064370437/collection1/'
[junit4:junit4]   2> 17627 T800 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-1364064370437/collection1/lib/README' to classloader
[junit4:junit4]   2> 17627 T800 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-1364064370437/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17662 T800 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 17693 T800 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17694 T800 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17698 T800 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 18070 T800 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 18075 T800 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 18078 T800 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 18093 T800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18096 T800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18099 T800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18100 T800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18101 T800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18101 T800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18102 T800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18102 T800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18102 T800 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18102 T800 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-1364064370437/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/
[junit4:junit4]   2> 18102 T800 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 18103 T800 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18103 T800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4
[junit4:junit4]   2> 18103 T800 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/index/
[junit4:junit4]   2> 18103 T800 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 18104 T800 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/index
[junit4:junit4]   2> 18105 T800 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8d5a42 lockFactory=org.apache.lucene.store.NativeFSLockFactory@93e7f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18105 T800 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18107 T800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 18107 T800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 18107 T800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 18108 T800 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 18108 T800 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 18108 T800 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 18108 T800 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 18109 T800 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 18109 T800 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18111 T800 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18113 T800 oass.SolrIndexSearcher.<init> Opening Searcher@12c1a51 main
[junit4:junit4]   2> 18114 T800 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/tlog
[junit4:junit4]   2> 18114 T800 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18114 T800 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18117 T801 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12c1a51 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18119 T800 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18120 T800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18815 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18816 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38121",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38121_"}
[junit4:junit4]   2> 18816 T731 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18816 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 18820 T730 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> 18820 T799 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> 18820 T750 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> 18820 T737 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> 18820 T782 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> 18820 T766 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> 19121 T800 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19121 T800 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38121 collection:collection1 shard:shard1
[junit4:junit4]   2> 19124 T800 oasc.ZkController.register We are http://127.0.0.1:38121/collection1/ and leader is http://127.0.0.1:43270/collection1/
[junit4:junit4]   2> 19124 T800 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38121
[junit4:junit4]   2> 19124 T800 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19124 T800 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C43 name=collection1 org.apache.solr.core.SolrCore@1d855d4 url=http://127.0.0.1:38121/collection1 node=127.0.0.1:38121_ C43_STATE=coll:collection1 core:collection1 props:{state=down, collection=collection1, base_url=http://127.0.0.1:38121, core=collection1, node_name=127.0.0.1:38121_}
[junit4:junit4]   2> 19124 T802 C43 P38121 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19125 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19125 T800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19125 T802 C43 P38121 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19125 T802 C43 P38121 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19126 T708 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19126 T802 C43 P38121 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19126 T708 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19127 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19133 T708 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19140 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19144 T746 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-1364064357683/onenodecollectioncore
[junit4:junit4]   2> 19145 T746 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19145 T746 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19146 T746 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19147 T746 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19147 T746 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19149 T746 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19150 T746 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-1364064357683/onenodecollectioncore/'
[junit4:junit4]   2> 19194 T746 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19243 T746 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19244 T746 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19250 T746 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C42_STATE=coll:collection1 core:collection1 props:{state=recovering, collection=collection1, shard=shard2, base_url=http://127.0.0.1:46596, core=collection1, node_name=127.0.0.1:46596_}
[junit4:junit4]   2> 19485 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:54151/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19485 T785 C42 P46596 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46596 START replicas=[http://127.0.0.1:54151/collection1/] nUpdates=100
[junit4:junit4]   2> 19486 T785 C42 P46596 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19487 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19487 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19488 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19488 T785 C42 P46596 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19488 T785 C42 P46596 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:54151/collection1/. core=collection1
[junit4:junit4]   2> 19488 T785 C42 P46596 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C44 name=collection1 org.apache.solr.core.SolrCore@bbeb70 url=http://127.0.0.1:54151/collection1 node=127.0.0.1:54151_ C44_STATE=coll:collection1 core:collection1 props:{state=active, collection=collection1, shard=shard2, base_url=http://127.0.0.1:54151, core=collection1, node_name=127.0.0.1:54151_, leader=true}
[junit4:junit4]   2> 19500 T744 C44 P54151 REQ /get {getVersions=100&version=2&distrib=false&wt=javabin&qt=/get} status=0 QTime=1 
[junit4:junit4]   2> 19501 T745 C44 P54151 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19503 T745 C44 P54151 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19abe4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c2d4c2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19504 T745 C44 P54151 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19505 T745 C44 P54151 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19abe4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c2d4c2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19abe4f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c2d4c2),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19505 T745 C44 P54151 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19506 T745 C44 P54151 oass.SolrIndexSearcher.<init> Opening Searcher@532fb9 realtime
[junit4:junit4]   2> 19506 T745 C44 P54151 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19506 T745 C44 P54151 /update {waitSearcher=true&softCommit=false&commit_end_point=true&version=2&wt=javabin&commit=true&openSearcher=false} {commit=} 0 5
[junit4:junit4]   2> 19507 T785 C42 P46596 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19507 T785 C42 P46596 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19590 T743 C44 P54151 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19590 T743 C44 P54151 REQ /replication {version=2&command=indexversion&wt=javabin&qt=/replication} status=0 QTime=7 
[junit4:junit4]   2> 19591 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19591 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19591 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19593 T744 C44 P54151 REQ /replication {version=2&command=filelist&generation=2&wt=javabin&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 19594 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19595 T785 C42 P46596 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty3/index.20130323214613548
[junit4:junit4]   2> 19595 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Starting download to BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@a133b0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a71bc2) fullCopy=false
[junit4:junit4]   2> 19601 T745 C44 P54151 REQ /replication {file=segments_2&checksum=true&command=filecontent&generation=2&wt=filestream&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 19608 T785 C42 P46596 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19609 T785 C42 P46596 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19610 T785 C42 P46596 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19611 T785 C42 P46596 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12bd4cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@137f1e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12bd4cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@137f1e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19611 T785 C42 P46596 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19611 T785 C42 P46596 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19612 T785 C42 P46596 oass.SolrIndexSearcher.<init> Opening Searcher@2d9280 main
[junit4:junit4]   2> 19613 T784 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d9280 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19613 T785 C42 P46596 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19613 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19613 T785 C42 P46596 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19614 T785 C42 P46596 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19615 T785 C42 P46596 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19734 T746 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19739 T746 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19741 T746 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19753 T746 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19756 T746 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19760 T746 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19761 T746 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19761 T746 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19761 T746 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19762 T746 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19762 T746 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19763 T746 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19763 T746 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-1364064357683/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/
[junit4:junit4]   2> 19763 T746 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c7296
[junit4:junit4]   2> 19764 T746 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19764 T746 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection
[junit4:junit4]   2> 19765 T746 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-1364064353960/onenodecollection/index/
[junit4:junit4]   2> 19765 T746 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19765 T746 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/index
[junit4:junit4]   2> 19767 T746 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@9e97ce lockFactory=org.apache.lucene.store.NativeFSLockFactory@14cbaaa),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19767 T746 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19768 T746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19769 T746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19769 T746 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19770 T746 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19770 T746 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19770 T746 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19771 T746 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19771 T746 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19772 T746 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19774 T746 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19776 T746 oass.SolrIndexSearcher.<init> Opening Searcher@8fa2cc main
[junit4:junit4]   2> 19777 T746 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/tlog
[junit4:junit4]   2> 19777 T746 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19777 T746 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19781 T806 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@8fa2cc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19782 T746 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20324 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20325 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:38121__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38121",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38121_"}
[junit4:junit4]   2> 20327 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:46596__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46596",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46596_"}
[junit4:junit4]   2> 20330 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 20330 T731 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20330 T731 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20333 T737 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> 20333 T730 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> 20333 T799 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> 20334 T782 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> 20333 T766 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> 20333 T750 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> 20783 T746 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20783 T746 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:54151 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20786 T746 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20791 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 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> 20792 T746 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20793 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20795 T746 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20795 T746 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20796 T746 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54151/onenodecollectioncore/
[junit4:junit4]   2> 20796 T746 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20796 T746 oasc.SyncStrategy.syncToMe http://127.0.0.1:54151/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20797 T746 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54151/onenodecollectioncore/
[junit4:junit4]   2> 20797 T746 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20808 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21139 T761 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {state=recovering&action=PREPRECOVERY&checkLive=true&nodeName=127.0.0.1:38121_&version=2&coreNodeName=127.0.0.1:38121__collection1&core=collection1&wt=javabin&onlyIfLeader=true} status=0 QTime=2000 
[junit4:junit4]   2> 21841 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21887 T730 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> 21887 T750 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> 21888 T799 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> 21888 T782 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> 21888 T766 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> 21888 T737 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> 21913 T746 oasc.ZkController.register We are http://127.0.0.1:54151/onenodecollectioncore/ and leader is http://127.0.0.1:54151/onenodecollectioncore/
[junit4:junit4]   2> 21913 T746 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:54151
[junit4:junit4]   2> 21913 T746 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21914 T746 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21915 T746 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21922 T746 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {action=CREATE&roles=none&version=2&collection=onenodecollection&numShards=1&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection&name=onenodecollectioncore&wt=javabin} status=0 QTime=2778 
[junit4:junit4]   2> 21923 T708 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21924 T708 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22925 T708 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C43_STATE=coll:collection1 core:collection1 props:{state=recovering, collection=collection1, shard=shard1, base_url=http://127.0.0.1:38121, core=collection1, node_name=127.0.0.1:38121_}
[junit4:junit4]   2> 23140 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43270/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23140 T802 C43 P38121 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38121 START replicas=[http://127.0.0.1:43270/collection1/] nUpdates=100
[junit4:junit4]   2> 23141 T802 C43 P38121 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23141 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23141 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23141 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23141 T802 C43 P38121 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23141 T802 C43 P38121 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43270/collection1/. core=collection1
[junit4:junit4]   2> 23141 T802 C43 P38121 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C45 name=collection1 org.apache.solr.core.SolrCore@1259a61 url=http://127.0.0.1:43270/collection1 node=127.0.0.1:43270_ C45_STATE=coll:collection1 core:collection1 props:{state=active, collection=collection1, shard=shard1, base_url=http://127.0.0.1:43270, core=collection1, node_name=127.0.0.1:43270_, leader=true}
[junit4:junit4]   2> 23145 T759 C45 P43270 REQ /get {getVersions=100&version=2&distrib=false&wt=javabin&qt=/get} status=0 QTime=0 
[junit4:junit4]   2> 23146 T760 C45 P43270 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23147 T760 C45 P43270 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e3308e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d342cb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 23148 T760 C45 P43270 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 23148 T760 C45 P43270 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e3308e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d342cb),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e3308e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d342cb),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23148 T760 C45 P43270 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23149 T760 C45 P43270 oass.SolrIndexSearcher.<init> Opening Searcher@f460d8 realtime
[junit4:junit4]   2> 23149 T760 C45 P43270 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23149 T760 C45 P43270 /update {waitSearcher=true&softCommit=false&commit_end_point=true&version=2&wt=javabin&commit=true&openSearcher=false} {commit=} 0 3
[junit4:junit4]   2> 23150 T802 C43 P38121 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23150 T802 C43 P38121 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23152 T761 C45 P43270 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23152 T761 C45 P43270 REQ /replication {version=2&command=indexversion&wt=javabin&qt=/replication} status=0 QTime=1 
[junit4:junit4]   2> 23153 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 23153 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23153 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23155 T759 C45 P43270 REQ /replication {version=2&command=filelist&generation=2&wt=javabin&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 23155 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23156 T802 C43 P38121 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty4/index.20130323214617110
[junit4:junit4]   2> 23156 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Starting download to BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@1776a5e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eae06f) fullCopy=false
[junit4:junit4]   2> 23158 T760 C45 P43270 REQ /replication {file=segments_2&checksum=true&command=filecontent&generation=2&wt=filestream&qt=/replication} status=0 QTime=0 
[junit4:junit4]   2> 23159 T802 C43 P38121 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23160 T802 C43 P38121 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23160 T802 C43 P38121 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23161 T802 C43 P38121 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8d5a42 lockFactory=org.apache.lucene.store.NativeFSLockFactory@93e7f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8d5a42 lockFactory=org.apache.lucene.store.NativeFSLockFactory@93e7f9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23162 T802 C43 P38121 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23162 T802 C43 P38121 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23162 T802 C43 P38121 oass.SolrIndexSearcher.<init> Opening Searcher@18a130a main
[junit4:junit4]   2> 23163 T801 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18a130a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 23163 T802 C43 P38121 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23163 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23164 T802 C43 P38121 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23164 T802 C43 P38121 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23165 T802 C43 P38121 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23395 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23396 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54151__onenodecollectioncore",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 23400 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:38121__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:38121",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:38121_"}
[junit4:junit4]   2> 23405 T730 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> 23405 T737 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> 23405 T750 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> 23405 T799 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> 23405 T766 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> 23405 T782 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> 23927 T708 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23928 T708 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23929 T708 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23938 T708 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:34532 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@b7d76
[junit4:junit4]   2> 23939 T708 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23939 T809 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:34532. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23939 T809 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:34532, initiating session
[junit4:junit4]   2> 23940 T710 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:57255
[junit4:junit4]   2> 23940 T710 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:57255
[junit4:junit4]   2> 23940 T712 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d98923eb0000d with negotiated timeout 10000 for client /127.0.0.1:57255
[junit4:junit4]   2> 23940 T809 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:34532, sessionid = 0x13d98923eb0000d, negotiated timeout = 10000
[junit4:junit4]   2> 23941 T810 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b7d76 name:ZooKeeperConnection Watcher:127.0.0.1:34532 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23941 T708 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23976 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb0000d
[junit4:junit4]   2> 23977 T810 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23977 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57255 which had sessionid 0x13d98923eb0000d
[junit4:junit4]   2> 23977 T708 oaz.ZooKeeper.close Session: 0x13d98923eb0000d closed
[junit4:junit4]   2> 23977 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00004
[junit4:junit4]   2> 23978 T737 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23978 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00004 closed
[junit4:junit4]   2> 23978 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57232 which had sessionid 0x13d98923eb00004
[junit4:junit4]   2> 23980 T708 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 53800
[junit4:junit4]   2> 23980 T708 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=31266721
[junit4:junit4]   2> 24911 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24912 T731 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:53800__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53800",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53800_"}
[junit4:junit4]   2> 24916 T730 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> 24916 T766 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> 24916 T799 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> 24916 T782 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> 24916 T750 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> 25982 T708 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25982 T708 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25984 T708 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@1637778
[junit4:junit4]   2> 25987 T708 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> 25987 T708 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25988 T708 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25988 T708 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25989 T708 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25989 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/index
[junit4:junit4]   2> 25989 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data/index
[junit4:junit4]   2> 25990 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data
[junit4:junit4]   2> 25990 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/control/data
[junit4:junit4]   2> 25990 T731 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89395321501646851-127.0.0.1:53800_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25991 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00003
[junit4:junit4]   2> 25991 T730 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> 25992 T710 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d98923eb00003, likely client has closed socket
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4]   2> 	at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4]   2> 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 
[junit4:junit4]   2> 25992 T750 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25992 T799 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25992 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00003 closed
[junit4:junit4]   2> 25992 T782 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25992 T750 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> 25992 T766 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25993 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57231 which had sessionid 0x13d98923eb00003
[junit4:junit4]   2> 25993 T782 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> 25993 T799 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> 25993 T766 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> 25995 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:delete cxid:0xc9 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25995 T750 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25997 T750 oasc.Overseer.start Overseer (id=89395321501646854-127.0.0.1:54151_-n_0000000001) starting
[junit4:junit4]   2> 25997 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xce zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25998 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xcf zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25999 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xd1 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26000 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00006 type:create cxid:0xd3 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26000 T812 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 26005 T811 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 26006 T811 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 26007 T811 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:53800__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:53800",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:53800_"}
[junit4:junit4]   2> 26015 T708 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 26022 T782 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> 26022 T766 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> 26022 T750 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> 26022 T799 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> 26068 T708 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 54151
[junit4:junit4]   2> 26068 T708 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=12001865
[junit4:junit4]   2> 27292 T730 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 27292 T730 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 27292 T730 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27526 T811 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27527 T811 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54151__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 27530 T811 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:54151__onenodecollectioncore",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54151",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54151_"}
[junit4:junit4]   2> 27534 T766 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> 27534 T799 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> 27534 T782 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> 27534 T750 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> 29070 T708 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 29071 T708 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 29072 T708 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 29074 T708 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@bbeb70
[junit4:junit4]   2> 29077 T708 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> 29077 T708 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29078 T708 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29078 T708 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29079 T708 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 29080 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/index
[junit4:junit4]   2> 29080 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1/index
[junit4:junit4]   2> 29080 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1
[junit4:junit4]   2> 29080 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364064353960/jetty1
[junit4:junit4]   2> 29081 T708 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@639d99
[junit4:junit4]   2> 29084 T708 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> 29085 T708 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29085 T708 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29085 T708 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29086 T708 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 29086 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection
[junit4:junit4]   2> 29087 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection
[junit4:junit4]   2> 29087 T708 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/index
[junit4:junit4]   2> 29087 T708 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364064353960/onenodecollection/index
[junit4:junit4]   2> 29088 T811 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89395321501646854-127.0.0.1:54151_-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 29088 T713 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d98923eb00006
[junit4:junit4]   2> 29089 T710 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:57234 which had sessionid 0x13d98923eb00006
[junit4:junit4]   2> 29089 T708 oaz.ZooKeeper.close Session: 0x13d98923eb00006 closed
[junit4:junit4]   2> 29090 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000a type:delete cxid:0x5e zxid:0xf9 txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 29090 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:delete cxid:0x7c zxid:0xfa txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 29090 T782 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 29090 T766 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 29090 T799 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29090 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb0000a type:create cxid:0x5f zxid:0xfb txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29091 T799 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> 29092 T782 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 29092 T782 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 29092 T782 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 29092 T766 oasc.Overseer.start Overseer (id=89395321501646856-127.0.0.1:43270_-n_0000000002) starting
[junit4:junit4]   2> 29092 T782 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46596/collection1/
[junit4:junit4]   2> 29093 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x81 zxid:0xfe txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29093 T782 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46596 START replicas=[http://127.0.0.1:54151/collection1/] nUpdates=100
[junit4:junit4]   2> 29093 T782 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46596 DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 29093 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x82 zxid:0xff txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29093 T782 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 29094 T782 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 29094 T782 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46596/collection1/
[junit4:junit4]   2> 29094 T782 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 29094 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x84 zxid:0x100 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29095 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d98923eb00008 type:create cxid:0x86 zxid:0x101 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29096 T815 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 29096 T766 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> 29097 T713 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sess

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

.0.0.1:53800_ (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:43270_ (0)
[junit4:junit4]   1>   /solr/overseer (3)
[junit4:junit4]   1>   DATA:
[junit4:junit4]   1>       
[junit4:junit4]   1>    /solr/overseer/queue (0)
[junit4:junit4]   1>    /solr/overseer/collection-queue-work (0)
[junit4:junit4]   1>    /solr/overseer/queue-work (0)
[junit4:junit4]   1>   /solr/aliases.json (0)
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=925378E2E4BEC312 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=no_NO -Dtests.timezone=Africa/Nairobi -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR   32.5s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.common.SolrException: Server at http://127.0.0.1:43270/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([925378E2E4BEC312:13B5F6FA93E1A32E]:0)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:197)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
[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> 32456 T708 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 32459 T707 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4]   2> 33046 T711 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 33664 T799 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33664 T799 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> 33665 T799 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33665 T799 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=DefaultSimilarity, locale=no_NO, timezone=Africa/Nairobi
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=52217944,total=111828992
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TermVectorComponentDistributedTest, SolrIndexConfigTest, TestRTGBase, TestIndexSearcher, TestCSVLoader, TestSolr4Spatial, EchoParamsTest, FullSolrCloudDistribCmdsTest, TestBinaryField, HighlighterConfigTest, TestCopyFieldCollectionResource, TestDFRSimilarityFactory, TestZkChroot, IndexBasedSpellCheckerTest, TestStressReorder, TestOmitPositions, TestDistributedSearch, UniqFieldsUpdateProcessorFactoryTest, TestSolrDiscoveryProperties, TestArbitraryIndexDir, TestFoldingMultitermQuery, TestSolrXMLSerializer, CurrencyFieldOpenExchangeTest, SignatureUpdateProcessorFactoryTest, TestElisionMultitermQuery, TestQuerySenderNoQuery, TestAnalyzedSuggestions, TestCollationField, TestSystemIdResolver, DOMUtilTest, TestIndexingPerformance, CopyFieldTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.74s, 1 test, 1 error <<< FAILURES!

[...truncated 660 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, 13 ignored (7 assumptions)

Total time: 41 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