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 # 4780 - Failure!
Date Fri, 22 Mar 2013 13:15:35 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/4780/
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:35084/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update

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




Build Log:
[...truncated 9457 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T910 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 3 T910 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746
[junit4:junit4]   2> 4 T910 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 4 T911 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 5 T911 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 5 T911 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 5 T911 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 5 T911 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 6 T911 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 104 T910 oasc.ZkTestServer.run start zk server on port:54167
[junit4:junit4]   2> 105 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@19d02bf
[junit4:junit4]   2> 105 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 106 T916 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 106 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39834
[junit4:junit4]   2> 106 T916 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 107 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39834
[junit4:junit4]   2> 107 T914 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 202 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450000 with negotiated timeout 10000 for client /127.0.0.1:39834
[junit4:junit4]   2> 202 T916 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450000, negotiated timeout = 10000
[junit4:junit4]   2> 203 T917 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19d02bf name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 203 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 203 T910 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 207 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450000
[junit4:junit4]   2> 207 T917 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 207 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39834 which had sessionid 0x13d9238d8450000
[junit4:junit4]   2> 207 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450000 closed
[junit4:junit4]   2> 208 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@15af8bc
[junit4:junit4]   2> 209 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 209 T918 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 209 T918 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 210 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39835
[junit4:junit4]   2> 210 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39835
[junit4:junit4]   2> 211 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450001 with negotiated timeout 10000 for client /127.0.0.1:39835
[junit4:junit4]   2> 211 T918 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450001, negotiated timeout = 10000
[junit4:junit4]   2> 211 T919 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15af8bc name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 211 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 211 T910 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 215 T910 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 216 T910 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 218 T910 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 220 T910 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> 220 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 223 T910 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> 224 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 226 T910 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> 227 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 228 T910 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> 229 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 230 T910 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> 231 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 233 T910 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> 233 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 235 T910 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> 235 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 237 T910 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> 237 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 239 T910 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> 240 T910 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 241 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450001
[junit4:junit4]   2> 242 T919 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 242 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39835 which had sessionid 0x13d9238d8450001
[junit4:junit4]   2> 242 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450001 closed
[junit4:junit4]   2> 300 T910 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 327 T910 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37340
[junit4:junit4]   2> 328 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 328 T910 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 329 T910 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986
[junit4:junit4]   2> 329 T910 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/solr.xml
[junit4:junit4]   2> 329 T910 oasc.CoreContainer.<init> New CoreContainer 7079465
[junit4:junit4]   2> 330 T910 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/'
[junit4:junit4]   2> 330 T910 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/'
[junit4:junit4]   2> 349 T910 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 349 T910 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 349 T910 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 350 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 350 T910 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 350 T910 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 351 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 351 T910 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 351 T910 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 352 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 366 T910 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 377 T910 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54167/solr
[junit4:junit4]   2> 378 T910 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 378 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7f1529
[junit4:junit4]   2> 379 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 379 T929 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 380 T929 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 380 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39836
[junit4:junit4]   2> 381 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39836
[junit4:junit4]   2> 381 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450002 with negotiated timeout 20000 for client /127.0.0.1:39836
[junit4:junit4]   2> 381 T929 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450002, negotiated timeout = 20000
[junit4:junit4]   2> 382 T930 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f1529 name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 382 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 384 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450002
[junit4:junit4]   2> 384 T930 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 384 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39836 which had sessionid 0x13d9238d8450002
[junit4:junit4]   2> 384 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450002 closed
[junit4:junit4]   2> 385 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 388 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@28eab7
[junit4:junit4]   2> 389 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 389 T931 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 389 T931 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 389 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39837
[junit4:junit4]   2> 390 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39837
[junit4:junit4]   2> 390 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450003 with negotiated timeout 20000 for client /127.0.0.1:39837
[junit4:junit4]   2> 390 T931 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450003, negotiated timeout = 20000
[junit4:junit4]   2> 391 T932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28eab7 name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 391 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 392 T910 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 394 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 395 T910 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 397 T910 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 399 T910 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37340_
[junit4:junit4]   2> 399 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37340_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37340_
[junit4:junit4]   2> 400 T910 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37340_
[junit4:junit4]   2> 402 T910 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 405 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 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> 406 T910 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 408 T910 oasc.Overseer.start Overseer (id=89388340461502467-127.0.0.1:37340_-n_0000000000) starting
[junit4:junit4]   2> 408 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 409 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 410 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 410 T910 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 412 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 413 T934 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 414 T910 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 416 T910 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 417 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 419 T933 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 422 T935 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/collection1
[junit4:junit4]   2> 422 T935 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 423 T935 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 423 T935 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 424 T935 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/collection1/'
[junit4:junit4]   2> 424 T935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/collection1/lib/README' to classloader
[junit4:junit4]   2> 425 T935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 460 T935 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 499 T935 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 500 T935 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 513 T935 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 994 T935 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1002 T935 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1006 T935 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1015 T935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1019 T935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1023 T935 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1024 T935 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1026 T935 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1026 T935 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1027 T935 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1027 T935 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1027 T935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1028 T935 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363957831986/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/
[junit4:junit4]   2> 1028 T935 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 1028 T935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1029 T935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data
[junit4:junit4]   2> 1029 T935 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/index/
[junit4:junit4]   2> 1030 T935 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1030 T935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/index
[junit4:junit4]   2> 1032 T935 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5194da lockFactory=org.apache.lucene.store.NativeFSLockFactory@115c2),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1032 T935 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1034 T935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1034 T935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1035 T935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1035 T935 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1036 T935 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1036 T935 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1036 T935 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1037 T935 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1037 T935 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1041 T935 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1044 T935 oass.SolrIndexSearcher.<init> Opening Searcher@10f34fc main
[junit4:junit4]   2> 1045 T935 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/tlog
[junit4:junit4]   2> 1045 T935 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1045 T935 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1049 T936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10f34fc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1049 T935 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1049 T935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1922 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1923 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37340_",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37340",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 1923 T933 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1923 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 1926 T932 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> 2050 T935 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2051 T935 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37340 collection:control_collection shard:shard1
[junit4:junit4]   2> 2052 T935 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2057 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 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> 2058 T935 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2058 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2060 T935 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2060 T935 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2061 T935 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37340/collection1/
[junit4:junit4]   2> 2061 T935 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2061 T935 oasc.SyncStrategy.syncToMe http://127.0.0.1:37340/collection1/ has no replicas
[junit4:junit4]   2> 2061 T935 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37340/collection1/
[junit4:junit4]   2> 2062 T935 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2065 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3428 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3433 T932 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> 3469 T935 oasc.ZkController.register We are http://127.0.0.1:37340/collection1/ and leader is http://127.0.0.1:37340/collection1/
[junit4:junit4]   2> 3469 T935 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37340
[junit4:junit4]   2> 3470 T935 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3470 T935 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3470 T935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3471 T935 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3472 T910 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3473 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3473 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3476 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3477 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1e3da96
[junit4:junit4]   2> 3477 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3478 T938 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3478 T938 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 3478 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39838
[junit4:junit4]   2> 3484 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39838
[junit4:junit4]   2> 3484 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450004 with negotiated timeout 10000 for client /127.0.0.1:39838
[junit4:junit4]   2> 3484 T938 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450004, negotiated timeout = 10000
[junit4:junit4]   2> 3485 T939 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e3da96 name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3485 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3486 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3488 T910 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3543 T910 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3545 T910 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52986
[junit4:junit4]   2> 3545 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3545 T910 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3546 T910 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231
[junit4:junit4]   2> 3546 T910 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/solr.xml
[junit4:junit4]   2> 3546 T910 oasc.CoreContainer.<init> New CoreContainer 16962583
[junit4:junit4]   2> 3547 T910 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/'
[junit4:junit4]   2> 3547 T910 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/'
[junit4:junit4]   2> 3565 T910 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3565 T910 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3566 T910 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3566 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3566 T910 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3567 T910 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3567 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3567 T910 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3568 T910 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3568 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3574 T910 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3586 T910 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54167/solr
[junit4:junit4]   2> 3586 T910 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3587 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@5c0c4b
[junit4:junit4]   2> 3587 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3588 T949 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3588 T949 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 3588 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39839
[junit4:junit4]   2> 3589 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39839
[junit4:junit4]   2> 3589 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450005 with negotiated timeout 20000 for client /127.0.0.1:39839
[junit4:junit4]   2> 3589 T949 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450005, negotiated timeout = 20000
[junit4:junit4]   2> 3590 T950 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5c0c4b name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3590 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3591 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450005
[junit4:junit4]   2> 3591 T950 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3591 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39839 which had sessionid 0x13d9238d8450005
[junit4:junit4]   2> 3591 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450005 closed
[junit4:junit4]   2> 3592 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3595 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@177f5de
[junit4:junit4]   2> 3596 T951 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3596 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3596 T951 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 3596 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39840
[junit4:junit4]   2> 3597 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39840
[junit4:junit4]   2> 3597 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450006 with negotiated timeout 20000 for client /127.0.0.1:39840
[junit4:junit4]   2> 3597 T951 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450006, negotiated timeout = 20000
[junit4:junit4]   2> 3598 T952 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@177f5de name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3598 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3599 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3600 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3601 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4604 T910 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52986_
[junit4:junit4]   2> 4605 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52986_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52986_
[junit4:junit4]   2> 4605 T910 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52986_
[junit4:junit4]   2> 4607 T932 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> 4608 T952 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4608 T939 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4609 T932 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4613 T953 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/collection1
[junit4:junit4]   2> 4613 T953 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4614 T953 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4614 T953 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4614 T953 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/collection1/'
[junit4:junit4]   2> 4615 T953 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/collection1/lib/README' to classloader
[junit4:junit4]   2> 4615 T953 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4649 T953 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 4692 T953 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4693 T953 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4698 T953 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4937 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 4937 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37340_",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37340",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 4940 T932 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> 4940 T939 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> 4940 T952 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> 5186 T953 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5193 T953 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5196 T953 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5212 T953 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5215 T953 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5218 T953 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5219 T953 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5220 T953 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5221 T953 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5222 T953 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5222 T953 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5222 T953 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5222 T953 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/
[junit4:junit4]   2> 5222 T953 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 5223 T953 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5223 T953 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1
[junit4:junit4]   2> 5223 T953 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/index/
[junit4:junit4]   2> 5224 T953 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5224 T953 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/index
[junit4:junit4]   2> 5225 T953 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1bb6d25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f4559f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5225 T953 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5227 T953 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5227 T953 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5228 T953 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5228 T953 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5229 T953 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5229 T953 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5229 T953 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5230 T953 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5230 T953 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5232 T953 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5235 T953 oass.SolrIndexSearcher.<init> Opening Searcher@1966523 main
[junit4:junit4]   2> 5235 T953 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/tlog
[junit4:junit4]   2> 5236 T953 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5236 T953 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5240 T954 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1966523 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5242 T953 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5242 T953 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6444 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6445 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 6445 T933 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6445 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6449 T952 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> 6449 T939 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> 6449 T932 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> 7243 T953 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7243 T953 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52986 collection:collection1 shard:shard1
[junit4:junit4]   2> 7244 T953 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7248 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 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> 7249 T953 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7249 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7251 T953 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7251 T953 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7251 T953 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52986/collection1/
[junit4:junit4]   2> 7252 T953 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7252 T953 oasc.SyncStrategy.syncToMe http://127.0.0.1:52986/collection1/ has no replicas
[junit4:junit4]   2> 7252 T953 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52986/collection1/
[junit4:junit4]   2> 7252 T953 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7255 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7952 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 7958 T932 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> 7958 T939 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> 7959 T952 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> 8010 T953 oasc.ZkController.register We are http://127.0.0.1:52986/collection1/ and leader is http://127.0.0.1:52986/collection1/
[junit4:junit4]   2> 8010 T953 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52986
[junit4:junit4]   2> 8010 T953 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8010 T953 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8011 T953 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8012 T953 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8013 T910 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 8013 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8014 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8075 T910 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8080 T910 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35084
[junit4:junit4]   2> 8081 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8082 T910 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8082 T910 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760
[junit4:junit4]   2> 8083 T910 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/solr.xml
[junit4:junit4]   2> 8083 T910 oasc.CoreContainer.<init> New CoreContainer 2477431
[junit4:junit4]   2> 8084 T910 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/'
[junit4:junit4]   2> 8084 T910 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/'
[junit4:junit4]   2> 8112 T910 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8113 T910 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8113 T910 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8114 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8114 T910 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8115 T910 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8115 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8116 T910 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8116 T910 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8117 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8127 T910 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8153 T910 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54167/solr
[junit4:junit4]   2> 8154 T910 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8154 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1626ed
[junit4:junit4]   2> 8155 T965 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8155 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8156 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39843
[junit4:junit4]   2> 8156 T965 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 8157 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39843
[junit4:junit4]   2> 8158 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450007 with negotiated timeout 20000 for client /127.0.0.1:39843
[junit4:junit4]   2> 8158 T965 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450007, negotiated timeout = 20000
[junit4:junit4]   2> 8158 T966 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1626ed name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8158 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8159 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450007
[junit4:junit4]   2> 8160 T966 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8160 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39843 which had sessionid 0x13d9238d8450007
[junit4:junit4]   2> 8160 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450007 closed
[junit4:junit4]   2> 8161 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8165 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f2e9c4
[junit4:junit4]   2> 8166 T967 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8166 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8166 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39844
[junit4:junit4]   2> 8166 T967 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 8167 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39844
[junit4:junit4]   2> 8167 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450008 with negotiated timeout 20000 for client /127.0.0.1:39844
[junit4:junit4]   2> 8168 T967 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450008, negotiated timeout = 20000
[junit4:junit4]   2> 8168 T968 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f2e9c4 name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8168 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8169 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8170 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8172 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9174 T910 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35084_
[junit4:junit4]   2> 9175 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:35084_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:35084_
[junit4:junit4]   2> 9176 T910 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35084_
[junit4:junit4]   2> 9178 T932 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> 9178 T952 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> 9179 T939 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9179 T968 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9179 T939 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> 9180 T932 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9180 T952 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9186 T969 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/collection1
[junit4:junit4]   2> 9186 T969 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9187 T969 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9187 T969 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9188 T969 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/collection1/'
[junit4:junit4]   2> 9189 T969 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/collection1/lib/README' to classloader
[junit4:junit4]   2> 9189 T969 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9215 T969 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 9258 T969 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9259 T969 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9263 T969 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9463 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9464 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 9467 T939 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> 9467 T952 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> 9467 T932 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> 9467 T968 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> 9705 T969 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9711 T969 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9714 T969 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9725 T969 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9730 T969 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9733 T969 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9735 T969 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9735 T969 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9735 T969 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9736 T969 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9737 T969 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9737 T969 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9737 T969 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363957839760/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2/
[junit4:junit4]   2> 9737 T969 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 9738 T969 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9738 T969 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2
[junit4:junit4]   2> 9738 T969 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2/index/
[junit4:junit4]   2> 9738 T969 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9739 T969 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2/index
[junit4:junit4]   2> 9740 T969 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1aa275d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ccd5d4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9740 T969 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9741 T969 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9742 T969 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9742 T969 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9742 T969 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9743 T969 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9743 T969 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9743 T969 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9744 T969 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9744 T969 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9746 T969 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9749 T969 oass.SolrIndexSearcher.<init> Opening Searcher@1e545a7 main
[junit4:junit4]   2> 9749 T969 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty2/tlog
[junit4:junit4]   2> 9749 T969 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9750 T969 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9754 T970 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e545a7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9755 T969 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9756 T969 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 10977 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 10977 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35084_",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35084",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 10977 T933 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 10978 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 10981 T968 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> 10981 T939 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> 10981 T952 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> 10981 T932 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> 11757 T969 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11757 T969 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35084 collection:collection1 shard:shard2
[junit4:junit4]   2> 11758 T969 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 11762 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 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> 11763 T969 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11763 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11764 T969 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11765 T969 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11765 T969 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:35084/collection1/
[junit4:junit4]   2> 11765 T969 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11765 T969 oasc.SyncStrategy.syncToMe http://127.0.0.1:35084/collection1/ has no replicas
[junit4:junit4]   2> 11765 T969 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:35084/collection1/
[junit4:junit4]   2> 11766 T969 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 11768 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12484 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12491 T932 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> 12491 T952 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> 12491 T939 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> 12491 T968 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> 12521 T969 oasc.ZkController.register We are http://127.0.0.1:35084/collection1/ and leader is http://127.0.0.1:35084/collection1/
[junit4:junit4]   2> 12521 T969 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35084
[junit4:junit4]   2> 12521 T969 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12522 T969 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12522 T969 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12524 T969 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12525 T910 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12525 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12525 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12590 T910 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12598 T910 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57476
[junit4:junit4]   2> 12599 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12599 T910 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12600 T910 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273
[junit4:junit4]   2> 12600 T910 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/solr.xml
[junit4:junit4]   2> 12600 T910 oasc.CoreContainer.<init> New CoreContainer 2390713
[junit4:junit4]   2> 12601 T910 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/'
[junit4:junit4]   2> 12601 T910 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/'
[junit4:junit4]   2> 12619 T910 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12619 T910 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12619 T910 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12620 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12620 T910 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12620 T910 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12621 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12621 T910 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12621 T910 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12622 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12628 T910 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12639 T910 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54167/solr
[junit4:junit4]   2> 12640 T910 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12640 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2226e0
[junit4:junit4]   2> 12641 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12641 T981 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12642 T981 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 12642 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39846
[junit4:junit4]   2> 12642 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39846
[junit4:junit4]   2> 12643 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d8450009 with negotiated timeout 20000 for client /127.0.0.1:39846
[junit4:junit4]   2> 12643 T981 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d8450009, negotiated timeout = 20000
[junit4:junit4]   2> 12643 T982 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2226e0 name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12643 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12645 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450009
[junit4:junit4]   2> 12646 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39846 which had sessionid 0x13d9238d8450009
[junit4:junit4]   2> 12646 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450009 closed
[junit4:junit4]   2> 12646 T982 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12646 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12650 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1266633
[junit4:junit4]   2> 12652 T983 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12652 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12652 T983 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 12652 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39847
[junit4:junit4]   2> 12653 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39847
[junit4:junit4]   2> 12653 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d845000a with negotiated timeout 20000 for client /127.0.0.1:39847
[junit4:junit4]   2> 12653 T983 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d845000a, negotiated timeout = 20000
[junit4:junit4]   2> 12654 T984 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1266633 name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12654 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12655 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12656 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12657 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13660 T910 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57476_
[junit4:junit4]   2> 13661 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:57476_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:57476_
[junit4:junit4]   2> 13662 T910 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57476_
[junit4:junit4]   2> 13665 T932 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> 13665 T968 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13665 T952 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13665 T968 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> 13665 T952 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> 13666 T939 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13666 T984 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13666 T939 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> 13667 T932 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13671 T985 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/collection1
[junit4:junit4]   2> 13671 T985 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13672 T985 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13672 T985 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13674 T985 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/collection1/'
[junit4:junit4]   2> 13674 T985 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/collection1/lib/README' to classloader
[junit4:junit4]   2> 13675 T985 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13723 T985 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 13779 T985 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13780 T985 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13785 T985 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 13996 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13997 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:35084_",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:35084",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 14000 T932 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> 14000 T968 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> 14000 T939 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> 14001 T984 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> 14003 T952 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> 14225 T985 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14231 T985 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14234 T985 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14244 T985 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14247 T985 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14250 T985 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14250 T985 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14251 T985 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14251 T985 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14252 T985 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14252 T985 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14252 T985 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14252 T985 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363957844273/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/
[junit4:junit4]   2> 14253 T985 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 14253 T985 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14253 T985 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3
[junit4:junit4]   2> 14254 T985 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/index/
[junit4:junit4]   2> 14254 T985 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14254 T985 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/index
[junit4:junit4]   2> 14255 T985 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@974660 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17ffcaf),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14255 T985 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14257 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14257 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14257 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14258 T985 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14258 T985 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14258 T985 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14259 T985 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14259 T985 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14259 T985 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14262 T985 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14273 T985 oass.SolrIndexSearcher.<init> Opening Searcher@17341f8 main
[junit4:junit4]   2> 14273 T985 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/tlog
[junit4:junit4]   2> 14274 T985 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14274 T985 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14278 T986 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17341f8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14279 T985 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14279 T985 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15505 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15506 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57476_",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57476",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 15506 T933 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15506 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 15511 T939 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> 15511 T984 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> 15511 T968 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> 15511 T952 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> 15511 T932 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> 16281 T985 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16281 T985 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57476 collection:collection1 shard:shard1
[junit4:junit4]   2> 16284 T985 oasc.ZkController.register We are http://127.0.0.1:57476/collection1/ and leader is http://127.0.0.1:52986/collection1/
[junit4:junit4]   2> 16285 T985 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57476
[junit4:junit4]   2> 16285 T985 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16285 T985 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C50 name=collection1 org.apache.solr.core.SolrCore@1bde86e url=http://127.0.0.1:57476/collection1 node=127.0.0.1:57476_ C50_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:57476_, state=down, base_url=http://127.0.0.1:57476, collection=collection1, core=collection1}
[junit4:junit4]   2> 16285 T987 C50 P57476 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16286 T985 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16286 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16286 T987 C50 P57476 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16286 T987 C50 P57476 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16287 T910 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16287 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16288 T987 C50 P57476 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16288 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16361 T910 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16363 T910 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55937
[junit4:junit4]   2> 16364 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16364 T910 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16365 T910 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034
[junit4:junit4]   2> 16365 T910 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/solr.xml
[junit4:junit4]   2> 16365 T910 oasc.CoreContainer.<init> New CoreContainer 4726245
[junit4:junit4]   2> 16366 T910 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/'
[junit4:junit4]   2> 16366 T910 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/'
[junit4:junit4]   2> 16387 T910 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16388 T910 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16388 T910 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16388 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16389 T910 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16389 T910 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16389 T910 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16390 T910 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16390 T910 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16391 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16398 T910 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16420 T910 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:54167/solr
[junit4:junit4]   2> 16421 T910 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16421 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4a4835
[junit4:junit4]   2> 16422 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16422 T998 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16423 T998 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 16423 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39849
[junit4:junit4]   2> 16424 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39849
[junit4:junit4]   2> 16425 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d845000b with negotiated timeout 20000 for client /127.0.0.1:39849
[junit4:junit4]   2> 16425 T998 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d845000b, negotiated timeout = 20000
[junit4:junit4]   2> 16425 T999 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a4835 name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16425 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16426 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d845000b
[junit4:junit4]   2> 16427 T999 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16427 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39849 which had sessionid 0x13d9238d845000b
[junit4:junit4]   2> 16427 T910 oaz.ZooKeeper.close Session: 0x13d9238d845000b closed
[junit4:junit4]   2> 16428 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16432 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d7a3c6
[junit4:junit4]   2> 16434 T1000 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16434 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16434 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39850
[junit4:junit4]   2> 16434 T1000 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 16435 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39850
[junit4:junit4]   2> 16436 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d845000c with negotiated timeout 20000 for client /127.0.0.1:39850
[junit4:junit4]   2> 16436 T1000 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d845000c, negotiated timeout = 20000
[junit4:junit4]   2> 16436 T1001 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d7a3c6 name:ZooKeeperConnection Watcher:127.0.0.1:54167/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16436 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16438 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16439 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16440 T910 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17014 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17015 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57476_",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57476",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 17018 T984 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> 17018 T932 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> 17018 T968 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> 17018 T939 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> 17018 T952 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> 17018 T1001 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> 17293 T948 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {checkLive=true&wt=javabin&coreNodeName=4&state=recovering&nodeName=127.0.0.1:57476_&action=PREPRECOVERY&onlyIfLeader=true&version=2&core=collection1} status=0 QTime=1001 
[junit4:junit4]   2> 17442 T910 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55937_
[junit4:junit4]   2> 17443 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:55937_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:55937_
[junit4:junit4]   2> 17444 T910 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55937_
[junit4:junit4]   2> 17447 T968 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> 17447 T952 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> 17447 T939 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> 17447 T984 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> 17447 T1001 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17447 T932 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17448 T1001 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> 17448 T932 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> 17450 T968 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17450 T952 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17450 T984 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17450 T939 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17454 T1002 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/collection1
[junit4:junit4]   2> 17454 T1002 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17455 T1002 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17455 T1002 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17456 T1002 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/collection1/'
[junit4:junit4]   2> 17456 T1002 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/collection1/lib/README' to classloader
[junit4:junit4]   2> 17457 T1002 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17484 T1002 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 17526 T1002 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17527 T1002 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17531 T1002 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 17964 T1002 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 17970 T1002 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 17973 T1002 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 17983 T1002 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17986 T1002 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 17990 T1002 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17991 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17991 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17991 T1002 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 17992 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 17992 T1002 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 17992 T1002 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17993 T1002 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363957848034/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/
[junit4:junit4]   2> 17993 T1002 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 17993 T1002 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 17994 T1002 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4
[junit4:junit4]   2> 17994 T1002 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/index/
[junit4:junit4]   2> 17994 T1002 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 17994 T1002 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/index
[junit4:junit4]   2> 17995 T1002 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10946ad lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33ba9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17996 T1002 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17997 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 17997 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 17997 T1002 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 17998 T1002 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 17998 T1002 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 17999 T1002 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 17999 T1002 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 17999 T1002 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 17999 T1002 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18002 T1002 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18004 T1002 oass.SolrIndexSearcher.<init> Opening Searcher@cdce5a main
[junit4:junit4]   2> 18005 T1002 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/tlog
[junit4:junit4]   2> 18005 T1002 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18005 T1002 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18011 T1003 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@cdce5a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18013 T1002 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18013 T1002 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18521 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18522 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55937_",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55937",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 18522 T933 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18523 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 18526 T952 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18526 T1001 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18526 T984 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18526 T939 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18526 T968 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18526 T932 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> 19015 T1002 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19015 T1002 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55937 collection:collection1 shard:shard2
[junit4:junit4]   2> 19018 T1002 oasc.ZkController.register We are http://127.0.0.1:55937/collection1/ and leader is http://127.0.0.1:35084/collection1/
[junit4:junit4]   2> 19018 T1002 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55937
[junit4:junit4]   2> 19019 T1002 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19019 T1002 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C51 name=collection1 org.apache.solr.core.SolrCore@e01e95 url=http://127.0.0.1:55937/collection1 node=127.0.0.1:55937_ C51_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:55937_, state=down, base_url=http://127.0.0.1:55937, collection=collection1, core=collection1}
[junit4:junit4]   2> 19019 T1004 C51 P55937 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19020 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19020 T1002 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19020 T1004 C51 P55937 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19020 T1004 C51 P55937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19021 T910 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19021 T1004 C51 P55937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19021 T910 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19022 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19025 T910 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19026 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19030 T945 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/onenodecollectioncore
[junit4:junit4]   2> 19030 T945 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19031 T945 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19031 T945 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19032 T945 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19032 T945 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19034 T945 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19035 T945 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/onenodecollectioncore/'
[junit4:junit4]   2> 19075 T945 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_43
[junit4:junit4]   2> 19120 T945 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19121 T945 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 19125 T945 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2>  C50_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:57476_, state=recovering, base_url=http://127.0.0.1:57476, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4]   2> 19294 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52986/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19294 T987 C50 P57476 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57476 START replicas=[http://127.0.0.1:52986/collection1/] nUpdates=100
[junit4:junit4]   2> 19294 T987 C50 P57476 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19295 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19295 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19295 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19295 T987 C50 P57476 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19295 T987 C50 P57476 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52986/collection1/. core=collection1
[junit4:junit4]   2> 19295 T987 C50 P57476 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C52 name=collection1 org.apache.solr.core.SolrCore@1071a6f url=http://127.0.0.1:52986/collection1 node=127.0.0.1:52986_ C52_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:52986_, state=active, base_url=http://127.0.0.1:52986, shard=shard1, collection=collection1, core=collection1, leader=true}
[junit4:junit4]   2> 19299 T946 C52 P52986 REQ /get {wt=javabin&getVersions=100&version=2&qt=/get&distrib=false} status=0 QTime=0 
[junit4:junit4]   2> 19310 T947 C52 P52986 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19311 T947 C52 P52986 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1bb6d25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f4559f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19312 T947 C52 P52986 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19312 T947 C52 P52986 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1bb6d25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f4559f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1bb6d25 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f4559f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19312 T947 C52 P52986 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19313 T947 C52 P52986 oass.SolrIndexSearcher.<init> Opening Searcher@17aa5d realtime
[junit4:junit4]   2> 19313 T947 C52 P52986 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19313 T947 C52 P52986 /update {commit=true&openSearcher=false&wt=javabin&softCommit=false&version=2&waitSearcher=true&commit_end_point=true} {commit=} 0 3
[junit4:junit4]   2> 19315 T987 C50 P57476 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19315 T987 C50 P57476 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19319 T946 C52 P52986 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19319 T946 C52 P52986 REQ /replication {wt=javabin&version=2&qt=/replication&command=indexversion} status=0 QTime=3 
[junit4:junit4]   2> 19320 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19320 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19320 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19322 T947 C52 P52986 REQ /replication {generation=2&wt=javabin&version=2&qt=/replication&command=filelist} status=0 QTime=0 
[junit4:junit4]   2> 19322 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19323 T987 C50 P57476 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty3/index.20130322131051065
[junit4:junit4]   2> 19323 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@41b583 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a620f4) fullCopy=false
[junit4:junit4]   2> 19325 T948 C52 P52986 REQ /replication {checksum=true&generation=2&wt=filestream&file=segments_2&qt=/replication&command=filecontent} status=0 QTime=0 
[junit4:junit4]   2> 19326 T987 C50 P57476 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19327 T987 C50 P57476 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19328 T987 C50 P57476 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19328 T987 C50 P57476 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@974660 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17ffcaf),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@974660 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17ffcaf),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19329 T987 C50 P57476 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19329 T987 C50 P57476 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19329 T987 C50 P57476 oass.SolrIndexSearcher.<init> Opening Searcher@1d44789 main
[junit4:junit4]   2> 19330 T986 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d44789 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19331 T987 C50 P57476 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19331 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19331 T987 C50 P57476 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19331 T987 C50 P57476 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19332 T987 C50 P57476 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19553 T945 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19559 T945 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19562 T945 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 19578 T945 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19582 T945 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 19585 T945 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19586 T945 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19586 T945 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19586 T945 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 19587 T945 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 19588 T945 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 19588 T945 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19588 T945 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363957835231/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/
[junit4:junit4]   2> 19589 T945 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6eb35c
[junit4:junit4]   2> 19589 T945 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 19590 T945 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection
[junit4:junit4]   2> 19590 T945 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/index/
[junit4:junit4]   2> 19590 T945 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 19591 T945 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/index
[junit4:junit4]   2> 19592 T945 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2347ad lockFactory=org.apache.lucene.store.NativeFSLockFactory@2e087a),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19592 T945 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19594 T945 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 19594 T945 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 19594 T945 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 19595 T945 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 19595 T945 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 19596 T945 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 19596 T945 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 19596 T945 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 19597 T945 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 19599 T945 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 19602 T945 oass.SolrIndexSearcher.<init> Opening Searcher@143fc05 main
[junit4:junit4]   2> 19602 T945 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/tlog
[junit4:junit4]   2> 19602 T945 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 19603 T945 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 19607 T1008 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@143fc05 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 19608 T945 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20030 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20031 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55937_",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55937",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 20034 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57476_",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57476",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 20036 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 20036 T933 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20037 T933 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20039 T984 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20039 T1001 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20039 T939 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20039 T952 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20039 T932 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> 20040 T968 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> 20611 T945 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 20611 T945 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:52986 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 20612 T945 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 20617 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 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> 20617 T945 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 20618 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 20620 T945 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 20620 T945 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 20621 T945 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52986/onenodecollectioncore/
[junit4:junit4]   2> 20621 T945 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 20621 T945 oasc.SyncStrategy.syncToMe http://127.0.0.1:52986/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 20622 T945 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52986/onenodecollectioncore/
[junit4:junit4]   2> 20622 T945 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 20625 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21026 T964 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {checkLive=true&wt=javabin&coreNodeName=5&state=recovering&nodeName=127.0.0.1:55937_&action=PREPRECOVERY&onlyIfLeader=true&version=2&core=collection1} status=0 QTime=2001 
[junit4:junit4]   2> 21545 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21552 T968 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21552 T952 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21552 T984 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21552 T939 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21552 T932 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21552 T1001 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> 21579 T945 oasc.ZkController.register We are http://127.0.0.1:52986/onenodecollectioncore/ and leader is http://127.0.0.1:52986/onenodecollectioncore/
[junit4:junit4]   2> 21579 T945 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:52986
[junit4:junit4]   2> 21580 T945 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21580 T945 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21582 T945 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21583 T945 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {name=onenodecollectioncore&numShards=1&roles=none&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection&wt=javabin&action=CREATE&version=2&collection=onenodecollection} status=0 QTime=2554 
[junit4:junit4]   2> 21584 T910 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21585 T910 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 22586 T910 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C51_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:55937_, state=recovering, base_url=http://127.0.0.1:55937, shard=shard2, collection=collection1, core=collection1}
[junit4:junit4]   2> 23026 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:35084/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 23027 T1004 C51 P55937 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55937 START replicas=[http://127.0.0.1:35084/collection1/] nUpdates=100
[junit4:junit4]   2> 23028 T1004 C51 P55937 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 23028 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 23028 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 23028 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 23029 T1004 C51 P55937 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 23029 T1004 C51 P55937 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:35084/collection1/. core=collection1
[junit4:junit4]   2> 23029 T1004 C51 P55937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C53 name=collection1 org.apache.solr.core.SolrCore@1fdfbda url=http://127.0.0.1:35084/collection1 node=127.0.0.1:35084_ C53_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:35084_, state=active, base_url=http://127.0.0.1:35084, shard=shard2, collection=collection1, core=collection1, leader=true}
[junit4:junit4]   2> 23034 T964 C53 P35084 REQ /get {wt=javabin&getVersions=100&version=2&qt=/get&distrib=false} status=0 QTime=0 
[junit4:junit4]   2> 23035 T961 C53 P35084 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 23037 T961 C53 P35084 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1aa275d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ccd5d4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 23038 T961 C53 P35084 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 23038 T961 C53 P35084 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1aa275d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ccd5d4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1aa275d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ccd5d4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23039 T961 C53 P35084 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23039 T961 C53 P35084 oass.SolrIndexSearcher.<init> Opening Searcher@1001cd3 realtime
[junit4:junit4]   2> 23040 T961 C53 P35084 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 23040 T961 C53 P35084 /update {commit=true&openSearcher=false&wt=javabin&softCommit=false&version=2&waitSearcher=true&commit_end_point=true} {commit=} 0 5
[junit4:junit4]   2> 23041 T1004 C51 P55937 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23041 T1004 C51 P55937 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 23043 T964 C53 P35084 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 23043 T964 C53 P35084 REQ /replication {wt=javabin&version=2&qt=/replication&command=indexversion} status=0 QTime=1 
[junit4:junit4]   2> 23044 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 23044 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 23044 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 23046 T962 C53 P35084 REQ /replication {generation=2&wt=javabin&version=2&qt=/replication&command=filelist} status=0 QTime=0 
[junit4:junit4]   2> 23046 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 23047 T1004 C51 P55937 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty4/index.20130322131054790
[junit4:junit4]   2> 23047 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@25f306 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c98b20) fullCopy=false
[junit4:junit4]   2> 23049 T961 C53 P35084 REQ /replication {checksum=true&generation=2&wt=filestream&file=segments_2&qt=/replication&command=filecontent} status=0 QTime=0 
[junit4:junit4]   2> 23051 T1004 C51 P55937 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 23051 T1004 C51 P55937 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 23052 T1004 C51 P55937 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 23053 T1004 C51 P55937 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10946ad lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33ba9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10946ad lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33ba9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 23053 T1004 C51 P55937 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 23053 T1004 C51 P55937 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 23054 T1004 C51 P55937 oass.SolrIndexSearcher.<init> Opening Searcher@1d0a13d main
[junit4:junit4]   2> 23055 T1003 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d0a13d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 23056 T1004 C51 P55937 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 23056 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 23056 T1004 C51 P55937 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 23056 T1004 C51 P55937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 23057 T1004 C51 P55937 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 23058 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23059 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:52986__onenodecollectioncore",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 23062 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:55937_",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:55937",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 23065 T939 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> 23065 T968 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> 23065 T932 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> 23065 T984 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> 23065 T952 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> 23065 T1001 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> 23587 T910 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23588 T910 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23589 T910 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23622 T910 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:54167 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@c30404
[junit4:junit4]   2> 23623 T910 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23623 T1011 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:54167. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23623 T1011 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:54167, initiating session
[junit4:junit4]   2> 23623 T912 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:39862
[junit4:junit4]   2> 23624 T912 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:39862
[junit4:junit4]   2> 23625 T914 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d9238d845000d with negotiated timeout 10000 for client /127.0.0.1:39862
[junit4:junit4]   2> 23625 T1011 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:54167, sessionid = 0x13d9238d845000d, negotiated timeout = 10000
[junit4:junit4]   2> 23625 T1012 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c30404 name:ZooKeeperConnection Watcher:127.0.0.1:54167 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23625 T910 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23657 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d845000d
[junit4:junit4]   2> 23658 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39862 which had sessionid 0x13d9238d845000d
[junit4:junit4]   2> 23658 T1012 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23658 T910 oaz.ZooKeeper.close Session: 0x13d9238d845000d closed
[junit4:junit4]   2> 23659 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450004
[junit4:junit4]   2> 23659 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39838 which had sessionid 0x13d9238d8450004
[junit4:junit4]   2> 23660 T939 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23660 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450004 closed
[junit4:junit4]   2> 23669 T910 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37340
[junit4:junit4]   2> 23670 T910 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=7079465
[junit4:junit4]   2> 24570 T933 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24571 T933 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37340_",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37340",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 24573 T1001 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> 24573 T984 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> 24573 T932 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> 24573 T968 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> 24573 T952 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> 25672 T910 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25672 T910 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25675 T910 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@1c8e9ad
[junit4:junit4]   2> 25679 T910 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> 25680 T910 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25680 T910 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25680 T910 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25681 T910 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25681 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data
[junit4:junit4]   2> 25681 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data
[junit4:junit4]   2> 25682 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/index
[junit4:junit4]   2> 25682 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/control/data/index
[junit4:junit4]   2> 25683 T933 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89388340461502467-127.0.0.1:37340_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25683 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450003
[junit4:junit4]   2> 25684 T968 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> 25684 T984 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> 25684 T932 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> 25684 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39837 which had sessionid 0x13d9238d8450003
[junit4:junit4]   2> 25684 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450003 closed
[junit4:junit4]   2> 25685 T932 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 25685 T1001 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25685 T932 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 25685 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 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> 25685 T1001 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> 25686 T932 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 25686 T952 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25687 T968 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25687 T984 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25688 T952 oasc.Overseer.start Overseer (id=89388340461502470-127.0.0.1:52986_-n_0000000001) starting
[junit4:junit4]   2> 25688 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xcb zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25689 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xcc zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25690 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xce zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25691 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450006 type:create cxid:0xd0 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25692 T952 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25692 T1014 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25692 T952 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> 25692 T1013 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25694 T1013 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25694 T1013 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:37340_",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:37340",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 25697 T1001 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> 25697 T968 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> 25698 T952 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> 25697 T984 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> 25707 T910 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 25760 T910 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 52986
[junit4:junit4]   2> 25760 T910 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=16962583
[junit4:junit4]   2> 27201 T1013 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27201 T1013 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:52986__onenodecollectioncore",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore"}
[junit4:junit4]   2> 27204 T1013 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52986_",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52986",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "core":"collection1"}
[junit4:junit4]   2> 27207 T952 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> 27207 T1001 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> 27207 T968 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> 27207 T984 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> 28762 T910 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 28763 T910 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 28765 T910 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 28767 T910 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@1071a6f
[junit4:junit4]   2> 28772 T910 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> 28772 T910 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 28773 T910 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 28773 T910 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 28775 T910 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 28775 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1
[junit4:junit4]   2> 28775 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1
[junit4:junit4]   2> 28776 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/index
[junit4:junit4]   2> 28776 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363957831746/jetty1/index
[junit4:junit4]   2> 28776 T910 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@99ec91
[junit4:junit4]   2> 28781 T910 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> 28782 T910 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 28782 T910 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 28782 T910 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 28783 T910 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 28783 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection
[junit4:junit4]   2> 28783 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection
[junit4:junit4]   2> 28784 T910 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/index
[junit4:junit4]   2> 28784 T910 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363957831746/onenodecollection/index
[junit4:junit4]   2> 28785 T1013 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89388340461502470-127.0.0.1:52986_-n_0000000001) am no longer a leader.
[junit4:junit4]   2> 28785 T915 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d9238d8450006
[junit4:junit4]   2> 28786 T1001 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> 28786 T952 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> 28786 T912 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:39840 which had sessionid 0x13d9238d8450006
[junit4:junit4]   2> 28787 T952 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 28786 T910 oaz.ZooKeeper.close Session: 0x13d9238d8450006 closed
[junit4:junit4]   2> 28787 T952 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 28787 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 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> 28787 T952 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 28788 T968 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 28788 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:delete cxid:0x5e zxid:0xfa txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 28789 T984 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 28789 T1001 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 28789 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:create cxid:0x5f zxid:0xfc txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 28790 T968 oasc.Overseer.start Overseer (id=89388340461502472-127.0.0.1:35084_-n_0000000002) starting
[junit4:junit4]   2> 28790 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x81 zxid:0xfd txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 28790 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x82 zxid:0xff txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 28790 T984 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4]   2> 28791 T984 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4]   2> 28791 T984 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 28791 T984 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57476/collection1/
[junit4:junit4]   2> 28791 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x84 zxid:0x100 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 28791 T984 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57476 START replicas=[http://127.0.0.1:52986/collection1/] nUpdates=100
[junit4:junit4]   2> 28792 T984 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57476 DONE.  We have no versions.  sync failed.
[junit4:junit4]   2> 28792 T984 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4]   2> 28792 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d8450008 type:create cxid:0x86 zxid:0x101 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 28792 T984 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4]   2> 28793 T984 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57476/collection1/
[junit4:junit4]   2> 28793 T984 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 28793 T1017 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 28794 T968 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 28794 T968 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> 28794 T1016 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 28795 T915 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d9238d845000a type:create cxid:0x68 zxid:0x103 txntype:-1 reqpath:n/a Error Path:/solr/over

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

