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 (32bit/jdk1.8.0-ea-b79) - Build # 4736 - Still Failing!
Date Tue, 19 Mar 2013 17:21:46 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4736/
Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseSerialGC

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

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

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




Build Log:
[...truncated 9335 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T1280 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /vhjv/gb
[junit4:junit4]   2> 3 T1280 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629
[junit4:junit4]   2> 3 T1280 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 4 T1281 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 4 T1281 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 4 T1281 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 5 T1281 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 5 T1281 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 6 T1281 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 104 T1280 oasc.ZkTestServer.run start zk server on port:54423
[junit4:junit4]   2> 104 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1170e0f
[junit4:junit4]   2> 105 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 105 T1286 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 106 T1286 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 106 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32781
[junit4:junit4]   2> 106 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32781
[junit4:junit4]   2> 106 T1284 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 199 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00000 with negotiated timeout 10000 for client /127.0.0.1:32781
[junit4:junit4]   2> 199 T1286 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00000, negotiated timeout = 10000
[junit4:junit4]   2> 200 T1287 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1170e0f name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 200 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 200 T1280 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 203 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00000
[junit4:junit4]   2> 204 T1287 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 204 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00000 closed
[junit4:junit4]   2> 204 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32781 which had sessionid 0x13d83a565d00000
[junit4:junit4]   2> 204 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1d0fd5d
[junit4:junit4]   2> 205 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 205 T1288 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 206 T1288 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 206 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32782
[junit4:junit4]   2> 206 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32782
[junit4:junit4]   2> 207 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00001 with negotiated timeout 10000 for client /127.0.0.1:32782
[junit4:junit4]   2> 207 T1288 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00001, negotiated timeout = 10000
[junit4:junit4]   2> 207 T1289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d0fd5d name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 207 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 208 T1280 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 210 T1280 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 212 T1280 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 215 T1280 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 216 T1280 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> 217 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 220 T1280 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> 221 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 223 T1280 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> 224 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 226 T1280 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> 226 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 228 T1280 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> 228 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 231 T1280 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> 231 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 233 T1280 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> 233 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 235 T1280 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> 236 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 237 T1280 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> 238 T1280 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 240 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00001
[junit4:junit4]   2> 240 T1289 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 240 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00001 closed
[junit4:junit4]   2> 240 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32782 which had sessionid 0x13d83a565d00001
[junit4:junit4]   2> 300 T1280 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 303 T1280 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40419
[junit4:junit4]   2> 304 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 304 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 305 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867
[junit4:junit4]   2> 305 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/solr.xml
[junit4:junit4]   2> 305 T1280 oasc.CoreContainer.<init> New CoreContainer 5890984
[junit4:junit4]   2> 306 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/'
[junit4:junit4]   2> 307 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/'
[junit4:junit4]   2> 325 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 326 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 326 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 327 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 327 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 327 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 328 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 328 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 328 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 329 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 335 T1280 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 355 T1280 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54423/solr
[junit4:junit4]   2> 356 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 356 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@fe7839
[junit4:junit4]   2> 357 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 357 T1299 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 358 T1299 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 358 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32783
[junit4:junit4]   2> 358 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32783
[junit4:junit4]   2> 359 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00002 with negotiated timeout 20000 for client /127.0.0.1:32783
[junit4:junit4]   2> 359 T1299 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00002, negotiated timeout = 20000
[junit4:junit4]   2> 359 T1300 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fe7839 name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 359 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 360 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00002
[junit4:junit4]   2> 360 T1300 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 360 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32783 which had sessionid 0x13d83a565d00002
[junit4:junit4]   2> 360 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00002 closed
[junit4:junit4]   2> 361 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 363 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@179f867
[junit4:junit4]   2> 364 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 364 T1301 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 365 T1301 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 365 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32784
[junit4:junit4]   2> 365 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32784
[junit4:junit4]   2> 366 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00003 with negotiated timeout 20000 for client /127.0.0.1:32784
[junit4:junit4]   2> 366 T1301 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00003, negotiated timeout = 20000
[junit4:junit4]   2> 366 T1302 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@179f867 name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 367 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 368 T1280 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 370 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 370 T1280 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 372 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 374 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40419_vhjv%2Fgb
[junit4:junit4]   2> 374 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:40419_vhjv%2Fgb Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:40419_vhjv%2Fgb
[junit4:junit4]   2> 375 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40419_vhjv%2Fgb
[junit4:junit4]   2> 377 T1280 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 381 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 381 T1280 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 383 T1280 oasc.Overseer.start Overseer (id=89372314018250755-127.0.0.1:40419_vhjv%2Fgb-n_0000000000) starting
[junit4:junit4]   2> 384 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 384 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 385 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 386 T1280 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 388 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 389 T1304 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 389 T1280 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 391 T1280 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 393 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 394 T1303 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 397 T1305 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/collection1
[junit4:junit4]   2> 397 T1305 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 398 T1305 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 398 T1305 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 399 T1305 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/collection1/'
[junit4:junit4]   2> 399 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/collection1/lib/README' to classloader
[junit4:junit4]   2> 400 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 430 T1305 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 472 T1305 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 473 T1305 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 485 T1305 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 908 T1305 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 914 T1305 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 917 T1305 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 927 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 930 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 932 T1305 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 933 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 933 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 934 T1305 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 934 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 935 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 935 T1305 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 935 T1305 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363713287867/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/
[junit4:junit4]   2> 935 T1305 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 935 T1305 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 936 T1305 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data forceNew: false
[junit4:junit4]   2> 936 T1305 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/index/
[junit4:junit4]   2> 936 T1305 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 937 T1305 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/index forceNew: false
[junit4:junit4]   2> 938 T1305 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1022fac lockFactory=org.apache.lucene.store.NativeFSLockFactory@e40bda),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 938 T1305 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 939 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 939 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 940 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 940 T1305 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 940 T1305 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 941 T1305 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 941 T1305 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 941 T1305 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 941 T1305 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 944 T1305 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 946 T1305 oass.SolrIndexSearcher.<init> Opening Searcher@1132f88 main
[junit4:junit4]   2> 946 T1305 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/tlog
[junit4:junit4]   2> 947 T1305 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 947 T1305 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 950 T1306 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1132f88 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 950 T1305 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 950 T1305 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1898 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1899 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40419_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40419/vhjv/gb"}
[junit4:junit4]   2> 1900 T1303 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1900 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1904 T1302 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> 1951 T1305 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 1952 T1305 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40419/vhjv/gb collection:control_collection shard:shard1
[junit4:junit4]   2> 1952 T1305 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 1957 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 1957 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 1958 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 1959 T1305 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 1959 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 1960 T1305 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40419/vhjv/gb/collection1/
[junit4:junit4]   2> 1960 T1305 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 1960 T1305 oasc.SyncStrategy.syncToMe http://127.0.0.1:40419/vhjv/gb/collection1/ has no replicas
[junit4:junit4]   2> 1960 T1305 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40419/vhjv/gb/collection1/
[junit4:junit4]   2> 1960 T1305 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 1963 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3407 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3425 T1302 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> 3468 T1305 oasc.ZkController.register We are http://127.0.0.1:40419/vhjv/gb/collection1/ and leader is http://127.0.0.1:40419/vhjv/gb/collection1/
[junit4:junit4]   2> 3469 T1305 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40419/vhjv/gb
[junit4:junit4]   2> 3469 T1305 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3469 T1305 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3470 T1305 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3471 T1305 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3472 T1280 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 3472 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3473 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3476 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3476 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@407988
[junit4:junit4]   2> 3477 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3477 T1308 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3478 T1308 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 3478 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32789
[junit4:junit4]   2> 3478 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32789
[junit4:junit4]   2> 3479 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00004 with negotiated timeout 10000 for client /127.0.0.1:32789
[junit4:junit4]   2> 3479 T1308 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00004, negotiated timeout = 10000
[junit4:junit4]   2> 3479 T1309 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@407988 name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3480 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3480 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3482 T1280 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3541 T1280 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3543 T1280 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39008
[junit4:junit4]   2> 3544 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3544 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3544 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108
[junit4:junit4]   2> 3545 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/solr.xml
[junit4:junit4]   2> 3545 T1280 oasc.CoreContainer.<init> New CoreContainer 27165641
[junit4:junit4]   2> 3545 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/'
[junit4:junit4]   2> 3546 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/'
[junit4:junit4]   2> 3563 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3564 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3564 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3565 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3565 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3565 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3566 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3566 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3566 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3567 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3573 T1280 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3594 T1280 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54423/solr
[junit4:junit4]   2> 3594 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3594 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@17c78f
[junit4:junit4]   2> 3595 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3595 T1319 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3596 T1319 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 3596 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32790
[junit4:junit4]   2> 3597 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32790
[junit4:junit4]   2> 3597 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00005 with negotiated timeout 20000 for client /127.0.0.1:32790
[junit4:junit4]   2> 3597 T1319 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00005, negotiated timeout = 20000
[junit4:junit4]   2> 3598 T1320 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17c78f name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3598 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3599 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00005
[junit4:junit4]   2> 3599 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32790 which had sessionid 0x13d83a565d00005
[junit4:junit4]   2> 3599 T1320 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3599 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00005 closed
[junit4:junit4]   2> 3600 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3603 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1408146
[junit4:junit4]   2> 3603 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3604 T1321 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3604 T1321 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 3604 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32791
[junit4:junit4]   2> 3605 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32791
[junit4:junit4]   2> 3605 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00006 with negotiated timeout 20000 for client /127.0.0.1:32791
[junit4:junit4]   2> 3605 T1321 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00006, negotiated timeout = 20000
[junit4:junit4]   2> 3606 T1322 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1408146 name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3606 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3607 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3608 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3609 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4611 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39008_vhjv%2Fgb
[junit4:junit4]   2> 4612 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39008_vhjv%2Fgb Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39008_vhjv%2Fgb
[junit4:junit4]   2> 4613 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39008_vhjv%2Fgb
[junit4:junit4]   2> 4615 T1302 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> 4615 T1309 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4616 T1322 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4617 T1302 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4620 T1323 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/collection1
[junit4:junit4]   2> 4620 T1323 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4621 T1323 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4621 T1323 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4622 T1323 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/collection1/'
[junit4:junit4]   2> 4622 T1323 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/collection1/lib/README' to classloader
[junit4:junit4]   2> 4622 T1323 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4652 T1323 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 4698 T1323 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4699 T1323 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4704 T1323 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4929 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4930 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40419_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40419/vhjv/gb"}
[junit4:junit4]   2> 4932 T1322 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> 4932 T1309 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> 4932 T1302 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> 5171 T1323 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5178 T1323 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5181 T1323 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5191 T1323 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5195 T1323 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5198 T1323 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5199 T1323 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5199 T1323 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5199 T1323 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5200 T1323 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5200 T1323 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5200 T1323 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5201 T1323 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/
[junit4:junit4]   2> 5201 T1323 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 5201 T1323 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5202 T1323 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1 forceNew: false
[junit4:junit4]   2> 5202 T1323 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/index/
[junit4:junit4]   2> 5202 T1323 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5202 T1323 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/index forceNew: false
[junit4:junit4]   2> 5203 T1323 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1be649d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca7e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5204 T1323 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5205 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5205 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5206 T1323 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5206 T1323 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5207 T1323 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5207 T1323 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5207 T1323 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5208 T1323 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5208 T1323 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5210 T1323 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5213 T1323 oass.SolrIndexSearcher.<init> Opening Searcher@6c2220 main
[junit4:junit4]   2> 5213 T1323 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/tlog
[junit4:junit4]   2> 5214 T1323 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5214 T1323 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5218 T1324 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6c2220 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5219 T1323 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5220 T1323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6437 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6438 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 6438 T1303 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6438 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6443 T1302 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> 6443 T1322 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> 6443 T1309 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> 7221 T1323 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7221 T1323 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39008/vhjv/gb collection:collection1 shard:shard1
[junit4:junit4]   2> 7222 T1323 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7226 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7226 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7227 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7228 T1323 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7228 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7229 T1323 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39008/vhjv/gb/collection1/
[junit4:junit4]   2> 7229 T1323 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7229 T1323 oasc.SyncStrategy.syncToMe http://127.0.0.1:39008/vhjv/gb/collection1/ has no replicas
[junit4:junit4]   2> 7229 T1323 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39008/vhjv/gb/collection1/
[junit4:junit4]   2> 7230 T1323 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7232 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7947 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7953 T1309 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> 7953 T1322 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> 7953 T1302 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> 7985 T1323 oasc.ZkController.register We are http://127.0.0.1:39008/vhjv/gb/collection1/ and leader is http://127.0.0.1:39008/vhjv/gb/collection1/
[junit4:junit4]   2> 7986 T1323 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39008/vhjv/gb
[junit4:junit4]   2> 7986 T1323 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 7986 T1323 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 7986 T1323 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 7988 T1323 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7989 T1280 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 7989 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 7990 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8050 T1280 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8052 T1280 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37418
[junit4:junit4]   2> 8053 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8053 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8053 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618
[junit4:junit4]   2> 8054 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/solr.xml
[junit4:junit4]   2> 8054 T1280 oasc.CoreContainer.<init> New CoreContainer 19656890
[junit4:junit4]   2> 8054 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/'
[junit4:junit4]   2> 8055 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/'
[junit4:junit4]   2> 8072 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8073 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8073 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8073 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8074 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8074 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8074 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8074 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8075 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8075 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8081 T1280 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8101 T1280 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54423/solr
[junit4:junit4]   2> 8102 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8102 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@e304cc
[junit4:junit4]   2> 8103 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8103 T1335 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8104 T1335 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 8104 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32798
[junit4:junit4]   2> 8104 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32798
[junit4:junit4]   2> 8105 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00007 with negotiated timeout 20000 for client /127.0.0.1:32798
[junit4:junit4]   2> 8105 T1335 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00007, negotiated timeout = 20000
[junit4:junit4]   2> 8105 T1336 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e304cc name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8106 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8107 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00007
[junit4:junit4]   2> 8107 T1336 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8107 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32798 which had sessionid 0x13d83a565d00007
[junit4:junit4]   2> 8107 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00007 closed
[junit4:junit4]   2> 8108 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8110 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ee906b
[junit4:junit4]   2> 8111 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8111 T1337 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8112 T1337 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 8112 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32799
[junit4:junit4]   2> 8113 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32799
[junit4:junit4]   2> 8113 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00008 with negotiated timeout 20000 for client /127.0.0.1:32799
[junit4:junit4]   2> 8113 T1337 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00008, negotiated timeout = 20000
[junit4:junit4]   2> 8114 T1338 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ee906b name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8114 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8115 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8116 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8118 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9121 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37418_vhjv%2Fgb
[junit4:junit4]   2> 9122 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37418_vhjv%2Fgb Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37418_vhjv%2Fgb
[junit4:junit4]   2> 9122 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37418_vhjv%2Fgb
[junit4:junit4]   2> 9124 T1309 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> 9125 T1322 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> 9125 T1302 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9125 T1338 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9125 T1302 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> 9126 T1309 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9126 T1322 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9130 T1339 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/collection1
[junit4:junit4]   2> 9131 T1339 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9131 T1339 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9131 T1339 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9132 T1339 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/collection1/'
[junit4:junit4]   2> 9133 T1339 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/collection1/lib/README' to classloader
[junit4:junit4]   2> 9133 T1339 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9159 T1339 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 9194 T1339 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9195 T1339 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9199 T1339 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9458 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9458 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 9461 T1338 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> 9461 T1322 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> 9461 T1309 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> 9461 T1302 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> 9617 T1339 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9622 T1339 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9625 T1339 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9635 T1339 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9638 T1339 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9641 T1339 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9642 T1339 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9642 T1339 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9643 T1339 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9643 T1339 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9644 T1339 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9644 T1339 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9644 T1339 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363713295618/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2/
[junit4:junit4]   2> 9644 T1339 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 9645 T1339 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9645 T1339 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2 forceNew: false
[junit4:junit4]   2> 9645 T1339 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2/index/
[junit4:junit4]   2> 9645 T1339 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9646 T1339 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2/index forceNew: false
[junit4:junit4]   2> 9647 T1339 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19394ef lockFactory=org.apache.lucene.store.NativeFSLockFactory@148a4c3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9647 T1339 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9648 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9648 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9649 T1339 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9649 T1339 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9650 T1339 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9650 T1339 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9650 T1339 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9650 T1339 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9651 T1339 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9653 T1339 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9655 T1339 oass.SolrIndexSearcher.<init> Opening Searcher@376560 main
[junit4:junit4]   2> 9656 T1339 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty2/tlog
[junit4:junit4]   2> 9656 T1339 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9656 T1339 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9660 T1340 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@376560 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9663 T1339 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9663 T1339 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10966 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10967 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37418_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37418/vhjv/gb"}
[junit4:junit4]   2> 10967 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 10968 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 11000 T1338 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> 11000 T1309 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> 11000 T1322 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> 11001 T1302 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> 11664 T1339 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11665 T1339 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37418/vhjv/gb collection:collection1 shard:shard2
[junit4:junit4]   2> 11665 T1339 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 11670 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4]   2> 11671 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11671 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11673 T1339 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11673 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11673 T1339 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37418/vhjv/gb/collection1/
[junit4:junit4]   2> 11674 T1339 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11674 T1339 oasc.SyncStrategy.syncToMe http://127.0.0.1:37418/vhjv/gb/collection1/ has no replicas
[junit4:junit4]   2> 11674 T1339 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37418/vhjv/gb/collection1/
[junit4:junit4]   2> 11674 T1339 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 11677 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12506 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12518 T1309 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> 12518 T1322 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> 12518 T1302 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> 12518 T1338 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4]   2> 12531 T1339 oasc.ZkController.register We are http://127.0.0.1:37418/vhjv/gb/collection1/ and leader is http://127.0.0.1:37418/vhjv/gb/collection1/
[junit4:junit4]   2> 12531 T1339 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37418/vhjv/gb
[junit4:junit4]   2> 12531 T1339 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12532 T1339 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12532 T1339 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12533 T1339 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12534 T1280 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 12534 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12535 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12602 T1280 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12604 T1280 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35683
[junit4:junit4]   2> 12605 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12605 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12606 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164
[junit4:junit4]   2> 12606 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/solr.xml
[junit4:junit4]   2> 12606 T1280 oasc.CoreContainer.<init> New CoreContainer 6541803
[junit4:junit4]   2> 12607 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/'
[junit4:junit4]   2> 12607 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/'
[junit4:junit4]   2> 12626 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12626 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12626 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12627 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12627 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12627 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12628 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12628 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12628 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12629 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12635 T1280 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12647 T1280 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54423/solr
[junit4:junit4]   2> 12647 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12647 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@12dc346
[junit4:junit4]   2> 12648 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12648 T1351 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12649 T1351 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 12649 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32819
[junit4:junit4]   2> 12650 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32819
[junit4:junit4]   2> 12650 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d00009 with negotiated timeout 20000 for client /127.0.0.1:32819
[junit4:junit4]   2> 12650 T1351 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d00009, negotiated timeout = 20000
[junit4:junit4]   2> 12651 T1352 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12dc346 name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12651 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12652 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00009
[junit4:junit4]   2> 12652 T1352 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12652 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32819 which had sessionid 0x13d83a565d00009
[junit4:junit4]   2> 12652 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00009 closed
[junit4:junit4]   2> 12653 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12655 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@12b84b3
[junit4:junit4]   2> 12656 T1353 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12656 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12656 T1353 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 12657 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32820
[junit4:junit4]   2> 12657 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32820
[junit4:junit4]   2> 12658 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d0000a with negotiated timeout 20000 for client /127.0.0.1:32820
[junit4:junit4]   2> 12658 T1353 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d0000a, negotiated timeout = 20000
[junit4:junit4]   2> 12658 T1354 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12b84b3 name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12658 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12659 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12660 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12661 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13664 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35683_vhjv%2Fgb
[junit4:junit4]   2> 13664 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35683_vhjv%2Fgb Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35683_vhjv%2Fgb
[junit4:junit4]   2> 13666 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35683_vhjv%2Fgb
[junit4:junit4]   2> 13668 T1322 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> 13668 T1338 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> 13668 T1309 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> 13669 T1354 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13669 T1302 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13669 T1302 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> 13670 T1338 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13670 T1322 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13670 T1309 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13675 T1355 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/collection1
[junit4:junit4]   2> 13675 T1355 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13676 T1355 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13676 T1355 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13677 T1355 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/collection1/'
[junit4:junit4]   2> 13678 T1355 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/collection1/lib/README' to classloader
[junit4:junit4]   2> 13678 T1355 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13713 T1355 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 13750 T1355 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13751 T1355 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13755 T1355 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14024 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14024 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37418_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37418/vhjv/gb"}
[junit4:junit4]   2> 14026 T1322 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> 14027 T1338 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> 14027 T1302 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> 14027 T1354 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> 14027 T1309 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> 14162 T1355 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14176 T1355 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14181 T1355 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14190 T1355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14193 T1355 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14196 T1355 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14197 T1355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14197 T1355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14197 T1355 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14198 T1355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14198 T1355 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14199 T1355 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14199 T1355 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363713300164/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/
[junit4:junit4]   2> 14199 T1355 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 14199 T1355 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14200 T1355 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3 forceNew: false
[junit4:junit4]   2> 14200 T1355 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/index/
[junit4:junit4]   2> 14200 T1355 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14200 T1355 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/index forceNew: false
[junit4:junit4]   2> 14202 T1355 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ba1fa6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8105d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14202 T1355 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14203 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14204 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14204 T1355 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14204 T1355 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14205 T1355 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14205 T1355 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14205 T1355 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14206 T1355 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14206 T1355 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14208 T1355 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14211 T1355 oass.SolrIndexSearcher.<init> Opening Searcher@1703177 main
[junit4:junit4]   2> 14211 T1355 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/tlog
[junit4:junit4]   2> 14212 T1355 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14212 T1355 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14216 T1356 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1703177 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14217 T1355 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14218 T1355 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15530 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15531 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35683_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35683/vhjv/gb"}
[junit4:junit4]   2> 15531 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15531 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 15536 T1338 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> 15536 T1309 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> 15536 T1302 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> 15536 T1322 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> 15536 T1354 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> 16219 T1355 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16219 T1355 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35683/vhjv/gb collection:collection1 shard:shard1
[junit4:junit4]   2> 16222 T1355 oasc.ZkController.register We are http://127.0.0.1:35683/vhjv/gb/collection1/ and leader is http://127.0.0.1:39008/vhjv/gb/collection1/
[junit4:junit4]   2> 16222 T1355 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35683/vhjv/gb
[junit4:junit4]   2> 16222 T1355 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16222 T1355 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C67 name=collection1 org.apache.solr.core.SolrCore@1a68acc url=http://127.0.0.1:35683/vhjv/gb/collection1 node=127.0.0.1:35683_vhjv%2Fgb C67_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=down, node_name=127.0.0.1:35683_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:35683/vhjv/gb}
[junit4:junit4]   2> 16223 T1357 C67 P35683 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16223 T1355 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16223 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16224 T1357 C67 P35683 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16224 T1357 C67 P35683 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16224 T1280 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 16224 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16225 T1357 C67 P35683 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16225 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16298 T1280 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16300 T1280 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52322
[junit4:junit4]   2> 16300 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16301 T1280 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16301 T1280 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854
[junit4:junit4]   2> 16302 T1280 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/solr.xml
[junit4:junit4]   2> 16302 T1280 oasc.CoreContainer.<init> New CoreContainer 16963808
[junit4:junit4]   2> 16302 T1280 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/'
[junit4:junit4]   2> 16303 T1280 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/'
[junit4:junit4]   2> 16323 T1280 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16324 T1280 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16324 T1280 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16325 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16325 T1280 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16325 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16326 T1280 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16326 T1280 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16326 T1280 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16327 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16334 T1280 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16347 T1280 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54423/solr
[junit4:junit4]   2> 16348 T1280 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16348 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@364f67
[junit4:junit4]   2> 16349 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16349 T1368 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16350 T1368 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 16350 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32840
[junit4:junit4]   2> 16350 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32840
[junit4:junit4]   2> 16351 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d0000b with negotiated timeout 20000 for client /127.0.0.1:32840
[junit4:junit4]   2> 16351 T1368 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d0000b, negotiated timeout = 20000
[junit4:junit4]   2> 16351 T1369 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@364f67 name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16352 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16353 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d0000b
[junit4:junit4]   2> 16353 T1369 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16353 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d0000b closed
[junit4:junit4]   2> 16353 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32840 which had sessionid 0x13d83a565d0000b
[junit4:junit4]   2> 16354 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16356 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ba32a0
[junit4:junit4]   2> 16357 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16358 T1370 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16358 T1370 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 16358 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32841
[junit4:junit4]   2> 16359 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32841
[junit4:junit4]   2> 16359 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d0000c with negotiated timeout 20000 for client /127.0.0.1:32841
[junit4:junit4]   2> 16360 T1370 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d0000c, negotiated timeout = 20000
[junit4:junit4]   2> 16360 T1371 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ba32a0 name:ZooKeeperConnection Watcher:127.0.0.1:54423/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16360 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16361 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16362 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16364 T1280 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17041 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17042 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35683_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35683/vhjv/gb"}
[junit4:junit4]   2> 17049 T1322 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> 17049 T1338 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> 17049 T1302 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> 17049 T1371 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> 17049 T1309 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> 17049 T1354 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> 17229 T1315 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&nodeName=127.0.0.1:35683_vhjv%252Fgb&onlyIfLeader=true&coreNodeName=4&state=recovering&checkLive=true&wt=javabin&action=PREPRECOVERY&core=collection1} status=0 QTime=1000 
[junit4:junit4]   2> 17366 T1280 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52322_vhjv%2Fgb
[junit4:junit4]   2> 17367 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52322_vhjv%2Fgb Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52322_vhjv%2Fgb
[junit4:junit4]   2> 17368 T1280 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52322_vhjv%2Fgb
[junit4:junit4]   2> 17370 T1309 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> 17370 T1322 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> 17370 T1338 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> 17371 T1371 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17371 T1302 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> 17371 T1354 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17372 T1371 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> 17372 T1354 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> 17373 T1309 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17374 T1338 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17374 T1322 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17374 T1302 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17380 T1372 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/collection1
[junit4:junit4]   2> 17380 T1372 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17381 T1372 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17381 T1372 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17382 T1372 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/collection1/'
[junit4:junit4]   2> 17382 T1372 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/collection1/lib/README' to classloader
[junit4:junit4]   2> 17383 T1372 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17423 T1372 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 17461 T1372 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17462 T1372 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17466 T1372 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17884 T1372 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 17889 T1372 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 17892 T1372 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 17905 T1372 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17909 T1372 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17912 T1372 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17913 T1372 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17913 T1372 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17914 T1372 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17915 T1372 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17915 T1372 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17915 T1372 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17915 T1372 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363713303854/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/
[junit4:junit4]   2> 17916 T1372 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 17916 T1372 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17916 T1372 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4 forceNew: false
[junit4:junit4]   2> 17917 T1372 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/index/
[junit4:junit4]   2> 17917 T1372 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 17917 T1372 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/index forceNew: false
[junit4:junit4]   2> 17918 T1372 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f95d94 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5882c4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17918 T1372 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17920 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 17920 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 17920 T1372 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 17921 T1372 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 17921 T1372 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 17921 T1372 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 17922 T1372 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 17922 T1372 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 17922 T1372 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 17925 T1372 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 17927 T1372 oass.SolrIndexSearcher.<init> Opening Searcher@1ef8ccc main
[junit4:junit4]   2> 17927 T1372 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/tlog
[junit4:junit4]   2> 17928 T1372 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 17928 T1372 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 17939 T1373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ef8ccc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 17940 T1372 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 17940 T1372 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18555 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18556 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52322_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52322/vhjv/gb"}
[junit4:junit4]   2> 18556 T1303 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18556 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 18559 T1338 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> 18559 T1302 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> 18559 T1354 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> 18559 T1371 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> 18559 T1309 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> 18559 T1322 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> 18941 T1372 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 18942 T1372 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52322/vhjv/gb collection:collection1 shard:shard2
[junit4:junit4]   2> 18944 T1372 oasc.ZkController.register We are http://127.0.0.1:52322/vhjv/gb/collection1/ and leader is http://127.0.0.1:37418/vhjv/gb/collection1/
[junit4:junit4]   2> 18945 T1372 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52322/vhjv/gb
[junit4:junit4]   2> 18945 T1372 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 18945 T1372 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C68 name=collection1 org.apache.solr.core.SolrCore@ed96c7 url=http://127.0.0.1:52322/vhjv/gb/collection1 node=127.0.0.1:52322_vhjv%2Fgb C68_STATE=coll:collection1 core:collection1 props:{collection=collection1, state=down, node_name=127.0.0.1:52322_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:52322/vhjv/gb}
[junit4:junit4]   2> 18945 T1374 C68 P52322 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 18946 T1372 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18946 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 18946 T1374 C68 P52322 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 18947 T1374 C68 P52322 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18947 T1280 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4]   2> 18947 T1374 C68 P52322 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18947 T1280 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 18948 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18951 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18952 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18956 T1315 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/onenodecollectioncore
[junit4:junit4]   2> 18956 T1315 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 18957 T1315 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 18957 T1315 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 18958 T1315 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 18958 T1315 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 18960 T1315 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 18960 T1315 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/onenodecollectioncore/'
[junit4:junit4]   2> 18989 T1315 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 19025 T1315 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19026 T1315 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19030 T1315 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C67_STATE=coll:collection1 core:collection1 props:{shard=shard1, collection=collection1, state=recovering, node_name=127.0.0.1:35683_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:35683/vhjv/gb}
[junit4:junit4]   2> 19230 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39008/vhjv/gb/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19230 T1357 C67 P35683 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35683/vhjv/gb START replicas=[http://127.0.0.1:39008/vhjv/gb/collection1/] nUpdates=100
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19231 T1357 C67 P35683 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39008/vhjv/gb/collection1/. core=collection1
[junit4:junit4]   2> 19231 T1357 C67 P35683 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C69 name=collection1 org.apache.solr.core.SolrCore@180aebd url=http://127.0.0.1:39008/vhjv/gb/collection1 node=127.0.0.1:39008_vhjv%2Fgb C69_STATE=coll:collection1 core:collection1 props:{shard=shard1, collection=collection1, state=active, node_name=127.0.0.1:39008_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:39008/vhjv/gb, leader=true}
[junit4:junit4]   2> 19235 T1316 C69 P39008 REQ /get {version=2&getVersions=100&wt=javabin&qt=/get&distrib=false} status=0 QTime=0 
[junit4:junit4]   2> 19238 T1318 C69 P39008 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19240 T1318 C69 P39008 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1be649d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca7e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19241 T1318 C69 P39008 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19241 T1318 C69 P39008 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1be649d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca7e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1be649d lockFactory=org.apache.lucene.store.NativeFSLockFactory@15ca7e),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19241 T1318 C69 P39008 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19242 T1318 C69 P39008 oass.SolrIndexSearcher.<init> Opening Searcher@1f3393b realtime
[junit4:junit4]   2> 19242 T1318 C69 P39008 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19242 T1318 C69 P39008 /update {version=2&commit_end_point=true&waitSearcher=true&commit=true&wt=javabin&softCommit=false&openSearcher=false} {commit=} 0 4
[junit4:junit4]   2> 19244 T1357 C67 P35683 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19244 T1357 C67 P35683 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19262 T1317 C69 P39008 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19263 T1317 C69 P39008 REQ /replication {version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=18 
[junit4:junit4]   2> 19264 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19264 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19264 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19266 T1318 C69 P39008 REQ /replication {version=2&wt=javabin&generation=2&qt=/replication&command=filelist} status=0 QTime=0 
[junit4:junit4]   2> 19266 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19267 T1357 C67 P35683 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty3/index.20130319101506892 forceNew: false
[junit4:junit4]   2> 19267 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@10c0f55 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1120d5c) fullCopy=false
[junit4:junit4]   2> 19269 T1316 C69 P39008 REQ /replication {checksum=true&file=segments_2&wt=filestream&generation=2&qt=/replication&command=filecontent} status=0 QTime=0 
[junit4:junit4]   2> 19270 T1357 C67 P35683 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19272 T1357 C67 P35683 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19272 T1357 C67 P35683 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19273 T1357 C67 P35683 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ba1fa6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8105d),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@ba1fa6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b8105d),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19273 T1357 C67 P35683 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19273 T1357 C67 P35683 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19273 T1357 C67 P35683 oass.SolrIndexSearcher.<init> Opening Searcher@bb80e3 main
[junit4:junit4]   2> 19274 T1356 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bb80e3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19275 T1357 C67 P35683 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19275 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19275 T1357 C67 P35683 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19275 T1357 C67 P35683 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19276 T1357 C67 P35683 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19457 T1315 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19464 T1315 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19467 T1315 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19479 T1315 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19482 T1315 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19485 T1315 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19486 T1315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19486 T1315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19486 T1315 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19487 T1315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19487 T1315 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19488 T1315 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19488 T1315 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363713291108/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/
[junit4:junit4]   2> 19488 T1315 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1c15d6d
[junit4:junit4]   2> 19489 T1315 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19489 T1315 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection forceNew: false
[junit4:junit4]   2> 19490 T1315 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/index/
[junit4:junit4]   2> 19490 T1315 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19490 T1315 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/index forceNew: false
[junit4:junit4]   2> 19491 T1315 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@91026f lockFactory=org.apache.lucene.store.NativeFSLockFactory@1250909),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19492 T1315 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19493 T1315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19494 T1315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19494 T1315 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19494 T1315 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19495 T1315 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19495 T1315 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19495 T1315 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19496 T1315 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19496 T1315 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19499 T1315 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19501 T1315 oass.SolrIndexSearcher.<init> Opening Searcher@9d79f9 main
[junit4:junit4]   2> 19501 T1315 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/tlog
[junit4:junit4]   2> 19502 T1315 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19502 T1315 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19506 T1378 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@9d79f9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19507 T1315 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20064 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20065 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52322_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52322/vhjv/gb"}
[junit4:junit4]   2> 20068 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35683_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35683/vhjv/gb"}
[junit4:junit4]   2> 20070 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 20071 T1303 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20071 T1303 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20074 T1338 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> 20074 T1309 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> 20074 T1371 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> 20075 T1302 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> 20074 T1322 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> 20074 T1354 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> 20508 T1315 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20509 T1315 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:39008/vhjv/gb collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20510 T1315 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20515 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:delete cxid:0xac zxid:0xc2 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 20515 T1315 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20516 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20517 T1315 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20517 T1315 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20518 T1315 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39008/vhjv/gb/onenodecollectioncore/
[junit4:junit4]   2> 20518 T1315 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20518 T1315 oasc.SyncStrategy.syncToMe http://127.0.0.1:39008/vhjv/gb/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20519 T1315 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39008/vhjv/gb/onenodecollectioncore/
[junit4:junit4]   2> 20519 T1315 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20522 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20951 T1331 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&nodeName=127.0.0.1:52322_vhjv%252Fgb&onlyIfLeader=true&coreNodeName=5&state=recovering&checkLive=true&wt=javabin&action=PREPRECOVERY&core=collection1} status=0 QTime=2000 
[junit4:junit4]   2> 21583 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21599 T1371 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> 21599 T1309 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> 21599 T1338 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> 21599 T1322 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> 21599 T1302 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> 21599 T1354 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> 21625 T1315 oasc.ZkController.register We are http://127.0.0.1:39008/vhjv/gb/onenodecollectioncore/ and leader is http://127.0.0.1:39008/vhjv/gb/onenodecollectioncore/
[junit4:junit4]   2> 21626 T1315 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:39008/vhjv/gb
[junit4:junit4]   2> 21626 T1315 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21626 T1315 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21627 T1315 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21628 T1315 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&collection=onenodecollection&roles=none&numShards=1&name=onenodecollectioncore&wt=javabin&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection&action=CREATE} status=0 QTime=2672 
[junit4:junit4]   2> 21629 T1280 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21630 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22631 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C68_STATE=coll:collection1 core:collection1 props:{shard=shard2, collection=collection1, state=recovering, node_name=127.0.0.1:52322_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:52322/vhjv/gb}
[junit4:junit4]   2> 22952 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:37418/vhjv/gb/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 22953 T1374 C68 P52322 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52322/vhjv/gb START replicas=[http://127.0.0.1:37418/vhjv/gb/collection1/] nUpdates=100
[junit4:junit4]   2> 22954 T1374 C68 P52322 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 22954 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 22954 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 22955 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 22955 T1374 C68 P52322 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 22956 T1374 C68 P52322 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:37418/vhjv/gb/collection1/. core=collection1
[junit4:junit4]   2> 22956 T1374 C68 P52322 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@bd6b6f url=http://127.0.0.1:37418/vhjv/gb/collection1 node=127.0.0.1:37418_vhjv%2Fgb C70_STATE=coll:collection1 core:collection1 props:{shard=shard2, collection=collection1, state=active, node_name=127.0.0.1:37418_vhjv%2Fgb, core=collection1, base_url=http://127.0.0.1:37418/vhjv/gb, leader=true}
[junit4:junit4]   2> 22962 T1334 C70 P37418 REQ /get {version=2&getVersions=100&wt=javabin&qt=/get&distrib=false} status=0 QTime=0 
[junit4:junit4]   2> 22963 T1333 C70 P37418 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 22964 T1333 C70 P37418 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19394ef lockFactory=org.apache.lucene.store.NativeFSLockFactory@148a4c3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 22965 T1333 C70 P37418 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 22965 T1333 C70 P37418 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19394ef lockFactory=org.apache.lucene.store.NativeFSLockFactory@148a4c3),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@19394ef lockFactory=org.apache.lucene.store.NativeFSLockFactory@148a4c3),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22965 T1333 C70 P37418 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22966 T1333 C70 P37418 oass.SolrIndexSearcher.<init> Opening Searcher@d4d63c realtime
[junit4:junit4]   2> 22966 T1333 C70 P37418 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 22966 T1333 C70 P37418 /update {version=2&commit_end_point=true&waitSearcher=true&commit=true&wt=javabin&softCommit=false&openSearcher=false} {commit=} 0 3
[junit4:junit4]   2> 22967 T1374 C68 P52322 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22967 T1374 C68 P52322 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 22969 T1334 C70 P37418 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22969 T1334 C70 P37418 REQ /replication {version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=1 
[junit4:junit4]   2> 22969 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 22970 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 22970 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 22972 T1332 C70 P37418 REQ /replication {version=2&wt=javabin&generation=2&qt=/replication&command=filelist} status=0 QTime=1 
[junit4:junit4]   2> 22972 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 22973 T1374 C68 P52322 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty4/index.20130319101510598 forceNew: false
[junit4:junit4]   2> 22973 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@f674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17d1611) fullCopy=false
[junit4:junit4]   2> 22975 T1333 C70 P37418 REQ /replication {checksum=true&file=segments_2&wt=filestream&generation=2&qt=/replication&command=filecontent} status=0 QTime=0 
[junit4:junit4]   2> 22976 T1374 C68 P52322 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 22977 T1374 C68 P52322 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 22977 T1374 C68 P52322 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 22978 T1374 C68 P52322 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f95d94 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5882c4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@f95d94 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5882c4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22978 T1374 C68 P52322 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22979 T1374 C68 P52322 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 22979 T1374 C68 P52322 oass.SolrIndexSearcher.<init> Opening Searcher@597b9f main
[junit4:junit4]   2> 22980 T1373 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@597b9f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 22980 T1374 C68 P52322 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 22981 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 22981 T1374 C68 P52322 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 22981 T1374 C68 P52322 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 22982 T1374 C68 P52322 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23104 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23105 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39008_vhjv%2Fgb_onenodecollectioncore",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 23107 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52322_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52322/vhjv/gb"}
[junit4:junit4]   2> 23111 T1322 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> 23111 T1309 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> 23111 T1302 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> 23111 T1371 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> 23111 T1338 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> 23111 T1354 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> 23633 T1280 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23634 T1280 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23635 T1280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23639 T1280 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54423 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@11ae5d8
[junit4:junit4]   2> 23640 T1280 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23640 T1381 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54423. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23640 T1381 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54423, initiating session
[junit4:junit4]   2> 23641 T1282 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:32862
[junit4:junit4]   2> 23641 T1282 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:32862
[junit4:junit4]   2> 23642 T1284 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d83a565d0000d with negotiated timeout 10000 for client /127.0.0.1:32862
[junit4:junit4]   2> 23642 T1381 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54423, sessionid = 0x13d83a565d0000d, negotiated timeout = 10000
[junit4:junit4]   2> 23642 T1382 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11ae5d8 name:ZooKeeperConnection Watcher:127.0.0.1:54423 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23642 T1280 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23671 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d0000d
[junit4:junit4]   2> 23672 T1382 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23672 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32862 which had sessionid 0x13d83a565d0000d
[junit4:junit4]   2> 23672 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d0000d closed
[junit4:junit4]   2> 23673 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00004
[junit4:junit4]   2> 23673 T1309 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23673 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00004 closed
[junit4:junit4]   2> 23673 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32789 which had sessionid 0x13d83a565d00004
[junit4:junit4]   2> 23675 T1280 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40419
[junit4:junit4]   2> 23675 T1280 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=5890984
[junit4:junit4]   2> 24616 T1303 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24616 T1303 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40419_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40419/vhjv/gb"}
[junit4:junit4]   2> 24620 T1302 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> 24620 T1322 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> 24620 T1338 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> 24620 T1371 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> 24620 T1354 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 T1280 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25677 T1280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25680 T1280 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@143b267
[junit4:junit4]   2> 25683 T1280 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> 25684 T1280 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25684 T1280 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25684 T1280 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25685 T1280 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25685 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data
[junit4:junit4]   2> 25686 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data
[junit4:junit4]   2> 25686 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/index
[junit4:junit4]   2> 25686 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/control/data/index
[junit4:junit4]   2> 25687 T1303 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89372314018250755-127.0.0.1:40419_vhjv%2Fgb-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25688 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00003
[junit4:junit4]   2> 25689 T1371 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> 25689 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32784 which had sessionid 0x13d83a565d00003
[junit4:junit4]   2> 25689 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00003 closed
[junit4:junit4]   2> 25690 T1354 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25690 T1338 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25703 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:delete cxid:0xc6 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25704 T1354 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> 25704 T1338 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> 25705 T1322 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25705 T1371 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25706 T1322 oasc.Overseer.start Overseer (id=89372314018250758-127.0.0.1:39008_vhjv%2Fgb-n_0000000001) starting
[junit4:junit4]   2> 25707 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xcb zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25707 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xcc zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25708 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xce zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25709 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00006 type:create cxid:0xd0 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25710 T1384 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25710 T1322 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25711 T1322 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> 25711 T1383 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25713 T1383 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25713 T1383 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:40419_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:40419/vhjv/gb"}
[junit4:junit4]   2> 25714 T1280 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/vhjv/gb,null}
[junit4:junit4]   2> 25716 T1371 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> 25716 T1338 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> 25716 T1322 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> 25716 T1354 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> 25765 T1280 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 39008
[junit4:junit4]   2> 25766 T1280 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=27165641
[junit4:junit4]   2> 26989 T1302 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26989 T1302 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> 26990 T1302 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 26990 T1302 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 27220 T1383 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27221 T1383 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 27224 T1383 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:39008_vhjv%2Fgb_onenodecollectioncore",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39008_vhjv%2Fgb",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39008/vhjv/gb"}
[junit4:junit4]   2> 28019 T1371 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> 28019 T1354 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> 28019 T1338 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> 28019 T1322 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> 29769 T1280 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 29770 T1280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 29772 T1280 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 29774 T1280 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@180aebd
[junit4:junit4]   2> 29778 T1280 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4]   2> 29778 T1280 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29779 T1280 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29779 T1280 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29781 T1280 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 29781 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/index
[junit4:junit4]   2> 29782 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1/index
[junit4:junit4]   2> 29782 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1
[junit4:junit4]   2> 29782 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363713287629/jetty1
[junit4:junit4]   2> 29783 T1280 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@37fd87
[junit4:junit4]   2> 29790 T1280 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> 29791 T1280 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29791 T1280 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29792 T1280 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29792 T1280 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 29793 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection
[junit4:junit4]   2> 29793 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection
[junit4:junit4]   2> 29793 T1280 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/index
[junit4:junit4]   2> 29794 T1280 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1363713287629/onenodecollection/index
[junit4:junit4]   2> 29795 T1383 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89372314018250758-127.0.0.1:39008_vhjv%2Fgb-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 29795 T1285 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d83a565d00006
[junit4:junit4]   2> 29796 T1371 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> 29796 T1282 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:32791 which had sessionid 0x13d83a565d00006
[junit4:junit4]   2> 29796 T1322 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> 29796 T1322 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 29796 T1280 oaz.ZooKeeper.close Session: 0x13d83a565d00006 closed
[junit4:junit4]   2> 29797 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:delete cxid:0x7c zxid:0xf9 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 29797 T1322 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 29797 T1322 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 29797 T1354 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29800 T1354 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> 29800 T1338 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 29801 T1371 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 29803 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000a type:delete cxid:0x61 zxid:0xfb txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 29803 T1338 oasc.Overseer.start Overseer (id=89372314018250760-127.0.0.1:37418_vhjv%2Fgb-n_0000000002) starting
[junit4:junit4]   2> 29803 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x81 zxid:0xfc txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29803 T1354 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 29804 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d0000a type:create cxid:0x62 zxid:0xfd txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29804 T1285 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d83a565d00008 type:create cxid:0x82 zxid:0xfe txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 29806 T1285 oazs.PrepRequestProcessor.pRequest G

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

 J0 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: org.apache.solr.common.SolrException: Server at http://127.0.0.1:37418/vhjv/gb/onenodecollectioncore returned non ok status:404, message:Can not find: /vhjv/gb/onenodecollectioncore/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([D0104395F3A74714:51F6CD8D84F82728]: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:89)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]    > 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    > 	at java.lang.reflect.Method.invoke(Method.java:487)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 33195 T1280 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 33199 T1279 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4]   2> 33374 T1283 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 34411 T1371 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 34411 T1371 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> 34411 T1371 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 34412 T1371 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=sv, timezone=America/Tijuana
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=48873424,total=177418240
[junit4:junit4]   2> NOTE: All tests run in this JVM: [CSVRequestHandlerTest, TestPluginEnable, TestPropInjectDefaults, DistributedQueryElevationComponentTest, TestExtendedDismaxParser, SolrIndexSplitterTest, TestRemoteStreaming, SolrTestCaseJ4Test, LukeRequestHandlerTest, UnloadDistributedZkTest, TestQueryUtils, TestFunctionQuery, MBeansHandlerTest, TestQuerySenderListener, TestLRUCache, TestStressRecovery, TestCharFilters, FastVectorHighlighterTest, TestSolrDeletionPolicy1, TestPhraseSuggestions, SolrCoreTest, SuggesterTest, TermVectorComponentTest, SystemInfoHandlerTest, ResponseLogComponentTest, TestRealTimeGet, TestFieldResource, DirectUpdateHandlerOptimizeTest, TestSolrIndexConfig, TestGroupingSearch, TestFuzzyAnalyzedSuggestions, TestStressVersions, RAMDirectoryFactoryTest, LeaderElectionTest, DocumentBuilderTest, TestFastLRUCache, PrimUtilsTest, TestJoin, TestLFUCache, SyncSliceTest, UpdateRequestProcessorFactoryTest, QueryEqualityTest, TestSearchPerf, ResourceLoaderTest, TestConfig, MoreLikeThisHandlerTest, TestRandomDVFaceting, TestSweetSpotSimilarityFactory, TestDocSet, TestSolrDeletionPolicy2, QueryParsingTest, FieldMutatingUpdateProcessorTest, QueryElevationComponentTest, SOLR749Test, DirectSolrConnectionTest, TestTrie, PrimitiveFieldTypeTest, SchemaVersionSpecificBehaviorTest, IndexSchemaTest, PluginInfoTest, ClusterStateUpdateTest, BinaryUpdateRequestHandlerTest, SolrInfoMBeanTest, ChaosMonkeyNothingIsSafeTest, OverseerCollectionProcessorTest, LoggingHandlerTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J0 in 34.48s, 1 test, 1 error <<< FAILURES!

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

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



Mime
View raw message