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 # 4846 - Failure!
Date Sun, 24 Mar 2013 07:59:59 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4846/
Java: 32bit/jdk1.8.0-ea-b82 -server -XX:+UseG1GC -XX:MarkStackSize=256K

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

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

Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:35506/b_jx/i/onenodecollectioncore returned non ok status:404, message:Can not find: /b_jx/i/onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([685AC33CC8D74261:E9BC4D24BF88225D]: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 9028 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T232 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /b_jx/i
[junit4:junit4]   2> 6 T232 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-1364111154301
[junit4:junit4]   2> 7 T232 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 7 T233 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 8 T233 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 8 T233 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 8 T233 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 9 T233 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 10 T233 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-1364111154300/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 108 T232 oasc.ZkTestServer.run start zk server on port:60657
[junit4:junit4]   2> 108 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@a8120e
[junit4:junit4]   2> 109 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 109 T238 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 110 T238 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 111 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60063
[junit4:junit4]   2> 112 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60063
[junit4:junit4]   2> 112 T236 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 180 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800000 with negotiated timeout 10000 for client /127.0.0.1:60063
[junit4:junit4]   2> 181 T238 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800000, negotiated timeout = 10000
[junit4:junit4]   2> 181 T239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a8120e name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 182 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 183 T232 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 189 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800000
[junit4:junit4]   2> 191 T239 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 191 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800000 closed
[junit4:junit4]   2> 191 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60063 which had sessionid 0x13d9b5c5c800000
[junit4:junit4]   2> 192 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@979d43
[junit4:junit4]   2> 193 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 193 T240 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 194 T240 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 194 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60064
[junit4:junit4]   2> 195 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60064
[junit4:junit4]   2> 196 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800001 with negotiated timeout 10000 for client /127.0.0.1:60064
[junit4:junit4]   2> 197 T240 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800001, negotiated timeout = 10000
[junit4:junit4]   2> 197 T241 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@979d43 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 198 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 198 T232 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 206 T232 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 212 T232 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 217 T232 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 224 T232 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> 226 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 235 T232 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 239 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 243 T232 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> 244 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 250 T232 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> 251 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 256 T232 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> 256 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 260 T232 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> 261 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 266 T232 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> 268 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 274 T232 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> 275 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 280 T232 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> 281 T232 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 287 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800001
[junit4:junit4]   2> 288 T241 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 288 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60064 which had sessionid 0x13d9b5c5c800001
[junit4:junit4]   2> 288 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800001 closed
[junit4:junit4]   2> 360 T232 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 363 T232 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57386
[junit4:junit4]   2> 364 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 364 T232 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 365 T232 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-1364111154584
[junit4:junit4]   2> 365 T232 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-1364111154584/solr.xml
[junit4:junit4]   2> 365 T232 oasc.CoreContainer.<init> New CoreContainer 29588577
[junit4:junit4]   2> 366 T232 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-1364111154584/'
[junit4:junit4]   2> 366 T232 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-1364111154584/'
[junit4:junit4]   2> 388 T232 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 389 T232 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 389 T232 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 389 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 390 T232 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 390 T232 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 391 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 391 T232 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 391 T232 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 392 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 400 T232 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 428 T232 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:60657/solr
[junit4:junit4]   2> 429 T232 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 429 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@20df86
[junit4:junit4]   2> 430 T251 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 430 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 431 T251 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 431 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60065
[junit4:junit4]   2> 432 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60065
[junit4:junit4]   2> 434 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800002 with negotiated timeout 20000 for client /127.0.0.1:60065
[junit4:junit4]   2> 434 T251 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800002, negotiated timeout = 20000
[junit4:junit4]   2> 434 T252 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20df86 name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 435 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 437 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800002
[junit4:junit4]   2> 437 T252 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 437 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800002 closed
[junit4:junit4]   2> 438 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60065 which had sessionid 0x13d9b5c5c800002
[junit4:junit4]   2> 438 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 470 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@673088
[junit4:junit4]   2> 471 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 471 T253 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 472 T253 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 472 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60066
[junit4:junit4]   2> 472 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60066
[junit4:junit4]   2> 473 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800003 with negotiated timeout 20000 for client /127.0.0.1:60066
[junit4:junit4]   2> 473 T253 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800003, negotiated timeout = 20000
[junit4:junit4]   2> 473 T254 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@673088 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 474 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 476 T232 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 479 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 480 T232 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 485 T232 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 489 T232 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57386_b_jx%2Fi
[junit4:junit4]   2> 490 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:57386_b_jx%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:57386_b_jx%2Fi
[junit4:junit4]   2> 491 T232 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57386_b_jx%2Fi
[junit4:junit4]   2> 497 T232 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 509 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 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> 510 T232 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 516 T232 oasc.Overseer.start Overseer (id=89398388608466947-127.0.0.1:57386_b_jx%2Fi-n_0000000000) starting
[junit4:junit4]   2> 517 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 519 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 520 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 522 T232 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 525 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 527 T256 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 528 T232 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 531 T232 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 534 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 538 T255 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 541 T257 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-1364111154584/collection1
[junit4:junit4]   2> 541 T257 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 542 T257 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 542 T257 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 544 T257 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-1364111154584/collection1/'
[junit4:junit4]   2> 544 T257 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-1364111154584/collection1/lib/README' to classloader
[junit4:junit4]   2> 544 T257 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-1364111154584/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 568 T257 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 611 T257 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 613 T257 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 617 T257 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 948 T257 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 954 T257 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 956 T257 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 982 T257 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 987 T257 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 993 T257 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 996 T257 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 997 T257 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 997 T257 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1000 T257 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1000 T257 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1001 T257 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1001 T257 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-1364111154584/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/
[junit4:junit4]   2> 1002 T257 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 1002 T257 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1003 T257 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data
[junit4:junit4]   2> 1004 T257 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/index/
[junit4:junit4]   2> 1004 T257 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1005 T257 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/index
[junit4:junit4]   2> 1008 T257 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a0367 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e667c9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1008 T257 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1030 T257 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1031 T257 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1032 T257 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1033 T257 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1033 T257 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1034 T257 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1034 T257 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1034 T257 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1034 T257 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1036 T257 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1039 T257 oass.SolrIndexSearcher.<init> Opening Searcher@14e901e main
[junit4:junit4]   2> 1041 T257 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/tlog
[junit4:junit4]   2> 1045 T257 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1046 T257 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1051 T258 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14e901e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1054 T257 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1054 T257 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 2043 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2044 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57386_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57386/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 2044 T255 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2046 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2051 T254 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> 2057 T257 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2057 T257 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57386/b_jx/i collection:control_collection shard:shard1
[junit4:junit4]   2> 2059 T257 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2071 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 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> 2072 T257 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2072 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2076 T257 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2076 T257 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2076 T257 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57386/b_jx/i/collection1/
[junit4:junit4]   2> 2076 T257 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2076 T257 oasc.SyncStrategy.syncToMe http://127.0.0.1:57386/b_jx/i/collection1/ has no replicas
[junit4:junit4]   2> 2077 T257 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57386/b_jx/i/collection1/
[junit4:junit4]   2> 2077 T257 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2082 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3558 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3567 T254 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> 3591 T257 oasc.ZkController.register We are http://127.0.0.1:57386/b_jx/i/collection1/ and leader is http://127.0.0.1:57386/b_jx/i/collection1/
[junit4:junit4]   2> 3592 T257 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57386/b_jx/i
[junit4:junit4]   2> 3592 T257 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3592 T257 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3592 T257 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3594 T257 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3596 T232 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3596 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3597 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3605 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3608 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@a05a77
[junit4:junit4]   2> 3610 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3610 T260 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3611 T260 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 3611 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60070
[junit4:junit4]   2> 3612 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60070
[junit4:junit4]   2> 3614 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800004 with negotiated timeout 10000 for client /127.0.0.1:60070
[junit4:junit4]   2> 3614 T260 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800004, negotiated timeout = 10000
[junit4:junit4]   2> 3614 T261 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a05a77 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3615 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3616 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3619 T232 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3678 T232 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3680 T232 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59425
[junit4:junit4]   2> 3681 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3681 T232 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3682 T232 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-1364111157914
[junit4:junit4]   2> 3682 T232 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-1364111157914/solr.xml
[junit4:junit4]   2> 3682 T232 oasc.CoreContainer.<init> New CoreContainer 15087408
[junit4:junit4]   2> 3683 T232 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-1364111157914/'
[junit4:junit4]   2> 3683 T232 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-1364111157914/'
[junit4:junit4]   2> 3701 T232 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3701 T232 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3701 T232 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3702 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3702 T232 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3702 T232 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3703 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3703 T232 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3703 T232 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3704 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3710 T232 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3720 T232 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:60657/solr
[junit4:junit4]   2> 3721 T232 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3721 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@12e8cff
[junit4:junit4]   2> 3722 T271 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3722 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3723 T271 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 3723 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60071
[junit4:junit4]   2> 3723 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60071
[junit4:junit4]   2> 3724 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800005 with negotiated timeout 20000 for client /127.0.0.1:60071
[junit4:junit4]   2> 3724 T271 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800005, negotiated timeout = 20000
[junit4:junit4]   2> 3725 T272 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12e8cff name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3725 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3726 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800005
[junit4:junit4]   2> 3727 T272 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3727 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60071 which had sessionid 0x13d9b5c5c800005
[junit4:junit4]   2> 3727 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800005 closed
[junit4:junit4]   2> 3728 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3731 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@cb0b72
[junit4:junit4]   2> 3733 T273 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3732 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3733 T273 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 3733 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60072
[junit4:junit4]   2> 3734 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60072
[junit4:junit4]   2> 3735 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800006 with negotiated timeout 20000 for client /127.0.0.1:60072
[junit4:junit4]   2> 3735 T273 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800006, negotiated timeout = 20000
[junit4:junit4]   2> 3735 T274 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cb0b72 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3735 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3736 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3738 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3740 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4743 T232 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59425_b_jx%2Fi
[junit4:junit4]   2> 4745 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59425_b_jx%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59425_b_jx%2Fi
[junit4:junit4]   2> 4746 T232 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59425_b_jx%2Fi
[junit4:junit4]   2> 4754 T261 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4754 T274 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4754 T254 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4766 T254 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> 4778 T275 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-1364111157914/collection1
[junit4:junit4]   2> 4778 T275 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4779 T275 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4780 T275 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4782 T275 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-1364111157914/collection1/'
[junit4:junit4]   2> 4783 T275 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-1364111157914/collection1/lib/README' to classloader
[junit4:junit4]   2> 4784 T275 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-1364111157914/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4813 T275 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4840 T275 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4841 T275 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4845 T275 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 5081 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5082 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57386_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57386/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 5086 T261 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> 5086 T254 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> 5086 T274 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> 5185 T275 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5190 T275 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5192 T275 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5215 T275 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5219 T275 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5225 T275 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5227 T275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5228 T275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5229 T275 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5232 T275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5232 T275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5233 T275 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5233 T275 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-1364111157914/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/
[junit4:junit4]   2> 5234 T275 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 5234 T275 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5235 T275 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1
[junit4:junit4]   2> 5236 T275 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/index/
[junit4:junit4]   2> 5236 T275 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5237 T275 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/index
[junit4:junit4]   2> 5239 T275 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a6d008 lockFactory=org.apache.lucene.store.NativeFSLockFactory@179f5d3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5240 T275 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5243 T275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5244 T275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5245 T275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5246 T275 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5247 T275 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5247 T275 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5248 T275 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5249 T275 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5249 T275 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5254 T275 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5256 T275 oass.SolrIndexSearcher.<init> Opening Searcher@1cb18a6 main
[junit4:junit4]   2> 5256 T275 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/tlog
[junit4:junit4]   2> 5256 T275 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5256 T275 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5263 T276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cb18a6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5267 T275 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5267 T275 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6591 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6592 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 6593 T255 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6593 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6599 T261 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> 6599 T254 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> 6599 T274 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> 7270 T275 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7271 T275 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59425/b_jx/i collection:collection1 shard:shard1
[junit4:junit4]   2> 7272 T275 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7287 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 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> 7288 T275 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7289 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7294 T275 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7295 T275 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7295 T275 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59425/b_jx/i/collection1/
[junit4:junit4]   2> 7296 T275 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7296 T275 oasc.SyncStrategy.syncToMe http://127.0.0.1:59425/b_jx/i/collection1/ has no replicas
[junit4:junit4]   2> 7296 T275 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59425/b_jx/i/collection1/
[junit4:junit4]   2> 7297 T275 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7306 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8104 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8114 T254 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> 8114 T274 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> 8114 T261 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> 8163 T275 oasc.ZkController.register We are http://127.0.0.1:59425/b_jx/i/collection1/ and leader is http://127.0.0.1:59425/b_jx/i/collection1/
[junit4:junit4]   2> 8164 T275 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59425/b_jx/i
[junit4:junit4]   2> 8164 T275 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8164 T275 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8164 T275 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8167 T275 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8168 T232 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 8168 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8169 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8230 T232 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8232 T232 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35506
[junit4:junit4]   2> 8233 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8234 T232 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8234 T232 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-1364111162466
[junit4:junit4]   2> 8235 T232 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-1364111162466/solr.xml
[junit4:junit4]   2> 8235 T232 oasc.CoreContainer.<init> New CoreContainer 1979211
[junit4:junit4]   2> 8236 T232 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-1364111162466/'
[junit4:junit4]   2> 8237 T232 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-1364111162466/'
[junit4:junit4]   2> 8258 T232 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8259 T232 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8259 T232 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8259 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8260 T232 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8260 T232 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8260 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8261 T232 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8261 T232 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8262 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8269 T232 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8286 T232 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:60657/solr
[junit4:junit4]   2> 8287 T232 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8287 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@10efae4
[junit4:junit4]   2> 8288 T287 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8288 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8289 T287 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 8289 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60075
[junit4:junit4]   2> 8289 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60075
[junit4:junit4]   2> 8290 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800007 with negotiated timeout 20000 for client /127.0.0.1:60075
[junit4:junit4]   2> 8290 T287 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800007, negotiated timeout = 20000
[junit4:junit4]   2> 8291 T288 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10efae4 name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8291 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8293 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800007
[junit4:junit4]   2> 8293 T288 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8293 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60075 which had sessionid 0x13d9b5c5c800007
[junit4:junit4]   2> 8293 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800007 closed
[junit4:junit4]   2> 8294 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8297 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@19fb103
[junit4:junit4]   2> 8298 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8298 T289 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8299 T289 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 8299 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60076
[junit4:junit4]   2> 8299 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60076
[junit4:junit4]   2> 8300 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800008 with negotiated timeout 20000 for client /127.0.0.1:60076
[junit4:junit4]   2> 8300 T289 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800008, negotiated timeout = 20000
[junit4:junit4]   2> 8300 T290 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19fb103 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8301 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8302 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8303 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8305 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9309 T232 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35506_b_jx%2Fi
[junit4:junit4]   2> 9311 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35506_b_jx%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35506_b_jx%2Fi
[junit4:junit4]   2> 9312 T232 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35506_b_jx%2Fi
[junit4:junit4]   2> 9317 T261 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> 9318 T290 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9318 T274 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9319 T254 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9319 T254 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> 9319 T274 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> 9321 T261 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9330 T291 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-1364111162466/collection1
[junit4:junit4]   2> 9331 T291 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9332 T291 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9333 T291 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9336 T291 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-1364111162466/collection1/'
[junit4:junit4]   2> 9337 T291 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-1364111162466/collection1/lib/README' to classloader
[junit4:junit4]   2> 9337 T291 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-1364111162466/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9378 T291 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9403 T291 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9405 T291 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9409 T291 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9632 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9633 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 9638 T254 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> 9638 T261 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> 9638 T290 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> 9638 T274 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> 9760 T291 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9765 T291 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9768 T291 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9793 T291 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9802 T291 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9805 T291 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9807 T291 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9807 T291 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9808 T291 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9810 T291 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9811 T291 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9811 T291 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9812 T291 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-1364111162466/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2/
[junit4:junit4]   2> 9812 T291 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 9813 T291 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9813 T291 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2
[junit4:junit4]   2> 9814 T291 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2/index/
[junit4:junit4]   2> 9814 T291 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9814 T291 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2/index
[junit4:junit4]   2> 9815 T291 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1442690 lockFactory=org.apache.lucene.store.NativeFSLockFactory@161402b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9815 T291 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9817 T291 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9817 T291 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9818 T291 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9818 T291 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9819 T291 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9819 T291 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9819 T291 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9820 T291 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9820 T291 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9822 T291 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9824 T291 oass.SolrIndexSearcher.<init> Opening Searcher@ec9ef4 main
[junit4:junit4]   2> 9824 T291 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty2/tlog
[junit4:junit4]   2> 9825 T291 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9825 T291 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9832 T292 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ec9ef4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9835 T291 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9836 T291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11145 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11148 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35506_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35506/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 11148 T255 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11148 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 11159 T290 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> 11159 T254 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> 11159 T274 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> 11160 T261 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> 11839 T291 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11839 T291 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35506/b_jx/i collection:collection1 shard:shard2
[junit4:junit4]   2> 11840 T291 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 11847 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 11848 T291 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11849 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11851 T291 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11851 T291 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11852 T291 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35506/b_jx/i/collection1/
[junit4:junit4]   2> 11852 T291 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11852 T291 oasc.SyncStrategy.syncToMe http://127.0.0.1:35506/b_jx/i/collection1/ has no replicas
[junit4:junit4]   2> 11852 T291 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35506/b_jx/i/collection1/
[junit4:junit4]   2> 11853 T291 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 11857 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12669 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12686 T290 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> 12686 T254 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> 12686 T274 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> 12686 T261 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> 12712 T291 oasc.ZkController.register We are http://127.0.0.1:35506/b_jx/i/collection1/ and leader is http://127.0.0.1:35506/b_jx/i/collection1/
[junit4:junit4]   2> 12713 T291 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35506/b_jx/i
[junit4:junit4]   2> 12713 T291 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12713 T291 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12714 T291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12717 T291 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12719 T232 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12720 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12721 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12786 T232 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12789 T232 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59230
[junit4:junit4]   2> 12790 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12791 T232 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12791 T232 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-1364111167023
[junit4:junit4]   2> 12792 T232 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-1364111167023/solr.xml
[junit4:junit4]   2> 12793 T232 oasc.CoreContainer.<init> New CoreContainer 27907884
[junit4:junit4]   2> 12794 T232 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-1364111167023/'
[junit4:junit4]   2> 12794 T232 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-1364111167023/'
[junit4:junit4]   2> 12822 T232 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12823 T232 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12823 T232 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12824 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12824 T232 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12824 T232 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12824 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12825 T232 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12825 T232 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12825 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12831 T232 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12840 T232 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:60657/solr
[junit4:junit4]   2> 12840 T232 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12841 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@19d09b8
[junit4:junit4]   2> 12842 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12842 T303 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12843 T303 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 12843 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60080
[junit4:junit4]   2> 12844 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60080
[junit4:junit4]   2> 12845 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c800009 with negotiated timeout 20000 for client /127.0.0.1:60080
[junit4:junit4]   2> 12845 T303 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c800009, negotiated timeout = 20000
[junit4:junit4]   2> 12846 T304 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19d09b8 name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12846 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12848 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800009
[junit4:junit4]   2> 12849 T304 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12849 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60080 which had sessionid 0x13d9b5c5c800009
[junit4:junit4]   2> 12849 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800009 closed
[junit4:junit4]   2> 12850 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12853 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1b8c9c1
[junit4:junit4]   2> 12854 T305 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12854 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12855 T305 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 12855 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60081
[junit4:junit4]   2> 12856 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60081
[junit4:junit4]   2> 12857 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c80000a with negotiated timeout 20000 for client /127.0.0.1:60081
[junit4:junit4]   2> 12857 T305 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c80000a, negotiated timeout = 20000
[junit4:junit4]   2> 12857 T306 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b8c9c1 name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12857 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12859 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12861 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12865 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13871 T232 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59230_b_jx%2Fi
[junit4:junit4]   2> 13872 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59230_b_jx%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59230_b_jx%2Fi
[junit4:junit4]   2> 13874 T232 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59230_b_jx%2Fi
[junit4:junit4]   2> 13878 T290 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> 13878 T254 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> 13880 T274 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13881 T261 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13881 T274 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> 13881 T261 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> 13882 T306 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13891 T290 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13892 T254 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13900 T307 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-1364111167023/collection1
[junit4:junit4]   2> 13900 T307 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13902 T307 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13902 T307 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13905 T307 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-1364111167023/collection1/'
[junit4:junit4]   2> 13906 T307 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-1364111167023/collection1/lib/README' to classloader
[junit4:junit4]   2> 13906 T307 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-1364111167023/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13941 T307 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 13972 T307 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13974 T307 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13978 T307 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14197 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14198 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35506_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35506/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 14203 T261 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> 14203 T274 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> 14203 T290 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> 14203 T254 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> 14203 T306 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> 14322 T307 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14328 T307 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14330 T307 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14355 T307 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14358 T307 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14362 T307 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14363 T307 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14364 T307 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14364 T307 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14365 T307 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14365 T307 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14366 T307 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14366 T307 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-1364111167023/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/
[junit4:junit4]   2> 14366 T307 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 14367 T307 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14367 T307 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3
[junit4:junit4]   2> 14367 T307 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/index/
[junit4:junit4]   2> 14368 T307 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14368 T307 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/index
[junit4:junit4]   2> 14375 T307 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d84de5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@163a9f5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14375 T307 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14377 T307 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14377 T307 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14378 T307 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14378 T307 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14379 T307 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14379 T307 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14379 T307 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14380 T307 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14380 T307 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14382 T307 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14385 T307 oass.SolrIndexSearcher.<init> Opening Searcher@527a78 main
[junit4:junit4]   2> 14385 T307 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/tlog
[junit4:junit4]   2> 14385 T307 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14386 T307 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14390 T308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@527a78 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14392 T307 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14392 T307 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15710 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15712 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59230_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59230/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 15712 T255 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15713 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 15721 T254 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> 15721 T261 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> 15721 T274 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> 15721 T306 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> 15721 T290 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> 16395 T307 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16395 T307 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59230/b_jx/i collection:collection1 shard:shard1
[junit4:junit4]   2> 16402 T307 oasc.ZkController.register We are http://127.0.0.1:59230/b_jx/i/collection1/ and leader is http://127.0.0.1:59425/b_jx/i/collection1/
[junit4:junit4]   2> 16402 T307 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59230/b_jx/i
[junit4:junit4]   2> 16402 T307 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16403 T307 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C19 name=collection1 org.apache.solr.core.SolrCore@1d95474 url=http://127.0.0.1:59230/b_jx/i/collection1 node=127.0.0.1:59230_b_jx%2Fi C19_STATE=coll:collection1 core:collection1 props:{collection=collection1, node_name=127.0.0.1:59230_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:59230/b_jx/i, state=down}
[junit4:junit4]   2> 16410 T309 C19 P59230 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16411 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16411 T307 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16412 T309 C19 P59230 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16412 T309 C19 P59230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16414 T232 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16414 T309 C19 P59230 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16415 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16415 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16484 T232 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16487 T232 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58159
[junit4:junit4]   2> 16488 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16488 T232 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16489 T232 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-1364111170716
[junit4:junit4]   2> 16489 T232 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-1364111170716/solr.xml
[junit4:junit4]   2> 16489 T232 oasc.CoreContainer.<init> New CoreContainer 19978016
[junit4:junit4]   2> 16490 T232 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-1364111170716/'
[junit4:junit4]   2> 16490 T232 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-1364111170716/'
[junit4:junit4]   2> 16506 T232 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16506 T232 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16507 T232 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16507 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16507 T232 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16508 T232 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16508 T232 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16508 T232 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16509 T232 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16509 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16515 T232 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16523 T232 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:60657/solr
[junit4:junit4]   2> 16524 T232 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16524 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1791745
[junit4:junit4]   2> 16525 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16526 T320 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16527 T320 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 16527 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60092
[junit4:junit4]   2> 16528 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60092
[junit4:junit4]   2> 16529 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c80000b with negotiated timeout 20000 for client /127.0.0.1:60092
[junit4:junit4]   2> 16529 T320 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c80000b, negotiated timeout = 20000
[junit4:junit4]   2> 16529 T321 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1791745 name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16530 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16532 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c80000b
[junit4:junit4]   2> 16532 T321 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16532 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60092 which had sessionid 0x13d9b5c5c80000b
[junit4:junit4]   2> 16532 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c80000b closed
[junit4:junit4]   2> 16533 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16537 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1739fef
[junit4:junit4]   2> 16538 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16538 T322 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16538 T322 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 16539 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60093
[junit4:junit4]   2> 16539 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60093
[junit4:junit4]   2> 16540 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c80000c with negotiated timeout 20000 for client /127.0.0.1:60093
[junit4:junit4]   2> 16540 T322 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c80000c, negotiated timeout = 20000
[junit4:junit4]   2> 16541 T323 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1739fef name:ZooKeeperConnection Watcher:127.0.0.1:60657/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16541 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16543 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16545 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16550 T232 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17230 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17232 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59230_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59230/b_jx/i",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 17241 T274 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> 17241 T290 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> 17241 T254 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> 17242 T323 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> 17241 T261 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> 17241 T306 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> 17432 T270 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&nodeName=127.0.0.1:59230_b_jx%252Fi&checkLive=true&action=PREPRECOVERY&wt=javabin&onlyIfLeader=true&state=recovering&core=collection1&coreNodeName=4} status=0 QTime=1003 
[junit4:junit4]   2> 17555 T232 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58159_b_jx%2Fi
[junit4:junit4]   2> 17557 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:58159_b_jx%2Fi Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:58159_b_jx%2Fi
[junit4:junit4]   2> 17559 T232 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58159_b_jx%2Fi
[junit4:junit4]   2> 17563 T261 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> 17563 T306 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> 17563 T290 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> 17564 T274 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17565 T274 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> 17565 T254 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17566 T254 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> 17566 T323 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17568 T323 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> 17568 T306 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17569 T290 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17570 T261 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17578 T324 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-1364111170716/collection1
[junit4:junit4]   2> 17579 T324 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17580 T324 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17581 T324 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17583 T324 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-1364111170716/collection1/'
[junit4:junit4]   2> 17584 T324 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-1364111170716/collection1/lib/README' to classloader
[junit4:junit4]   2> 17585 T324 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-1364111170716/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17611 T324 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 17644 T324 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17646 T324 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17650 T324 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17991 T324 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 18010 T324 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 18015 T324 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 18049 T324 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18054 T324 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18058 T324 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18060 T324 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18060 T324 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18060 T324 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18062 T324 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18062 T324 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18062 T324 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18062 T324 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-1364111170716/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/
[junit4:junit4]   2> 18063 T324 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 18063 T324 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18064 T324 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4
[junit4:junit4]   2> 18064 T324 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/index/
[junit4:junit4]   2> 18064 T324 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 18064 T324 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/index
[junit4:junit4]   2> 18066 T324 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1360130 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b2269a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18066 T324 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18070 T324 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 18070 T324 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 18071 T324 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 18072 T324 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 18073 T324 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 18073 T324 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 18074 T324 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 18074 T324 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 18075 T324 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18077 T324 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18079 T324 oass.SolrIndexSearcher.<init> Opening Searcher@fc9c15 main
[junit4:junit4]   2> 18079 T324 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/tlog
[junit4:junit4]   2> 18079 T324 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18079 T324 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18087 T325 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@fc9c15 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18091 T324 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18091 T324 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18753 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18755 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58159_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58159/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 18755 T255 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18756 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 18765 T306 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> 18765 T274 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> 18765 T290 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> 18765 T254 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> 18765 T323 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> 18765 T261 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> 19093 T324 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19094 T324 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58159/b_jx/i collection:collection1 shard:shard2
[junit4:junit4]   2> 19100 T324 oasc.ZkController.register We are http://127.0.0.1:58159/b_jx/i/collection1/ and leader is http://127.0.0.1:35506/b_jx/i/collection1/
[junit4:junit4]   2> 19101 T324 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58159/b_jx/i
[junit4:junit4]   2> 19101 T324 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19102 T324 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@16cb9b2 url=http://127.0.0.1:58159/b_jx/i/collection1 node=127.0.0.1:58159_b_jx%2Fi C20_STATE=coll:collection1 core:collection1 props:{collection=collection1, node_name=127.0.0.1:58159_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:58159/b_jx/i, state=down}
[junit4:junit4]   2> 19102 T326 C20 P58159 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19104 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19104 T324 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19104 T326 C20 P58159 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19105 T326 C20 P58159 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19107 T232 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19107 T326 C20 P58159 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19108 T232 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19109 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19117 T232 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19120 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19129 T268 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-1364111157914/onenodecollectioncore
[junit4:junit4]   2> 19130 T268 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19131 T268 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19132 T268 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19135 T268 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19135 T268 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19140 T268 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19143 T268 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-1364111157914/onenodecollectioncore/'
[junit4:junit4]   2> 19186 T268 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19222 T268 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19224 T268 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19227 T268 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C19_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, node_name=127.0.0.1:59230_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:59230/b_jx/i, state=recovering}
[junit4:junit4]   2> 19433 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59425/b_jx/i/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19436 T309 C19 P59230 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> 19441 T309 C19 P59230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59230/b_jx/i START replicas=[http://127.0.0.1:59425/b_jx/i/collection1/] nUpdates=100
[junit4:junit4]   2> 19442 T309 C19 P59230 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19442 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19443 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19443 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19443 T309 C19 P59230 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19444 T309 C19 P59230 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59425/b_jx/i/collection1/. core=collection1
[junit4:junit4]   2> 19444 T309 C19 P59230 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C21 name=collection1 org.apache.solr.core.SolrCore@1ab00f3 url=http://127.0.0.1:59425/b_jx/i/collection1 node=127.0.0.1:59425_b_jx%2Fi C21_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, node_name=127.0.0.1:59425_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:59425/b_jx/i, state=active, leader=true}
[junit4:junit4]   2> 19447 T270 C21 P59425 REQ /get {version=2&qt=/get&wt=javabin&getVersions=100&distrib=false} status=0 QTime=1 
[junit4:junit4]   2> 19449 T269 C21 P59425 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19456 T269 C21 P59425 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a6d008 lockFactory=org.apache.lucene.store.NativeFSLockFactory@179f5d3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19457 T269 C21 P59425 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19457 T269 C21 P59425 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a6d008 lockFactory=org.apache.lucene.store.NativeFSLockFactory@179f5d3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a6d008 lockFactory=org.apache.lucene.store.NativeFSLockFactory@179f5d3),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19458 T269 C21 P59425 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19458 T269 C21 P59425 oass.SolrIndexSearcher.<init> Opening Searcher@1657065 realtime
[junit4:junit4]   2> 19458 T269 C21 P59425 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19459 T269 C21 P59425 /update {version=2&commit=true&wt=javabin&softCommit=false&openSearcher=false&commit_end_point=true&waitSearcher=true} {commit=} 0 11
[junit4:junit4]   2> 19479 T309 C19 P59230 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19479 T309 C19 P59230 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> 19484 T309 C19 P59230 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19487 T267 C21 P59425 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19488 T267 C21 P59425 REQ /replication {version=2&qt=/replication&command=indexversion&wt=javabin} status=0 QTime=2 
[junit4:junit4]   2> 19489 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19489 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19490 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19492 T269 C21 P59425 REQ /replication {version=2&qt=/replication&command=filelist&wt=javabin&generation=2} status=0 QTime=1 
[junit4:junit4]   2> 19492 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19493 T309 C19 P59230 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty3/index.20130324014613787
[junit4:junit4]   2> 19494 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@69c23a lockFactory=org.apache.lucene.store.NativeFSLockFactory@e5ce88; maxCacheMB=0.6103515625 maxMergeSizeMB=0.7119140625)) fullCopy=false
[junit4:junit4]   2> 19500 T270 C21 P59425 REQ /replication {qt=/replication&checksum=true&command=filecontent&wt=filestream&generation=2&file=segments_2} status=0 QTime=2 
[junit4:junit4]   2> 19512 T309 C19 P59230 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19514 T309 C19 P59230 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19515 T309 C19 P59230 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19517 T309 C19 P59230 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d84de5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@163a9f5),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d84de5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@163a9f5),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19517 T309 C19 P59230 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19518 T309 C19 P59230 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19518 T309 C19 P59230 oass.SolrIndexSearcher.<init> Opening Searcher@1fd58cc main
[junit4:junit4]   2> 19519 T308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fd58cc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19520 T309 C19 P59230 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19520 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19520 T309 C19 P59230 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19520 T309 C19 P59230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19522 T309 C19 P59230 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19603 T268 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19609 T268 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19611 T268 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19630 T268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19635 T268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19638 T268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19640 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19640 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19640 T268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19642 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19642 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19642 T268 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19643 T268 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-1364111157914/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/
[junit4:junit4]   2> 19643 T268 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@13521f0
[junit4:junit4]   2> 19644 T268 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19644 T268 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection
[junit4:junit4]   2> 19645 T268 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-1364111154301/onenodecollection/index/
[junit4:junit4]   2> 19645 T268 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19645 T268 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/index
[junit4:junit4]   2> 19647 T268 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@752bf4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@107ec74),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19647 T268 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19649 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19649 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19650 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19650 T268 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19651 T268 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19651 T268 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19651 T268 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19652 T268 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19652 T268 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19654 T268 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19657 T268 oass.SolrIndexSearcher.<init> Opening Searcher@1953c35 main
[junit4:junit4]   2> 19657 T268 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/tlog
[junit4:junit4]   2> 19658 T268 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19658 T268 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19662 T330 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@1953c35 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19664 T268 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20276 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20278 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58159_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58159/b_jx/i",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 20286 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59230_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59230/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 20293 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 20293 T255 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20294 T255 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20309 T323 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> 20309 T261 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> 20309 T254 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> 20309 T306 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> 20309 T290 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> 20309 T274 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> 20666 T268 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20667 T268 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:59425/b_jx/i collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20668 T268 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20684 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 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> 20685 T268 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20686 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20691 T268 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20692 T268 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20692 T268 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59425/b_jx/i/onenodecollectioncore/
[junit4:junit4]   2> 20693 T268 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20693 T268 oasc.SyncStrategy.syncToMe http://127.0.0.1:59425/b_jx/i/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20694 T268 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59425/b_jx/i/onenodecollectioncore/
[junit4:junit4]   2> 20695 T268 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20703 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21118 T283 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&nodeName=127.0.0.1:58159_b_jx%252Fi&checkLive=true&action=PREPRECOVERY&wt=javabin&onlyIfLeader=true&state=recovering&core=collection1&coreNodeName=5} status=0 QTime=2000 
[junit4:junit4]   2> 21830 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21859 T274 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> 21859 T306 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> 21859 T290 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> 21859 T261 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> 21859 T254 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> 21859 T323 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> 21864 T268 oasc.ZkController.register We are http://127.0.0.1:59425/b_jx/i/onenodecollectioncore/ and leader is http://127.0.0.1:59425/b_jx/i/onenodecollectioncore/
[junit4:junit4]   2> 21865 T268 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:59425/b_jx/i
[junit4:junit4]   2> 21866 T268 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21866 T268 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21870 T268 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21872 T268 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&collection=onenodecollection&roles=none&action=CREATE&numShards=1&wt=javabin&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection&name=onenodecollectioncore} status=0 QTime=2743 
[junit4:junit4]   2> 21873 T232 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21875 T232 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22879 T232 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C20_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard2, node_name=127.0.0.1:58159_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:58159/b_jx/i, state=recovering}
[junit4:junit4]   2> 23120 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35506/b_jx/i/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23121 T326 C20 P58159 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58159/b_jx/i START replicas=[http://127.0.0.1:35506/b_jx/i/collection1/] nUpdates=100
[junit4:junit4]   2> 23121 T326 C20 P58159 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23122 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23122 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23123 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23124 T326 C20 P58159 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23124 T326 C20 P58159 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35506/b_jx/i/collection1/. core=collection1
[junit4:junit4]   2> 23125 T326 C20 P58159 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C22 name=collection1 org.apache.solr.core.SolrCore@135ddc9 url=http://127.0.0.1:35506/b_jx/i/collection1 node=127.0.0.1:35506_b_jx%2Fi C22_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard2, node_name=127.0.0.1:35506_b_jx%2Fi, core=collection1, base_url=http://127.0.0.1:35506/b_jx/i, state=active, leader=true}
[junit4:junit4]   2> 23130 T284 C22 P35506 REQ /get {version=2&qt=/get&wt=javabin&getVersions=100&distrib=false} status=0 QTime=0 
[junit4:junit4]   2> 23134 T283 C22 P35506 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23135 T283 C22 P35506 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1442690 lockFactory=org.apache.lucene.store.NativeFSLockFactory@161402b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 23136 T283 C22 P35506 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 23136 T283 C22 P35506 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1442690 lockFactory=org.apache.lucene.store.NativeFSLockFactory@161402b),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1442690 lockFactory=org.apache.lucene.store.NativeFSLockFactory@161402b),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23136 T283 C22 P35506 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23137 T283 C22 P35506 oass.SolrIndexSearcher.<init> Opening Searcher@1139539 realtime
[junit4:junit4]   2> 23137 T283 C22 P35506 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23138 T283 C22 P35506 /update {version=2&commit=true&wt=javabin&softCommit=false&openSearcher=false&commit_end_point=true&waitSearcher=true} {commit=} 0 4
[junit4:junit4]   2> 23138 T326 C20 P58159 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23139 T326 C20 P58159 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23141 T285 C22 P35506 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23141 T285 C22 P35506 REQ /replication {version=2&qt=/replication&command=indexversion&wt=javabin} status=0 QTime=1 
[junit4:junit4]   2> 23142 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 23142 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23142 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23145 T284 C22 P35506 REQ /replication {version=2&qt=/replication&command=filelist&wt=javabin&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 23146 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23147 T326 C20 P58159 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty4/index.20130324014617440
[junit4:junit4]   2> 23148 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@14897d3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@166afee; maxCacheMB=0.6103515625 maxMergeSizeMB=0.7119140625)) fullCopy=false
[junit4:junit4]   2> 23151 T283 C22 P35506 REQ /replication {qt=/replication&checksum=true&command=filecontent&wt=filestream&generation=2&file=segments_2} status=0 QTime=0 
[junit4:junit4]   2> 23154 T326 C20 P58159 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23156 T326 C20 P58159 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23156 T326 C20 P58159 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23158 T326 C20 P58159 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1360130 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b2269a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1360130 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b2269a),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23159 T326 C20 P58159 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23159 T326 C20 P58159 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23160 T326 C20 P58159 oass.SolrIndexSearcher.<init> Opening Searcher@766ada main
[junit4:junit4]   2> 23162 T325 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@766ada main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 23163 T326 C20 P58159 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23163 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23163 T326 C20 P58159 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23164 T326 C20 P58159 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23166 T326 C20 P58159 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23374 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23376 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:59425_b_jx%2Fi_onenodecollectioncore",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 23383 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:58159_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:58159/b_jx/i",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 23416 T290 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> 23416 T323 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> 23416 T274 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> 23416 T306 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> 23417 T261 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> 23416 T254 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> 23883 T232 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23885 T232 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23886 T232 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23906 T232 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:60657 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1ae66a
[junit4:junit4]   2> 23908 T333 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:60657. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23908 T232 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23909 T333 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:60657, initiating session
[junit4:junit4]   2> 23909 T234 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:60123
[junit4:junit4]   2> 23910 T234 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:60123
[junit4:junit4]   2> 23912 T236 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9b5c5c80000d with negotiated timeout 10000 for client /127.0.0.1:60123
[junit4:junit4]   2> 23912 T333 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:60657, sessionid = 0x13d9b5c5c80000d, negotiated timeout = 10000
[junit4:junit4]   2> 23913 T334 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ae66a name:ZooKeeperConnection Watcher:127.0.0.1:60657 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23913 T232 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 24020 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c80000d
[junit4:junit4]   2> 24021 T334 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24021 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c80000d closed
[junit4:junit4]   2> 24021 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60123 which had sessionid 0x13d9b5c5c80000d
[junit4:junit4]   2> 24022 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800004
[junit4:junit4]   2> 24024 T261 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 24023 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800004 closed
[junit4:junit4]   2> 24024 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60070 which had sessionid 0x13d9b5c5c800004
[junit4:junit4]   2> 24029 T232 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 57386
[junit4:junit4]   2> 24030 T232 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=29588577
[junit4:junit4]   2> 24932 T255 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24934 T255 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57386_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57386/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 24959 T323 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> 24959 T274 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> 24959 T290 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> 24959 T306 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> 24959 T254 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> 26033 T232 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 26034 T232 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 26038 T232 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@24d1e4
[junit4:junit4]   2> 26047 T232 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> 26048 T232 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 26048 T232 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 26049 T232 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 26050 T232 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 26051 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/index
[junit4:junit4]   2> 26051 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data/index
[junit4:junit4]   2> 26052 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data
[junit4:junit4]   2> 26053 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/control/data
[junit4:junit4]   2> 26054 T255 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89398388608466947-127.0.0.1:57386_b_jx%2Fi-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 26056 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800003
[junit4:junit4]   2> 26057 T274 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> 26057 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800003 closed
[junit4:junit4]   2> 26058 T290 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26059 T290 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> 26058 T234 oazs.NIOServerCnxn.doIO WARNING caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13d9b5c5c800003, 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> 26058 T306 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26060 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60066 which had sessionid 0x13d9b5c5c800003
[junit4:junit4]   2> 26060 T306 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> 26061 T323 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26061 T323 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> 26064 T274 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 26066 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 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> 26067 T274 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 26073 T274 oasc.Overseer.start Overseer (id=89398388608466950-127.0.0.1:59425_b_jx%2Fi-n_0000000001) starting
[junit4:junit4]   2> 26074 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xce zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26076 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xcf zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26079 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xd1 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26082 T232 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/b_jx/i,null}
[junit4:junit4]   2> 26083 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800006 type:create cxid:0xd3 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 26086 T336 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 26088 T335 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 26091 T335 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 26093 T335 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57386_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57386/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 26101 T323 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> 26101 T290 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> 26101 T274 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> 26101 T306 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> 26134 T232 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 59425
[junit4:junit4]   2> 26135 T232 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=15087408
[junit4:junit4]   2> 27358 T254 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 27358 T254 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> 27358 T254 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 27359 T254 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27611 T335 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27613 T335 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:59425_b_jx%2Fi_onenodecollectioncore",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 27620 T335 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:59425_b_jx%2Fi",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:59425/b_jx/i",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state"}
[junit4:junit4]   2> 27629 T323 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> 27629 T290 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> 27629 T274 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> 27629 T306 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> 29139 T232 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 29140 T232 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 29143 T232 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 29147 T232 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@1ab00f3
[junit4:junit4]   2> 29154 T232 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> 29154 T232 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29155 T232 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29155 T232 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29158 T232 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 29159 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/index
[junit4:junit4]   2> 29160 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1/index
[junit4:junit4]   2> 29160 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1
[junit4:junit4]   2> 29161 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1364111154300/jetty1
[junit4:junit4]   2> 29162 T232 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@140ab2d
[junit4:junit4]   2> 29172 T232 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> 29173 T232 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29174 T232 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29174 T232 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29175 T232 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 29175 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/index
[junit4:junit4]   2> 29175 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection/index
[junit4:junit4]   2> 29176 T232 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection
[junit4:junit4]   2> 29176 T232 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1364111154301/onenodecollection
[junit4:junit4]   2> 29177 T335 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89398388608466950-127.0.0.1:59425_b_jx%2Fi-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 29178 T237 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9b5c5c800006
[junit4:junit4]   2> 29179 T234 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:60072 which had sessionid 0x13d9b5c5c800006
[junit4:junit4]   2> 29179 T290 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29179 T232 oaz.ZooKeeper.close Session: 0x13d9b5c5c800006 closed
[junit4:junit4]   2> 29180 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000a type:delete cxid:0x5e zxid:0xf9 txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 29179 T323 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29180 T290 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> 29180 T323 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> 29181 T306 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 29182 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c80000a type:create cxid:0x5f zxid:0xfa txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29184 T237 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9b5c5c800008 type:delete cxid:0x7f zxid:0xfb txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 29184 T290 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 29185 T306 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 29185 T306 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 29185 T306 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 29186 T306 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59230/b_jx/i/collection1/
[junit4:junit4]   2> 29186 T306 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59230/b_jx/i START replicas=[http://127.0.0.1:59425/b_jx/i/collection1/] nUpdates=100
[junit4:junit4]   2> 29187 T306 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59230/b_jx/i DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 29187 T306 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 29188 T306 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> 29188 T290 oasc.Overseer.start Overseer (id=89398388608466952-127.0.0.1:35506_b_jx%2Fi-n_0000000002) starting
[junit4:junit4]   2> 29188 T306 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59230/b_jx/i/collection1/
[junit4:junit4]   2> 

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

on (0)
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=685AC33CC8D74261 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=lt -Dtests.timezone=Mexico/General -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR   32.7s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.common.SolrException: Server at http://127.0.0.1:35506/b_jx/i/onenodecollectioncore returned non ok status:404, message:Can not find: /b_jx/i/onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([685AC33CC8D74261:E9BC4D24BF88225D]: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> 32659 T232 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 32662 T231 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4]   2> 32699 T306 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 32699 T306 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> 32700 T306 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 32700 T306 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 32706 T235 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 33812 T323 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33812 T323 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> 33813 T323 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33813 T323 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=HighCompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=295), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=HIGH_COMPRESSION, chunkSize=295)), sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=lt, timezone=Mexico/General
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=3,free=47558888,total=100663296
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestBM25SimilarityFactory, SolrRequestParserTest, IndexSchemaRuntimeFieldTest, SampleTest, SuggesterWFSTTest, TestDynamicFieldResource, ConvertedLegacyTest, BasicZkTest, BadIndexSchemaTest, TestElisionMultitermQuery, TestLMJelinekMercerSimilarityFactory, TestDistributedSearch, SortByFunctionTest, TestOmitPositions, TestSolrJ, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.95s, 1 test, 1 error <<< FAILURES!

[...truncated 721 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: 37 minutes 29 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:+UseG1GC -XX:MarkStackSize=256K
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message