e/update
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([3993AA474632F341:B875245F316D937D]:0)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:197)
[junit4:junit4]    > 	at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]    > 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    > 	at java.lang.reflect.Method.invoke(Method.java:487)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 32148 T910 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 32151 T909 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4]   2> 32245 T984 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 32245 T984 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> 32245 T984 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 32246 T984 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 32257 T913 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> 33336 T1001 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33337 T1001 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> 33337 T1001 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 33337 T1001 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=DefaultSimilarity, locale=sl_SI, timezone=Europe/London
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=3,free=31406400,total=90099712
[junit4:junit4]   2> NOTE: All tests run in this JVM: [CachingDirectoryFactoryTest, IndexReaderFactoryTest, TestSolr4Spatial, ChaosMonkeySafeLeaderTest, ShardRoutingCustomTest, SpellCheckCollatorTest, TestShardHandlerFactory, NotRequiredUniqueKeyTest, SpellCheckComponentTest, XsltUpdateRequestHandlerTest, CoreContainerCoreInitFailuresTest, SolrRequestParserTest, RequestHandlersTest, TestFiltering, SignatureUpdateProcessorFactoryTest, OpenExchangeRatesOrgProviderTest, TestSolrXMLSerializer, SimplePostToolTest, CurrencyFieldXmlFileTest, TestPartialUpdateDeduplication, DirectSolrSpellCheckerTest, TestCodecSupport, TestDistributedGrouping, CopyFieldTest, TestPostingsSolrHighlighter, TestCollationField, TestBinaryField, CurrencyFieldOpenExchangeTest, TestCSVResponseWriter, TestLazyCores, TestSuggestSpellingConverter, StatsComponentTest, PathHierarchyTokenizerFactoryTest, LeaderElectionIntegrationTest, DocumentAnalysisRequestHandlerTest, PingRequestHandlerTest, TestBinaryResponseWriter, IndexBasedSpellCheckerTest, TestDefaultSimilarityFactory, UniqFieldsUpdateProcessorFactoryTest, DefaultValueUpdateProcessorTest, TestUpdate, TestUtils, TestSolrJ, DirectUpdateHandlerTest, TestArbitraryIndexDir, UpdateParamsTest, DisMaxRequestHandlerTest, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 33.44s, 1 test, 1 error <<< FAILURES!

[...truncated 426 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, 1149 tests, 1 error, 14 ignored (8 assumptions)

Total time: 46 minutes 42 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