lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.8.0-ea-b79) - Build # 4559 - Failure!
Date Wed, 06 Mar 2013 05:18:41 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4559/
Java: 64bit/jdk1.8.0-ea-b79 -XX:+UseParallelGC

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

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

Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:39160/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([E184245560913A05:6062AA4D17CE5A39]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:85)
	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 9142 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 1 T895 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 3 T895 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665
[junit4:junit4]   2> 4 T895 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 4 T896 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 5 T896 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 5 T896 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 5 T896 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 6 T896 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 6 T896 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 104 T895 oasc.ZkTestServer.run start zk server on port:50085
[junit4:junit4]   2> 105 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@18158f31
[junit4:junit4]   2> 106 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 106 T901 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 107 T901 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 107 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46721
[junit4:junit4]   2> 107 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46721
[junit4:junit4]   2> 108 T899 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 131 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0000 with negotiated timeout 10000 for client /127.0.0.1:46721
[junit4:junit4]   2> 131 T901 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0000, negotiated timeout = 10000
[junit4:junit4]   2> 132 T902 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18158f31 name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 132 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 132 T895 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 136 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0000
[junit4:junit4]   2> 137 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46721 which had sessionid 0x13d3e1b136c0000
[junit4:junit4]   2> 137 T902 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 137 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0000 closed
[junit4:junit4]   2> 137 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@16d27243
[junit4:junit4]   2> 138 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 138 T903 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 139 T903 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 139 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46722
[junit4:junit4]   2> 139 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46722
[junit4:junit4]   2> 140 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0001 with negotiated timeout 10000 for client /127.0.0.1:46722
[junit4:junit4]   2> 140 T903 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0001, negotiated timeout = 10000
[junit4:junit4]   2> 140 T904 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16d27243 name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 141 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 141 T895 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 145 T895 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 147 T895 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 149 T895 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 152 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 153 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 157 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 158 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 161 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 162 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 167 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 167 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 170 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 171 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 174 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 175 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 177 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 178 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 181 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 181 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 185 T895 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 186 T895 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 190 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0001
[junit4:junit4]   2> 191 T904 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 191 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0001 closed
[junit4:junit4]   2> 191 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46722 which had sessionid 0x13d3e1b136c0001
[junit4:junit4]   2> 274 T895 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 280 T895 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57432
[junit4:junit4]   2> 281 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 281 T895 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 281 T895 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852
[junit4:junit4]   2> 281 T895 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/solr.xml
[junit4:junit4]   2> 282 T895 oasc.CoreContainer.<init> New CoreContainer 4459078
[junit4:junit4]   2> 282 T895 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/'
[junit4:junit4]   2> 282 T895 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/'
[junit4:junit4]   2> 298 T895 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 299 T895 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 299 T895 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 299 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 300 T895 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 300 T895 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 300 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 300 T895 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 301 T895 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 301 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 307 T895 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 316 T895 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50085/solr
[junit4:junit4]   2> 316 T895 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 317 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2b2e9cb5
[junit4:junit4]   2> 317 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 317 T914 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 318 T914 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 318 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46723
[junit4:junit4]   2> 318 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46723
[junit4:junit4]   2> 319 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0002 with negotiated timeout 20000 for client /127.0.0.1:46723
[junit4:junit4]   2> 319 T914 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0002, negotiated timeout = 20000
[junit4:junit4]   2> 320 T915 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b2e9cb5 name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 320 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 321 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0002
[junit4:junit4]   2> 321 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46723 which had sessionid 0x13d3e1b136c0002
[junit4:junit4]   2> 321 T915 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 321 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0002 closed
[junit4:junit4]   2> 322 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 325 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@40f8d251
[junit4:junit4]   2> 325 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 325 T916 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 326 T916 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 326 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46724
[junit4:junit4]   2> 326 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46724
[junit4:junit4]   2> 327 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0003 with negotiated timeout 20000 for client /127.0.0.1:46724
[junit4:junit4]   2> 327 T916 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0003, negotiated timeout = 20000
[junit4:junit4]   2> 327 T917 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40f8d251 name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 327 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 329 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 330 T895 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 331 T895 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57432_
[junit4:junit4]   2> 332 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:57432_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:57432_
[junit4:junit4]   2> 332 T895 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57432_
[junit4:junit4]   2> 335 T895 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 338 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 338 T895 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 341 T895 oasc.Overseer.start Overseer (id=89295853628162051-127.0.0.1:57432_-n_0000000000) starting
[junit4:junit4]   2> 341 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 342 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 342 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 343 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 344 T919 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 344 T895 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 346 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 347 T918 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 350 T920 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/collection1
[junit4:junit4]   2> 350 T920 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 350 T920 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 351 T920 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 351 T920 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/collection1/'
[junit4:junit4]   2> 352 T920 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/collection1/lib/README' to classloader
[junit4:junit4]   2> 352 T920 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 380 T920 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 408 T920 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 409 T920 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 412 T920 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 700 T920 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 705 T920 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 707 T920 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 719 T920 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 722 T920 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 725 T920 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 726 T920 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 726 T920 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 727 T920 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 727 T920 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 728 T920 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 728 T920 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362546594852/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/
[junit4:junit4]   2> 728 T920 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 728 T920 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 734 T920 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data forceNew:false
[junit4:junit4]   2> 735 T920 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data
[junit4:junit4]   2> 735 T920 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index/
[junit4:junit4]   2> 735 T920 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 735 T920 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index forceNew:false
[junit4:junit4]   2> 739 T920 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 739 T920 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 740 T920 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index
[junit4:junit4]   2> 741 T920 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 741 T920 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 742 T920 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 742 T920 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 742 T920 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 742 T920 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 743 T920 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 743 T920 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 743 T920 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 745 T920 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 747 T920 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data
[junit4:junit4]   2> 748 T920 oass.SolrIndexSearcher.<init> Opening Searcher@74ba075 main
[junit4:junit4]   2> 748 T920 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 749 T920 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 751 T920 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data
[junit4:junit4]   2> 752 T921 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@74ba075 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 752 T920 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 752 T920 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 753 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 1850 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1851 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57432_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57432"}
[junit4:junit4]   2> 1851 T918 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1851 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1852 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 1855 T917 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> 2755 T920 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2755 T920 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57432 collection:control_collection shard:shard1
[junit4:junit4]   2> 2756 T920 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2762 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2762 T920 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2763 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2764 T920 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2764 T920 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2764 T920 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57432/collection1/
[junit4:junit4]   2> 2764 T920 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2764 T920 oasc.SyncStrategy.syncToMe http://127.0.0.1:57432/collection1/ has no replicas
[junit4:junit4]   2> 2765 T920 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57432/collection1/
[junit4:junit4]   2> 2765 T920 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2767 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3359 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3368 T917 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> 3420 T920 oasc.ZkController.register We are http://127.0.0.1:57432/collection1/ and leader is http://127.0.0.1:57432/collection1/
[junit4:junit4]   2> 3420 T920 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57432
[junit4:junit4]   2> 3420 T920 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3421 T920 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3421 T920 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3423 T920 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3424 T895 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3424 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3424 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3430 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3431 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@5bdad440
[junit4:junit4]   2> 3432 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3432 T922 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3433 T922 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 3433 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46725
[junit4:junit4]   2> 3433 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46725
[junit4:junit4]   2> 3434 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0004 with negotiated timeout 10000 for client /127.0.0.1:46725
[junit4:junit4]   2> 3434 T922 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0004, negotiated timeout = 10000
[junit4:junit4]   2> 3435 T923 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bdad440 name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3435 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3436 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3438 T895 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3495 T895 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3497 T895 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34452
[junit4:junit4]   2> 3498 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3498 T895 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3499 T895 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099
[junit4:junit4]   2> 3499 T895 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/solr.xml
[junit4:junit4]   2> 3499 T895 oasc.CoreContainer.<init> New CoreContainer 2147454478
[junit4:junit4]   2> 3500 T895 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/'
[junit4:junit4]   2> 3500 T895 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/'
[junit4:junit4]   2> 3519 T895 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3519 T895 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3519 T895 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3520 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3520 T895 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3520 T895 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3521 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3521 T895 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3521 T895 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3522 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3528 T895 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3538 T895 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50085/solr
[junit4:junit4]   2> 3539 T895 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3539 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ee2739e
[junit4:junit4]   2> 3540 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3540 T933 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3541 T933 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 3541 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46726
[junit4:junit4]   2> 3541 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46726
[junit4:junit4]   2> 3542 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0005 with negotiated timeout 20000 for client /127.0.0.1:46726
[junit4:junit4]   2> 3542 T933 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0005, negotiated timeout = 20000
[junit4:junit4]   2> 3542 T934 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ee2739e name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3543 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3544 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0005
[junit4:junit4]   2> 3545 T934 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3545 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46726 which had sessionid 0x13d3e1b136c0005
[junit4:junit4]   2> 3545 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0005 closed
[junit4:junit4]   2> 3545 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3548 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1a838fac
[junit4:junit4]   2> 3549 T935 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3550 T935 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 3550 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46727
[junit4:junit4]   2> 3550 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46727
[junit4:junit4]   2> 3551 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3551 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0006 with negotiated timeout 20000 for client /127.0.0.1:46727
[junit4:junit4]   2> 3552 T935 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0006, negotiated timeout = 20000
[junit4:junit4]   2> 3552 T936 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a838fac name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3552 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3553 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3554 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3555 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4557 T895 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34452_
[junit4:junit4]   2> 4558 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:34452_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:34452_
[junit4:junit4]   2> 4559 T895 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34452_
[junit4:junit4]   2> 4566 T917 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4567 T917 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> 4567 T923 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4568 T936 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4575 T937 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/collection1
[junit4:junit4]   2> 4575 T937 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4576 T937 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4576 T937 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4578 T937 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/collection1/'
[junit4:junit4]   2> 4578 T937 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/collection1/lib/README' to classloader
[junit4:junit4]   2> 4579 T937 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4620 T937 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 4655 T937 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4656 T937 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4660 T937 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4874 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4875 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57432_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57432"}
[junit4:junit4]   2> 4878 T923 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> 4878 T917 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> 4878 T936 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> 4966 T937 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4972 T937 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4974 T937 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 4986 T937 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4989 T937 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4992 T937 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4993 T937 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 4993 T937 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 4994 T937 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4995 T937 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 4995 T937 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 4995 T937 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/
[junit4:junit4]   2> 4995 T937 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 4996 T937 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 4996 T937 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1 forceNew:false
[junit4:junit4]   2> 4996 T937 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1
[junit4:junit4]   2> 4996 T937 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index/
[junit4:junit4]   2> 4997 T937 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 4997 T937 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index forceNew:false
[junit4:junit4]   2> 5000 T937 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5000 T937 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5001 T937 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index
[junit4:junit4]   2> 5002 T937 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5002 T937 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5003 T937 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5003 T937 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5003 T937 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5003 T937 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5004 T937 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5004 T937 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5004 T937 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5006 T937 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5008 T937 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1
[junit4:junit4]   2> 5009 T937 oass.SolrIndexSearcher.<init> Opening Searcher@342fe24e main
[junit4:junit4]   2> 5010 T937 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5010 T937 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5013 T938 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@342fe24e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5014 T937 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5015 T937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6382 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6383 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4]   2> 6383 T918 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6383 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6387 T917 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> 6387 T923 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> 6387 T936 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> 7016 T937 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7017 T937 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34452 collection:collection1 shard:shard1
[junit4:junit4]   2> 7018 T937 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7024 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:delete cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7025 T937 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7025 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7027 T937 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7028 T937 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7028 T937 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34452/collection1/
[junit4:junit4]   2> 7028 T937 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7028 T937 oasc.SyncStrategy.syncToMe http://127.0.0.1:34452/collection1/ has no replicas
[junit4:junit4]   2> 7028 T937 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34452/collection1/
[junit4:junit4]   2> 7029 T937 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7033 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7891 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7898 T917 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> 7898 T923 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> 7898 T936 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> 7937 T937 oasc.ZkController.register We are http://127.0.0.1:34452/collection1/ and leader is http://127.0.0.1:34452/collection1/
[junit4:junit4]   2> 7937 T937 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34452
[junit4:junit4]   2> 7937 T937 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 7938 T937 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 7938 T937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7940 T937 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7941 T895 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 7941 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 7942 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8033 T895 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8036 T895 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39160
[junit4:junit4]   2> 8037 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8037 T895 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8038 T895 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608
[junit4:junit4]   2> 8038 T895 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/solr.xml
[junit4:junit4]   2> 8039 T895 oasc.CoreContainer.<init> New CoreContainer 1688764095
[junit4:junit4]   2> 8039 T895 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/'
[junit4:junit4]   2> 8040 T895 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/'
[junit4:junit4]   2> 8062 T895 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8063 T895 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8063 T895 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8063 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8064 T895 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8064 T895 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8064 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8064 T895 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8065 T895 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8065 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8071 T895 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8079 T895 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50085/solr
[junit4:junit4]   2> 8080 T895 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8080 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@43cf205f
[junit4:junit4]   2> 8081 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8081 T948 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8082 T948 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 8082 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46728
[junit4:junit4]   2> 8082 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46728
[junit4:junit4]   2> 8083 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0007 with negotiated timeout 20000 for client /127.0.0.1:46728
[junit4:junit4]   2> 8083 T948 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0007, negotiated timeout = 20000
[junit4:junit4]   2> 8083 T949 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43cf205f name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8084 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8085 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0007
[junit4:junit4]   2> 8086 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46728 which had sessionid 0x13d3e1b136c0007
[junit4:junit4]   2> 8086 T949 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8086 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0007 closed
[junit4:junit4]   2> 8086 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8089 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4cb0dd11
[junit4:junit4]   2> 8090 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8091 T950 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8091 T950 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 8091 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46729
[junit4:junit4]   2> 8092 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46729
[junit4:junit4]   2> 8095 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0008 with negotiated timeout 20000 for client /127.0.0.1:46729
[junit4:junit4]   2> 8095 T950 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0008, negotiated timeout = 20000
[junit4:junit4]   2> 8095 T951 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cb0dd11 name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8095 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8097 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8097 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8099 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9102 T895 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39160_
[junit4:junit4]   2> 9103 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39160_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39160_
[junit4:junit4]   2> 9103 T895 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39160_
[junit4:junit4]   2> 9106 T923 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> 9106 T951 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9106 T936 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9106 T936 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> 9107 T917 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9107 T917 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> 9108 T923 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9112 T952 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/collection1
[junit4:junit4]   2> 9112 T952 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9113 T952 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9113 T952 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9114 T952 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/collection1/'
[junit4:junit4]   2> 9115 T952 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/collection1/lib/README' to classloader
[junit4:junit4]   2> 9115 T952 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9138 T952 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 9175 T952 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9176 T952 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9179 T952 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9408 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9409 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4]   2> 9413 T917 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> 9413 T923 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> 9413 T951 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> 9413 T936 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> 9493 T952 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9498 T952 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9501 T952 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9523 T952 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9526 T952 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9530 T952 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9531 T952 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9531 T952 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9531 T952 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9532 T952 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9533 T952 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9533 T952 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362546602608/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/
[junit4:junit4]   2> 9533 T952 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 9534 T952 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 9534 T952 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2 forceNew:false
[junit4:junit4]   2> 9535 T952 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2
[junit4:junit4]   2> 9535 T952 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index/
[junit4:junit4]   2> 9535 T952 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9536 T952 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index forceNew:false
[junit4:junit4]   2> 9539 T952 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9540 T952 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9540 T952 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index
[junit4:junit4]   2> 9542 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9543 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9543 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9544 T952 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9544 T952 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9545 T952 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9545 T952 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9545 T952 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9546 T952 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9549 T952 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9552 T952 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2
[junit4:junit4]   2> 9553 T952 oass.SolrIndexSearcher.<init> Opening Searcher@526a47b3 main
[junit4:junit4]   2> 9554 T952 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9554 T952 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9558 T953 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@526a47b3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9561 T952 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9561 T952 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10918 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10918 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39160_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39160"}
[junit4:junit4]   2> 10919 T918 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 10919 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 10923 T923 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> 10923 T936 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> 10923 T951 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> 10923 T917 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> 11563 T952 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11563 T952 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39160 collection:collection1 shard:shard2
[junit4:junit4]   2> 11564 T952 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 11569 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:delete cxid:0x45 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 11570 T952 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11570 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:create cxid:0x46 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11572 T952 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11572 T952 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11572 T952 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39160/collection1/
[junit4:junit4]   2> 11572 T952 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11572 T952 oasc.SyncStrategy.syncToMe http://127.0.0.1:39160/collection1/ has no replicas
[junit4:junit4]   2> 11572 T952 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39160/collection1/
[junit4:junit4]   2> 11573 T952 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 11577 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0008 type:create cxid:0x4f zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12428 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12435 T923 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> 12435 T936 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> 12435 T917 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> 12435 T951 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12485 T952 oasc.ZkController.register We are http://127.0.0.1:39160/collection1/ and leader is http://127.0.0.1:39160/collection1/
[junit4:junit4]   2> 12485 T952 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39160
[junit4:junit4]   2> 12485 T952 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12485 T952 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12485 T952 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12488 T952 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12489 T895 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12489 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12489 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12545 T895 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12548 T895 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42313
[junit4:junit4]   2> 12548 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12549 T895 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12549 T895 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154
[junit4:junit4]   2> 12549 T895 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/solr.xml
[junit4:junit4]   2> 12549 T895 oasc.CoreContainer.<init> New CoreContainer 792384415
[junit4:junit4]   2> 12550 T895 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/'
[junit4:junit4]   2> 12550 T895 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/'
[junit4:junit4]   2> 12566 T895 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12567 T895 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12567 T895 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12567 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12567 T895 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12568 T895 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12568 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12568 T895 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12569 T895 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12569 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12575 T895 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12584 T895 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50085/solr
[junit4:junit4]   2> 12584 T895 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12584 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@6988456c
[junit4:junit4]   2> 12585 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12585 T963 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12586 T963 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 12586 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46731
[junit4:junit4]   2> 12587 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46731
[junit4:junit4]   2> 12587 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c0009 with negotiated timeout 20000 for client /127.0.0.1:46731
[junit4:junit4]   2> 12587 T963 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c0009, negotiated timeout = 20000
[junit4:junit4]   2> 12588 T964 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6988456c name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12588 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12590 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0009
[junit4:junit4]   2> 12590 T964 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12590 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46731 which had sessionid 0x13d3e1b136c0009
[junit4:junit4]   2> 12590 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0009 closed
[junit4:junit4]   2> 12591 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12596 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@74c7786f
[junit4:junit4]   2> 12597 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12597 T965 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12598 T965 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 12598 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46732
[junit4:junit4]   2> 12598 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46732
[junit4:junit4]   2> 12599 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c000a with negotiated timeout 20000 for client /127.0.0.1:46732
[junit4:junit4]   2> 12599 T965 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c000a, negotiated timeout = 20000
[junit4:junit4]   2> 12599 T966 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74c7786f name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12599 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12601 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000a type:create cxid:0x1 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12602 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000a type:create cxid:0x2 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12603 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13606 T895 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42313_
[junit4:junit4]   2> 13607 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000a type:delete cxid:0x9 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:42313_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:42313_
[junit4:junit4]   2> 13608 T895 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42313_
[junit4:junit4]   2> 13610 T923 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> 13610 T951 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> 13612 T936 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13612 T936 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> 13612 T917 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13612 T917 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> 13613 T966 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13614 T951 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13614 T923 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13619 T967 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/collection1
[junit4:junit4]   2> 13619 T967 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13620 T967 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13620 T967 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13621 T967 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/collection1/'
[junit4:junit4]   2> 13622 T967 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/collection1/lib/README' to classloader
[junit4:junit4]   2> 13622 T967 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13644 T967 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 13670 T967 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13671 T967 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13674 T967 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 13941 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13942 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39160_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39160"}
[junit4:junit4]   2> 13947 T966 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> 13947 T923 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> 13947 T936 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> 13947 T951 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> 13948 T917 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> 13979 T967 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 13985 T967 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 13987 T967 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 13999 T967 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14002 T967 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14006 T967 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14007 T967 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14010 T967 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14010 T967 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14012 T967 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14012 T967 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14012 T967 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362546607154/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/
[junit4:junit4]   2> 14012 T967 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 14013 T967 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 14014 T967 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3 forceNew:false
[junit4:junit4]   2> 14014 T967 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 14014 T967 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index/
[junit4:junit4]   2> 14015 T967 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14015 T967 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index forceNew:false
[junit4:junit4]   2> 14019 T967 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14019 T967 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14020 T967 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index
[junit4:junit4]   2> 14022 T967 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14022 T967 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14023 T967 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14024 T967 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14024 T967 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14025 T967 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14025 T967 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14025 T967 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14026 T967 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14030 T967 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14033 T967 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 14034 T967 oass.SolrIndexSearcher.<init> Opening Searcher@7399af24 main
[junit4:junit4]   2> 14035 T967 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14035 T967 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14039 T968 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7399af24 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14040 T967 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14041 T967 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15452 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15453 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42313_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42313"}
[junit4:junit4]   2> 15453 T918 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15454 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 15457 T917 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> 15458 T923 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> 15458 T936 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> 15457 T966 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> 15457 T951 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> 16042 T967 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16042 T967 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42313 collection:collection1 shard:shard1
[junit4:junit4]   2> 16045 T967 oasc.ZkController.register We are http://127.0.0.1:42313/collection1/ and leader is http://127.0.0.1:34452/collection1/
[junit4:junit4]   2> 16046 T967 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42313
[junit4:junit4]   2> 16046 T967 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16046 T967 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C68 name=collection1 org.apache.solr.core.SolrCore@3aa9bbf3 url=http://127.0.0.1:42313/collection1 node=127.0.0.1:42313_ C68_STATE=coll:collection1 core:collection1 props:{collection=collection1, core=collection1, node_name=127.0.0.1:42313_, state=down, base_url=http://127.0.0.1:42313}
[junit4:junit4]   2> 16047 T969 C68 P42313 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16047 T967 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16048 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16048 T969 C68 P42313 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16049 T969 C68 P42313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16049 T895 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16049 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16050 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16050 T969 C68 P42313 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16115 T895 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16117 T895 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47966
[junit4:junit4]   2> 16118 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16118 T895 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16118 T895 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714
[junit4:junit4]   2> 16119 T895 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/solr.xml
[junit4:junit4]   2> 16119 T895 oasc.CoreContainer.<init> New CoreContainer 285880834
[junit4:junit4]   2> 16119 T895 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/'
[junit4:junit4]   2> 16120 T895 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/'
[junit4:junit4]   2> 16142 T895 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16143 T895 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16143 T895 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16143 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16144 T895 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16144 T895 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16145 T895 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16145 T895 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16146 T895 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16146 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16156 T895 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16170 T895 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50085/solr
[junit4:junit4]   2> 16171 T895 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16171 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4fcacb11
[junit4:junit4]   2> 16172 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16172 T979 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16173 T979 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 16173 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46734
[junit4:junit4]   2> 16173 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46734
[junit4:junit4]   2> 16174 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c000b with negotiated timeout 20000 for client /127.0.0.1:46734
[junit4:junit4]   2> 16174 T979 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c000b, negotiated timeout = 20000
[junit4:junit4]   2> 16174 T980 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4fcacb11 name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16175 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16176 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c000b
[junit4:junit4]   2> 16177 T980 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16177 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46734 which had sessionid 0x13d3e1b136c000b
[junit4:junit4]   2> 16176 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c000b closed
[junit4:junit4]   2> 16177 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16180 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@226d9ae7
[junit4:junit4]   2> 16181 T981 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16181 T981 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 16182 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16182 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46735
[junit4:junit4]   2> 16183 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46735
[junit4:junit4]   2> 16183 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c000c with negotiated timeout 20000 for client /127.0.0.1:46735
[junit4:junit4]   2> 16183 T981 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c000c, negotiated timeout = 20000
[junit4:junit4]   2> 16184 T982 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@226d9ae7 name:ZooKeeperConnection Watcher:127.0.0.1:50085/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16184 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16185 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000c type:create cxid:0x1 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16185 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000c type:create cxid:0x2 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16186 T895 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 16962 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16963 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42313_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42313"}
[junit4:junit4]   2> 16967 T936 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> 16967 T923 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> 16968 T951 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> 16967 T966 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> 16967 T982 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> 16968 T917 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> 17189 T895 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47966_
[junit4:junit4]   2> 17190 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c000c type:delete cxid:0xb zxid:0xa8 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:47966_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:47966_
[junit4:junit4]   2> 17190 T895 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47966_
[junit4:junit4]   2> 17192 T917 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> 17193 T936 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> 17193 T923 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17193 T923 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> 17193 T951 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17193 T966 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17193 T951 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> 17194 T966 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> 17194 T982 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17194 T982 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> 17195 T917 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17196 T936 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17201 T983 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/collection1
[junit4:junit4]   2> 17202 T983 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17202 T983 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17202 T983 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17203 T983 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/collection1/'
[junit4:junit4]   2> 17204 T983 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/collection1/lib/README' to classloader
[junit4:junit4]   2> 17204 T983 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17227 T983 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 17254 T983 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17255 T983 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17258 T983 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17649 T983 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 17655 T983 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 17657 T983 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 17669 T983 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17672 T983 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17675 T983 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17676 T983 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17677 T983 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17677 T983 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17678 T983 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17678 T983 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17678 T983 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1362546610714/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/
[junit4:junit4]   2> 17678 T983 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 17679 T983 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 17679 T983 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4 forceNew:false
[junit4:junit4]   2> 17680 T983 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 17680 T983 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index/
[junit4:junit4]   2> 17680 T983 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 17680 T983 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index forceNew:false
[junit4:junit4]   2> 17683 T983 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17683 T983 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17684 T983 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index
[junit4:junit4]   2> 17685 T983 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 17686 T983 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 17686 T983 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 17686 T983 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 17687 T983 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 17687 T983 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 17687 T983 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 17687 T983 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 17688 T983 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 17690 T983 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 17692 T983 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 17693 T983 oass.SolrIndexSearcher.<init> Opening Searcher@3288c66d main
[junit4:junit4]   2> 17694 T983 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 17694 T983 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 17699 T984 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3288c66d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 17701 T983 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 17701 T983 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18473 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18474 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:47966_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:47966"}
[junit4:junit4]   2> 18474 T918 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18474 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 18478 T923 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> 18478 T966 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> 18478 T982 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> 18478 T936 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> 18478 T951 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> 18478 T917 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> 18702 T983 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 18703 T983 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47966 collection:collection1 shard:shard2
[junit4:junit4]   2> 18708 T983 oasc.ZkController.register We are http://127.0.0.1:47966/collection1/ and leader is http://127.0.0.1:39160/collection1/
[junit4:junit4]   2> 18708 T983 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47966
[junit4:junit4]   2> 18708 T983 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 18709 T983 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C69 name=collection1 org.apache.solr.core.SolrCore@67cf294a url=http://127.0.0.1:47966/collection1 node=127.0.0.1:47966_ C69_STATE=coll:collection1 core:collection1 props:{collection=collection1, core=collection1, node_name=127.0.0.1:47966_, state=down, base_url=http://127.0.0.1:47966}
[junit4:junit4]   2> 18710 T985 C69 P47966 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 18710 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 18710 T985 C69 P47966 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 18710 T983 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18710 T985 C69 P47966 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18712 T985 C69 P47966 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18712 T895 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 18712 T895 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 18713 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18718 T895 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18720 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18725 T931 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/onenodecollectioncore
[junit4:junit4]   2> 18726 T931 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 18726 T931 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 18727 T931 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 18728 T931 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 18728 T931 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 18730 T931 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 18731 T931 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/onenodecollectioncore/'
[junit4:junit4]   2> 18757 T931 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4]   2> 18792 T931 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 18793 T931 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 18796 T931 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C68_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, core=collection1, node_name=127.0.0.1:42313_, state=recovering, base_url=http://127.0.0.1:42313}
[junit4:junit4]   2> 19066 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:34452/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19066 T969 C68 P42313 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42313 START replicas=[http://127.0.0.1:34452/collection1/] nUpdates=100
[junit4:junit4]   2> 19067 T969 C68 P42313 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19067 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19067 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19068 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19068 T969 C68 P42313 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19068 T969 C68 P42313 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:34452/collection1/. core=collection1
[junit4:junit4]   2> 19068 T969 C68 P42313 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C70 name=collection1 org.apache.solr.core.SolrCore@5d81243e url=http://127.0.0.1:34452/collection1 node=127.0.0.1:34452_ C70_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, core=collection1, node_name=127.0.0.1:34452_, state=active, base_url=http://127.0.0.1:34452, leader=true}
[junit4:junit4]   2> 19073 T932 C70 P34452 REQ /get {getVersions=100&version=2&distrib=false&wt=javabin&qt=/get} status=0 QTime=1 
[junit4:junit4]   2> 19075 T929 C70 P34452 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19076 T929 C70 P34452 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1
[junit4:junit4]   2> 19078 T929 C70 P34452 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19079 T929 C70 P34452 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19091 T929 C70 P34452 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19091 T929 C70 P34452 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19092 T929 C70 P34452 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1
[junit4:junit4]   2> 19092 T929 C70 P34452 oass.SolrIndexSearcher.<init> Opening Searcher@441132f2 realtime
[junit4:junit4]   2> 19093 T929 C70 P34452 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19093 T929 C70 P34452 /update {waitSearcher=true&commit=true&version=2&openSearcher=false&wt=javabin&commit_end_point=true&softCommit=false} {commit=} 0 18
[junit4:junit4]   2> 19094 T969 C68 P42313 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19095 T969 C68 P42313 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19100 T929 C70 P34452 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19101 T929 C70 P34452 REQ /replication {version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=4 
[junit4:junit4]   2> 19101 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19102 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19102 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19105 T930 C70 P34452 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1
[junit4:junit4]   2> 19105 T930 C70 P34452 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty1/index
[junit4:junit4]   2> 19106 T930 C70 P34452 REQ /replication {generation=2&version=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=2 
[junit4:junit4]   2> 19107 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19107 T969 C68 P42313 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index.20130306161013768 forceNew:false
[junit4:junit4]   2> 19108 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 19108 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index.20130306161013768 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d12e9ef fullCopy=false
[junit4:junit4]   2> 19111 T931 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19111 T932 C70 P34452 REQ /replication {generation=2&wt=filestream&file=segments_2&checksum=true&qt=/replication&command=filecontent} status=0 QTime=0 
[junit4:junit4]   2> 19113 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index
[junit4:junit4]   2> 19113 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19117 T931 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19119 T931 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19121 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 19122 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 19122 T969 C68 P42313 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19122 T969 C68 P42313 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19123 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 19125 T969 C68 P42313 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19126 T969 C68 P42313 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19126 T969 C68 P42313 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19127 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3
[junit4:junit4]   2> 19127 T969 C68 P42313 oass.SolrIndexSearcher.<init> Opening Searcher@10804d73 main
[junit4:junit4]   2> 19128 T968 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10804d73 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19128 T968 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index
[junit4:junit4]   2> 19128 T969 C68 P42313 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index.20130306161013768 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d12e9ef
[junit4:junit4]   2> 19129 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index.20130306161013768
[junit4:junit4]   2> 19129 T969 C68 P42313 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty3/index
[junit4:junit4]   2> 19129 T969 C68 P42313 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19129 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19130 T969 C68 P42313 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19130 T969 C68 P42313 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19132 T969 C68 P42313 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19132 T931 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19137 T931 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19140 T931 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19142 T931 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19142 T931 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19142 T931 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19143 T931 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19143 T931 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19144 T931 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362546598099/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/
[junit4:junit4]   2> 19144 T931 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a05a599
[junit4:junit4]   2> 19145 T931 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4]   2> 19146 T931 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection forceNew:false
[junit4:junit4]   2> 19146 T931 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection
[junit4:junit4]   2> 19146 T931 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/index/
[junit4:junit4]   2> 19147 T931 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19147 T931 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/index forceNew:false
[junit4:junit4]   2> 19162 T931 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19163 T931 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19163 T931 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection/index
[junit4:junit4]   2> 19164 T931 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19165 T931 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19165 T931 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19166 T931 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19166 T931 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19166 T931 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19167 T931 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19167 T931 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19167 T931 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19170 T931 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19172 T931 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection
[junit4:junit4]   2> 19173 T931 oass.SolrIndexSearcher.<init> Opening Searcher@308f8c50 main
[junit4:junit4]   2> 19173 T931 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19174 T931 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19176 T931 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362546594665/onenodecollection
[junit4:junit4]   2> 19177 T988 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@308f8c50 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19178 T931 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 19983 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19984 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:47966_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:47966"}
[junit4:junit4]   2> 19987 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:42313_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:42313"}
[junit4:junit4]   2> 19990 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4]   2> 19990 T918 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 19990 T918 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 19994 T966 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> 19994 T951 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> 19994 T923 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> 19994 T936 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> 19994 T982 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> 19994 T917 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> 20179 T931 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20180 T931 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:34452 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20181 T931 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20185 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:delete cxid:0xa6 zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 20185 T931 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20186 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xa7 zxid:0xc4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20187 T931 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20187 T931 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20188 T931 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34452/onenodecollectioncore/
[junit4:junit4]   2> 20188 T931 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20188 T931 oasc.SyncStrategy.syncToMe http://127.0.0.1:34452/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20188 T931 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34452/onenodecollectioncore/
[junit4:junit4]   2> 20188 T931 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20191 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xb1 zxid:0xc8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21500 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21591 T966 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> 21591 T936 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> 21591 T982 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> 21591 T923 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> 21591 T951 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> 21591 T917 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> 21595 T931 oasc.ZkController.register We are http://127.0.0.1:34452/onenodecollectioncore/ and leader is http://127.0.0.1:34452/onenodecollectioncore/
[junit4:junit4]   2> 21596 T931 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:34452
[junit4:junit4]   2> 21596 T931 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21596 T931 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21597 T931 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21599 T895 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21599 T895 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22601 T895 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C69_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard2, core=collection1, node_name=127.0.0.1:47966_, state=recovering, base_url=http://127.0.0.1:47966}
[junit4:junit4]   2> 22720 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39160/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 22721 T985 C69 P47966 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47966 START replicas=[http://127.0.0.1:39160/collection1/] nUpdates=100
[junit4:junit4]   2> 22721 T985 C69 P47966 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 22721 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 22722 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 22722 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 22722 T985 C69 P47966 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 22722 T985 C69 P47966 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39160/collection1/. core=collection1
[junit4:junit4]   2> 22722 T985 C69 P47966 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C71 name=collection1 org.apache.solr.core.SolrCore@7779990b url=http://127.0.0.1:39160/collection1 node=127.0.0.1:39160_ C71_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard2, core=collection1, node_name=127.0.0.1:39160_, state=active, base_url=http://127.0.0.1:39160, leader=true}
[junit4:junit4]   2> 22726 T945 C71 P39160 REQ /get {getVersions=100&version=2&distrib=false&wt=javabin&qt=/get} status=0 QTime=1 
[junit4:junit4]   2> 22729 T944 C71 P39160 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 22729 T944 C71 P39160 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2
[junit4:junit4]   2> 22731 T944 C71 P39160 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 22731 T944 C71 P39160 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 22861 T944 C71 P39160 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22861 T944 C71 P39160 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22862 T944 C71 P39160 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2
[junit4:junit4]   2> 22862 T944 C71 P39160 oass.SolrIndexSearcher.<init> Opening Searcher@16774d77 realtime
[junit4:junit4]   2> 22862 T944 C71 P39160 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 22862 T944 C71 P39160 /update {waitSearcher=true&commit=true&version=2&openSearcher=false&wt=javabin&commit_end_point=true&softCommit=false} {commit=} 0 134
[junit4:junit4]   2> 22864 T985 C69 P47966 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22864 T985 C69 P47966 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 22866 T945 C71 P39160 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22867 T945 C71 P39160 REQ /replication {version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=1 
[junit4:junit4]   2> 22868 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 22868 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 22868 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 22870 T944 C71 P39160 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2
[junit4:junit4]   2> 22871 T944 C71 P39160 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty2/index
[junit4:junit4]   2> 22871 T944 C71 P39160 REQ /replication {generation=2&version=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=1 
[junit4:junit4]   2> 22872 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 22873 T985 C69 P47966 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index.20130306161017533 forceNew:false
[junit4:junit4]   2> 22873 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 22874 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index.20130306161017533 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60e45a4d fullCopy=false
[junit4:junit4]   2> 22877 T946 C71 P39160 REQ /replication {generation=2&wt=filestream&file=segments_2&checksum=true&qt=/replication&command=filecontent} status=0 QTime=1 
[junit4:junit4]   2> 22878 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index
[junit4:junit4]   2> 22878 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 22881 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 22882 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 22882 T985 C69 P47966 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 22882 T985 C69 P47966 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 22882 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 22885 T985 C69 P47966 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index,segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index,segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22885 T985 C69 P47966 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22886 T985 C69 P47966 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 22886 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 22886 T985 C69 P47966 oass.SolrIndexSearcher.<init> Opening Searcher@7a5ef6f5 main
[junit4:junit4]   2> 22887 T984 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a5ef6f5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 22888 T984 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index
[junit4:junit4]   2> 22888 T985 C69 P47966 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index.20130306161017533 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60e45a4d
[junit4:junit4]   2> 22888 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index.20130306161017533
[junit4:junit4]   2> 22889 T985 C69 P47966 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index
[junit4:junit4]   2> 22889 T985 C69 P47966 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 22889 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 22889 T985 C69 P47966 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 22890 T985 C69 P47966 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 22892 T985 C69 P47966 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23098 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23099 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4]   2> 23101 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:47966_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:47966"}
[junit4:junit4]   2> 23107 T917 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> 23107 T951 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> 23108 T966 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> 23108 T982 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> 23108 T936 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> 23108 T923 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> 23603 T895 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23604 T895 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23604 T895 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23629 T895 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50085 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@68e2da1a
[junit4:junit4]   2> 23630 T895 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23630 T991 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50085. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23631 T991 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50085, initiating session
[junit4:junit4]   2> 23631 T897 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:46749
[junit4:junit4]   2> 23631 T897 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:46749
[junit4:junit4]   2> 23632 T899 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d3e1b136c000d with negotiated timeout 10000 for client /127.0.0.1:46749
[junit4:junit4]   2> 23632 T991 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50085, sessionid = 0x13d3e1b136c000d, negotiated timeout = 10000
[junit4:junit4]   2> 23632 T992 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68e2da1a name:ZooKeeperConnection Watcher:127.0.0.1:50085 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23632 T895 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23671 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c000d
[junit4:junit4]   2> 23671 T992 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23671 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46749 which had sessionid 0x13d3e1b136c000d
[junit4:junit4]   2> 23671 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c000d closed
[junit4:junit4]   2> 23672 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0004
[junit4:junit4]   2> 23673 T923 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23673 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0004 closed
[junit4:junit4]   2> 23673 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46725 which had sessionid 0x13d3e1b136c0004
[junit4:junit4]   2> 23675 T895 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 57432
[junit4:junit4]   2> 23675 T895 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=4459078
[junit4:junit4]   2> 24613 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24614 T918 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57432_",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57432__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57432"}
[junit4:junit4]   2> 24618 T917 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> 24618 T982 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> 24618 T951 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> 24618 T936 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> 24618 T966 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> 25677 T895 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@127c97e4
[junit4:junit4]   2> 25678 T895 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4/index
[junit4:junit4]   2> 25679 T895 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/jetty4
[junit4:junit4]   2> 25681 T895 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> 25682 T895 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25682 T895 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25682 T895 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25683 T895 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25683 T895 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index
[junit4:junit4]   2> 25683 T895 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index
[junit4:junit4]   2> 25684 T895 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data/index
[junit4:junit4]   2> 25684 T895 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data
[junit4:junit4]   2> 25684 T895 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362546594665/control/data
[junit4:junit4]   2> 25685 T918 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89295853628162051-127.0.0.1:57432_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25686 T900 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d3e1b136c0003
[junit4:junit4]   2> 25687 T966 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> 25687 T982 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25687 T982 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> 25687 T897 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:46724 which had sessionid 0x13d3e1b136c0003
[junit4:junit4]   2> 25687 T895 oaz.ZooKeeper.close Session: 0x13d3e1b136c0003 closed
[junit4:junit4]   2> 25688 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:delete cxid:0xbe zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25688 T951 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25688 T951 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> 25688 T936 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25689 T966 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25690 T936 oasc.Overseer.start Overseer (id=89295853628162054-127.0.0.1:34452_-n_0000000001) starting
[junit4:junit4]   2> 25691 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xc3 zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25691 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xc4 zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25692 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xc5 zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25693 T900 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d3e1b136c0006 type:create cxid:0xc6 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25693 T936 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> 25693 T994 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25695 T936 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25695 T993 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25709 T895 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 25761 T895 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 34452
[junit4:junit4]   2> 25762 T895 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2147454478
[junit4:junit4]   2> 26987 T917 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26987 T917 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> 26987 T917 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26987 T917 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27198 T993 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27199 T993 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34452__collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4]   2> 27202 T993 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:34452_",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:34452__onenodecollectioncore",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:34452"}
[junit4:junit4] 

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

:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=E184245560913A05 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mk_MK -Dtests.timezone=Australia/ACT -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR   32.2s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.common.SolrException: Server at http://127.0.0.1:39160/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([E184245560913A05:6062AA4D17CE5A39]: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:196)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:85)
[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> 32168 T895 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 32172 T894 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 32339 T898 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 33336 T982 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33336 T982 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> 33336 T982 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33336 T982 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=mk_MK, timezone=Australia/ACT
[junit4:junit4]   2> NOTE: Linux 3.2.0-38-generic amd64/Oracle Corporation 1.8.0-ea (64-bit)/cpus=8,threads=2,free=59303904,total=355598336
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestAtomicUpdateErrorCases, DistributedQueryElevationComponentTest, TestSolrXMLSerializer, NoCacheHeaderTest, TermsComponentTest, TestWordDelimiterFilterFactory, URLClassifyProcessorTest, OverseerCollectionProcessorTest, SortByFunctionTest, TestRecovery, TestStressLucene, TestRandomDVFaceting, MBeansHandlerTest, BadIndexSchemaTest, IndexSchemaTest, ZkNodePropsTest, SolrIndexConfigTest, TimeZoneUtilsTest, UniqFieldsUpdateProcessorFactoryTest, XsltUpdateRequestHandlerTest, DisMaxRequestHandlerTest, FullSolrCloudDistribCmdsTest, TestDefaultSimilarityFactory, ClusterStateTest, BasicFunctionalityTest, PingRequestHandlerTest, TestPartialUpdateDeduplication, CoreContainerCoreInitFailuresTest, AutoCommitTest, RegexBoostProcessorTest, DirectSolrSpellCheckerTest, SoftAutoCommitTest, StandardRequestHandlerTest, TestReversedWildcardFilterFactory, SimpleFacetsTest, CopyFieldTest, TestSuggestSpellingConverter, TestFastOutputStream, TestBinaryField, SuggesterTest, TestSolrQueryParser, TestStressVersions, TestCSVLoader, SimplePostToolTest, ShardRoutingTest, FileUtilsTest, TestCodecSupport, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.44s, 1 test, 1 error <<< FAILURES!

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

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



Mime
View raw message