lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-MacOSX (64bit/jdk1.7.0) - Build # 187 - Failure!
Date Tue, 05 Feb 2013 13:46:19 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-MacOSX/187/
Java: 64bit/jdk1.7.0 -XX:+UseG1GC

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

Error Message:
IOException occured when talking to server at: http://127.0.0.1:49952

Stack Trace:
org.apache.solr.client.solrj.SolrServerException: IOException occured when talking to server at: http://127.0.0.1:49952
	at __randomizedtesting.SeedInfo.seed([591C540BA084DC7C:D8FADA13D7DBBC40]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:416)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.cloud.BasicDistributedZkTest.testCoreUnloadAndLeaders(BasicDistributedZkTest.java:519)
	at org.apache.solr.cloud.BasicDistributedZkTest.doTest(BasicDistributedZkTest.java:337)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
	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:601)
	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)
Caused by: java.net.SocketException: Invalid argument
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:150)
	at java.net.SocketInputStream.read(SocketInputStream.java:121)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
	at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:111)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:282)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:216)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:647)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
	... 44 more




Build Log:
[...truncated 9047 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4]   2> 0 T2575 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 7 T2575 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1360071257410
[junit4:junit4]   2> 8 T2575 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 9 T2576 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 10 T2576 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 11 T2576 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 11 T2576 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 11 T2576 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 13 T2576 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 110 T2575 oasc.ZkTestServer.run start zk server on port:49945
[junit4:junit4]   2> 110 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@772778d7
[junit4:junit4]   2> 111 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 112 T2581 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 113 T2581 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 113 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49946
[junit4:junit4]   2> 114 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49946
[junit4:junit4]   2> 114 T2579 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 116 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470000 with negotiated timeout 10000 for client /127.0.0.1:49946
[junit4:junit4]   2> 117 T2581 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470000, negotiated timeout = 10000
[junit4:junit4]   2> 117 T2582 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@772778d7 name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 118 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 118 T2575 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 122 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470000
[junit4:junit4]   2> 123 T2582 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 123 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470000 closed
[junit4:junit4]   2> 125 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49946 which had sessionid 0x13caa906d470000
[junit4:junit4]   2> 125 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@500b2c92
[junit4:junit4]   2> 126 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 127 T2583 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 127 T2583 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 128 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49947
[junit4:junit4]   2> 128 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49947
[junit4:junit4]   2> 129 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470001 with negotiated timeout 10000 for client /127.0.0.1:49947
[junit4:junit4]   2> 129 T2583 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470001, negotiated timeout = 10000
[junit4:junit4]   2> 130 T2584 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@500b2c92 name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 130 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 131 T2575 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 136 T2575 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 140 T2575 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 144 T2575 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 149 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 150 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 157 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 158 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 163 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 164 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 168 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 169 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 173 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 174 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 178 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 179 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 183 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 184 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 189 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 189 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 194 T2575 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 195 T2575 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 199 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470001
[junit4:junit4]   2> 200 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49947 which had sessionid 0x13caa906d470001
[junit4:junit4]   2> 200 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470001 closed
[junit4:junit4]   2> 201 T2584 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 370 T2575 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 397 T2575 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49948
[junit4:junit4]   2> 398 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 399 T2575 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 399 T2575 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603
[junit4:junit4]   2> 400 T2575 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/solr.xml
[junit4:junit4]   2> 400 T2575 oasc.CoreContainer.<init> New CoreContainer 457100283
[junit4:junit4]   2> 401 T2575 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/'
[junit4:junit4]   2> 402 T2575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/'
[junit4:junit4]   2> 436 T2575 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 437 T2575 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 437 T2575 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 437 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 438 T2575 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 438 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 438 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 439 T2575 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 439 T2575 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 440 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 449 T2575 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 463 T2575 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49945/solr
[junit4:junit4]   2> 465 T2575 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 465 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@c3ff826
[junit4:junit4]   2> 466 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 466 T2594 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 468 T2594 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 468 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49949
[junit4:junit4]   2> 468 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49949
[junit4:junit4]   2> 469 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470002 with negotiated timeout 20000 for client /127.0.0.1:49949
[junit4:junit4]   2> 470 T2594 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470002, negotiated timeout = 20000
[junit4:junit4]   2> 470 T2595 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c3ff826 name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 470 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 472 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470002
[junit4:junit4]   2> 473 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49949 which had sessionid 0x13caa906d470002
[junit4:junit4]   2> 473 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470002 closed
[junit4:junit4]   2> 473 T2595 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 474 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 479 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5f488d27
[junit4:junit4]   2> 480 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 480 T2596 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 481 T2596 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 482 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49950
[junit4:junit4]   2> 482 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49950
[junit4:junit4]   2> 483 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470003 with negotiated timeout 20000 for client /127.0.0.1:49950
[junit4:junit4]   2> 483 T2596 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470003, negotiated timeout = 20000
[junit4:junit4]   2> 484 T2597 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f488d27 name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 484 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 486 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 488 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 491 T2575 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49948_
[junit4:junit4]   2> 492 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:delete cxid:0x7 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49948_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49948_
[junit4:junit4]   2> 493 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49948_
[junit4:junit4]   2> 497 T2575 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 505 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:delete cxid:0x15 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 506 T2575 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 510 T2575 oasc.Overseer.start Overseer (id=89133629925949443-127.0.0.1:49948_-n_0000000000) starting
[junit4:junit4]   2> 512 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x1a zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 513 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x1b zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 514 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x1c zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 516 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x1d zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 517 T2599 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 518 T2575 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 522 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 526 T2598 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 532 T2600 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/collection1
[junit4:junit4]   2> 533 T2600 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 534 T2600 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 534 T2600 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 536 T2600 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/collection1/'
[junit4:junit4]   2> 537 T2600 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 538 T2600 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/collection1/lib/README' to classloader
[junit4:junit4]   2> 588 T2600 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 666 T2600 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 667 T2600 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 679 T2600 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1283 T2600 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1292 T2600 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1295 T2600 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1317 T2600 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1321 T2600 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1327 T2600 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1329 T2600 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1331 T2600 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360071257603/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/
[junit4:junit4]   2> 1331 T2600 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@591913b3
[junit4:junit4]   2> 1332 T2600 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 1333 T2600 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data forceNew:false
[junit4:junit4]   2> 1333 T2600 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data
[junit4:junit4]   2> 1334 T2600 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index/
[junit4:junit4]   2> 1334 T2600 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1336 T2600 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index forceNew:false
[junit4:junit4]   2> 1341 T2600 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d4e72d8; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1341 T2600 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1343 T2600 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index
[junit4:junit4]   2> 1343 T2600 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 1347 T2600 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1348 T2600 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 1349 T2600 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1350 T2600 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 1351 T2600 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1352 T2600 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1353 T2600 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1353 T2600 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1354 T2600 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1355 T2600 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 1356 T2600 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 1357 T2600 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1358 T2600 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 1359 T2600 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 1359 T2600 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 1360 T2600 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1361 T2600 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1362 T2600 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1363 T2600 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1363 T2600 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1364 T2600 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1365 T2600 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1366 T2600 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1367 T2600 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1367 T2600 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 1368 T2600 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 1374 T2600 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1377 T2600 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 1379 T2600 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 1381 T2600 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data
[junit4:junit4]   2> 1382 T2600 oass.SolrIndexSearcher.<init> Opening Searcher@38758f3a main
[junit4:junit4]   2> 1383 T2600 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1384 T2600 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1384 T2600 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 1390 T2600 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 1419 T2601 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38758f3a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1425 T2600 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1425 T2600 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1426 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 2035 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2037 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49948_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49948"}
[junit4:junit4]   2> 2037 T2598 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2037 T2598 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2038 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 2047 T2597 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> 2430 T2600 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2431 T2600 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49948 collection:control_collection shard:shard1
[junit4:junit4]   2> 2432 T2600 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2444 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2445 T2600 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2446 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2449 T2600 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2450 T2600 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2450 T2600 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49948/collection1/
[junit4:junit4]   2> 2451 T2600 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2451 T2600 oasc.SyncStrategy.syncToMe http://127.0.0.1:49948/collection1/ has no replicas
[junit4:junit4]   2> 2451 T2600 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49948/collection1/
[junit4:junit4]   2> 2452 T2600 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2462 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3555 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3571 T2597 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> 3594 T2600 oasc.ZkController.register We are http://127.0.0.1:49948/collection1/ and leader is http://127.0.0.1:49948/collection1/
[junit4:junit4]   2> 3595 T2600 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49948
[junit4:junit4]   2> 3595 T2600 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3595 T2600 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3596 T2600 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3600 T2600 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3602 T2575 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 3602 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3603 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3614 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3623 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@390eaf8c
[junit4:junit4]   2> 3624 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3625 T2602 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3626 T2602 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 3627 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49951
[junit4:junit4]   2> 3628 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49951
[junit4:junit4]   2> 3629 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470004 with negotiated timeout 10000 for client /127.0.0.1:49951
[junit4:junit4]   2> 3630 T2602 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470004, negotiated timeout = 10000
[junit4:junit4]   2> 3630 T2603 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@390eaf8c name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3631 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3633 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3637 T2575 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3894 T2575 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3899 T2575 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49952
[junit4:junit4]   2> 3901 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3902 T2575 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3903 T2575 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039
[junit4:junit4]   2> 3904 T2575 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/solr.xml
[junit4:junit4]   2> 3905 T2575 oasc.CoreContainer.<init> New CoreContainer 1422985641
[junit4:junit4]   2> 3906 T2575 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/'
[junit4:junit4]   2> 3907 T2575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/'
[junit4:junit4]   2> 3958 T2575 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 3960 T2575 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3961 T2575 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3963 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3964 T2575 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3965 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3966 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3967 T2575 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3968 T2575 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3969 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3983 T2575 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4010 T2575 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49945/solr
[junit4:junit4]   2> 4011 T2575 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4012 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3858b3e1
[junit4:junit4]   2> 4013 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4014 T2613 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4016 T2613 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 4016 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49953
[junit4:junit4]   2> 4017 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49953
[junit4:junit4]   2> 4174 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470005 with negotiated timeout 20000 for client /127.0.0.1:49953
[junit4:junit4]   2> 4175 T2613 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470005, negotiated timeout = 20000
[junit4:junit4]   2> 4176 T2614 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3858b3e1 name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4176 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4178 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470005
[junit4:junit4]   2> 4180 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49953 which had sessionid 0x13caa906d470005
[junit4:junit4]   2> 4180 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470005 closed
[junit4:junit4]   2> 4180 T2614 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4181 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 4187 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3b6a4cdf
[junit4:junit4]   2> 4188 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4189 T2615 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4190 T2615 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 4190 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49954
[junit4:junit4]   2> 4191 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49954
[junit4:junit4]   2> 4193 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470006 with negotiated timeout 20000 for client /127.0.0.1:49954
[junit4:junit4]   2> 4193 T2615 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470006, negotiated timeout = 20000
[junit4:junit4]   2> 4194 T2616 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b6a4cdf name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4195 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4196 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4198 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4200 T2575 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49952_
[junit4:junit4]   2> 4201 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:delete cxid:0x4 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49952_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49952_
[junit4:junit4]   2> 4202 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49952_
[junit4:junit4]   2> 4207 T2597 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4207 T2603 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4207 T2597 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> 4212 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4219 T2617 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/collection1
[junit4:junit4]   2> 4219 T2617 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4220 T2617 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4220 T2617 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4222 T2617 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/collection1/'
[junit4:junit4]   2> 4224 T2617 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4225 T2617 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/collection1/lib/README' to classloader
[junit4:junit4]   2> 4271 T2617 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4340 T2617 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4342 T2617 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4349 T2617 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4982 T2617 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4991 T2617 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4995 T2617 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5019 T2617 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5028 T2617 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5037 T2617 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5039 T2617 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5041 T2617 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360071261039/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/
[junit4:junit4]   2> 5042 T2617 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@591913b3
[junit4:junit4]   2> 5042 T2617 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 5043 T2617 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1 forceNew:false
[junit4:junit4]   2> 5043 T2617 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2> 5044 T2617 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index/
[junit4:junit4]   2> 5044 T2617 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5046 T2617 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index forceNew:false
[junit4:junit4]   2> 5051 T2617 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@83a17e0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5051 T2617 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5052 T2617 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index
[junit4:junit4]   2> 5052 T2617 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 5055 T2617 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5055 T2617 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 5055 T2617 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5056 T2617 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 5057 T2617 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5057 T2617 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5057 T2617 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5058 T2617 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5058 T2617 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5059 T2617 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 5060 T2617 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 5060 T2617 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5061 T2617 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 5061 T2617 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 5061 T2617 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 5062 T2617 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5062 T2617 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5063 T2617 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5064 T2617 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5064 T2617 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5065 T2617 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5065 T2617 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5066 T2617 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5067 T2617 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5067 T2617 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 5068 T2617 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 5074 T2617 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5077 T2617 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 5079 T2617 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 5082 T2617 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2> 5083 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5083 T2617 oass.SolrIndexSearcher.<init> Opening Searcher@36718a67 main
[junit4:junit4]   2> 5084 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49948_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49948"}
[junit4:junit4]   2> 5084 T2617 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5085 T2617 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5086 T2617 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 5093 T2617 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 5094 T2603 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> 5095 T2616 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> 5095 T2597 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> 5128 T2618 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36718a67 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5135 T2617 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5136 T2617 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6605 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6607 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49952_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49952"}
[junit4:junit4]   2> 6607 T2598 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6607 T2598 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 6614 T2597 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> 6614 T2603 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> 6615 T2616 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> 7140 T2617 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7140 T2617 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49952 collection:collection1 shard:shard1
[junit4:junit4]   2> 7141 T2617 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 7153 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:delete cxid:0x45 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7154 T2617 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7155 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:create cxid:0x46 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7158 T2617 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7158 T2617 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7158 T2617 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49952/collection1/
[junit4:junit4]   2> 7159 T2617 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7159 T2617 oasc.SyncStrategy.syncToMe http://127.0.0.1:49952/collection1/ has no replicas
[junit4:junit4]   2> 7159 T2617 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49952/collection1/
[junit4:junit4]   2> 7160 T2617 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 7166 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470006 type:create cxid:0x50 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8123 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8136 T2616 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> 8136 T2597 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> 8136 T2603 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> 8165 T2617 oasc.ZkController.register We are http://127.0.0.1:49952/collection1/ and leader is http://127.0.0.1:49952/collection1/
[junit4:junit4]   2> 8165 T2617 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49952
[junit4:junit4]   2> 8165 T2617 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8166 T2617 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8166 T2617 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8169 T2617 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8170 T2575 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 8171 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8171 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8342 T2575 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8347 T2575 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49955
[junit4:junit4]   2> 8348 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8349 T2575 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8350 T2575 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581
[junit4:junit4]   2> 8350 T2575 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/solr.xml
[junit4:junit4]   2> 8350 T2575 oasc.CoreContainer.<init> New CoreContainer 1575248066
[junit4:junit4]   2> 8351 T2575 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/'
[junit4:junit4]   2> 8352 T2575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/'
[junit4:junit4]   2> 8387 T2575 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 8388 T2575 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8388 T2575 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8389 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8389 T2575 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8390 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8390 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8391 T2575 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8391 T2575 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8392 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8405 T2575 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8427 T2575 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49945/solr
[junit4:junit4]   2> 8428 T2575 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8428 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@786cb83a
[junit4:junit4]   2> 8430 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8430 T2628 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8432 T2628 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 8432 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49956
[junit4:junit4]   2> 8433 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49956
[junit4:junit4]   2> 8434 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470007 with negotiated timeout 20000 for client /127.0.0.1:49956
[junit4:junit4]   2> 8434 T2628 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470007, negotiated timeout = 20000
[junit4:junit4]   2> 8435 T2629 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@786cb83a name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8435 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8438 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470007
[junit4:junit4]   2> 8439 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49956 which had sessionid 0x13caa906d470007
[junit4:junit4]   2> 8439 T2629 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8439 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470007 closed
[junit4:junit4]   2> 8440 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 8446 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2b1ab336
[junit4:junit4]   2> 8448 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8448 T2630 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8449 T2630 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 8450 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49957
[junit4:junit4]   2> 8450 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49957
[junit4:junit4]   2> 8452 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470008 with negotiated timeout 20000 for client /127.0.0.1:49957
[junit4:junit4]   2> 8452 T2630 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470008, negotiated timeout = 20000
[junit4:junit4]   2> 8453 T2631 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b1ab336 name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8454 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8455 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8457 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8459 T2575 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49955_
[junit4:junit4]   2> 8460 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:delete cxid:0x4 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49955_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49955_
[junit4:junit4]   2> 8461 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49955_
[junit4:junit4]   2> 8464 T2616 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> 8465 T2597 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 8465 T2597 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> 8466 T2603 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 8466 T2603 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> 8468 T2616 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 8471 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 8479 T2632 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/collection1
[junit4:junit4]   2> 8479 T2632 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 8480 T2632 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 8481 T2632 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 8483 T2632 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/collection1/'
[junit4:junit4]   2> 8484 T2632 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 8484 T2632 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/collection1/lib/README' to classloader
[junit4:junit4]   2> 8600 T2632 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 8674 T2632 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 8676 T2632 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 8684 T2632 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9331 T2632 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9347 T2632 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9353 T2632 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9379 T2632 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9387 T2632 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9393 T2632 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9396 T2632 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9398 T2632 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360071265581/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/
[junit4:junit4]   2> 9398 T2632 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@591913b3
[junit4:junit4]   2> 9399 T2632 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 9401 T2632 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2 forceNew:false
[junit4:junit4]   2> 9401 T2632 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 9402 T2632 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index/
[junit4:junit4]   2> 9402 T2632 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9403 T2632 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index forceNew:false
[junit4:junit4]   2> 9408 T2632 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@388f470; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9408 T2632 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9409 T2632 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index
[junit4:junit4]   2> 9410 T2632 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 9412 T2632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9413 T2632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 9414 T2632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9414 T2632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 9416 T2632 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9416 T2632 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9417 T2632 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9418 T2632 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9422 T2632 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9424 T2632 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 9425 T2632 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 9426 T2632 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9427 T2632 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 9428 T2632 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 9429 T2632 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 9430 T2632 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9431 T2632 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9432 T2632 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9433 T2632 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9434 T2632 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9435 T2632 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9437 T2632 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9438 T2632 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9439 T2632 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 9440 T2632 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 9441 T2632 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 9454 T2632 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9461 T2632 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 9464 T2632 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 9469 T2632 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 9471 T2632 oass.SolrIndexSearcher.<init> Opening Searcher@67edd42c main
[junit4:junit4]   2> 9473 T2632 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9474 T2632 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9475 T2632 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 9484 T2632 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 9545 T2633 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@67edd42c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9553 T2632 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9554 T2632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9647 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9649 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49952_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49952"}
[junit4:junit4]   2> 9655 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49955_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49955"}
[junit4:junit4]   2> 9655 T2598 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 9655 T2598 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 9663 T2603 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> 9663 T2597 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> 9663 T2631 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> 9663 T2616 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> 10561 T2632 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 10562 T2632 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49955 collection:collection1 shard:shard2
[junit4:junit4]   2> 10563 T2632 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 10574 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:delete cxid:0x42 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> 10575 T2632 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 10576 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:create cxid:0x43 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10579 T2632 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 10580 T2632 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 10580 T2632 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49955/collection1/
[junit4:junit4]   2> 10581 T2632 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 10581 T2632 oasc.SyncStrategy.syncToMe http://127.0.0.1:49955/collection1/ has no replicas
[junit4:junit4]   2> 10581 T2632 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49955/collection1/
[junit4:junit4]   2> 10581 T2632 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 10587 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d470008 type:create cxid:0x4c zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11176 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11189 T2631 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> 11189 T2616 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> 11189 T2603 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> 11189 T2597 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> 11228 T2632 oasc.ZkController.register We are http://127.0.0.1:49955/collection1/ and leader is http://127.0.0.1:49955/collection1/
[junit4:junit4]   2> 11228 T2632 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49955
[junit4:junit4]   2> 11228 T2632 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 11229 T2632 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 11229 T2632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11231 T2632 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11233 T2575 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 11233 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 11234 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11396 T2575 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 11401 T2575 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49958
[junit4:junit4]   2> 11401 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 11402 T2575 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 11403 T2575 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640
[junit4:junit4]   2> 11403 T2575 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/solr.xml
[junit4:junit4]   2> 11404 T2575 oasc.CoreContainer.<init> New CoreContainer 1622651495
[junit4:junit4]   2> 11404 T2575 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/'
[junit4:junit4]   2> 11405 T2575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/'
[junit4:junit4]   2> 11441 T2575 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 11442 T2575 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 11443 T2575 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 11443 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 11444 T2575 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 11445 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 11445 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 11446 T2575 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 11447 T2575 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 11448 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 11466 T2575 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 11485 T2575 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49945/solr
[junit4:junit4]   2> 11487 T2575 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 11487 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ea19aa8
[junit4:junit4]   2> 11489 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 11489 T2643 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 11490 T2643 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 11491 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49959
[junit4:junit4]   2> 11491 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49959
[junit4:junit4]   2> 11492 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d470009 with negotiated timeout 20000 for client /127.0.0.1:49959
[junit4:junit4]   2> 11493 T2643 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d470009, negotiated timeout = 20000
[junit4:junit4]   2> 11493 T2644 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ea19aa8 name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 11493 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 11495 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d470009
[junit4:junit4]   2> 11496 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49959 which had sessionid 0x13caa906d470009
[junit4:junit4]   2> 11496 T2644 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 11496 T2575 oaz.ZooKeeper.close Session: 0x13caa906d470009 closed
[junit4:junit4]   2> 11497 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 11501 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2819ac52
[junit4:junit4]   2> 11502 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 11502 T2645 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 11503 T2645 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 11503 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49960
[junit4:junit4]   2> 11504 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49960
[junit4:junit4]   2> 11505 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d47000a with negotiated timeout 20000 for client /127.0.0.1:49960
[junit4:junit4]   2> 11505 T2645 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d47000a, negotiated timeout = 20000
[junit4:junit4]   2> 11505 T2646 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2819ac52 name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 11506 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 11506 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11508 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000a type:create cxid:0x2 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11509 T2575 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49958_
[junit4:junit4]   2> 11510 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000a type:delete cxid:0x4 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49958_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49958_
[junit4:junit4]   2> 11511 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49958_
[junit4:junit4]   2> 11515 T2616 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> 11515 T2597 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11515 T2597 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> 11516 T2603 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11516 T2631 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11516 T2603 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> 11516 T2631 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> 11518 T2616 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11522 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 11528 T2647 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/collection1
[junit4:junit4]   2> 11529 T2647 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 11530 T2647 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 11530 T2647 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 11532 T2647 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/collection1/'
[junit4:junit4]   2> 11533 T2647 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 11533 T2647 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/collection1/lib/README' to classloader
[junit4:junit4]   2> 11580 T2647 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 11647 T2647 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 11648 T2647 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 11655 T2647 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 12224 T2647 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 12232 T2647 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 12236 T2647 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 12256 T2647 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12262 T2647 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12267 T2647 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12269 T2647 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12271 T2647 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360071268640/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/
[junit4:junit4]   2> 12271 T2647 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@591913b3
[junit4:junit4]   2> 12272 T2647 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 12272 T2647 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3 forceNew:false
[junit4:junit4]   2> 12273 T2647 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 12273 T2647 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index/
[junit4:junit4]   2> 12274 T2647 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 12275 T2647 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index forceNew:false
[junit4:junit4]   2> 12279 T2647 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@12fa67aa; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 12280 T2647 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 12281 T2647 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index
[junit4:junit4]   2> 12281 T2647 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 12283 T2647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 12284 T2647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 12284 T2647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 12284 T2647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 12286 T2647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 12286 T2647 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 12286 T2647 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 12286 T2647 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 12287 T2647 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 12287 T2647 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 12287 T2647 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 12288 T2647 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 12288 T2647 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 12289 T2647 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 12289 T2647 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 12290 T2647 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 12290 T2647 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12291 T2647 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12291 T2647 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12292 T2647 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12292 T2647 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12292 T2647 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12292 T2647 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12293 T2647 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12293 T2647 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 12294 T2647 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 12301 T2647 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 12303 T2647 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 12304 T2647 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 12306 T2647 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 12308 T2647 oass.SolrIndexSearcher.<init> Opening Searcher@3276cb8a main
[junit4:junit4]   2> 12308 T2647 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 12309 T2647 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 12309 T2647 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 12313 T2647 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 12340 T2648 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3276cb8a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 12346 T2647 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 12347 T2647 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12702 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12703 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49955_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49955"}
[junit4:junit4]   2> 12710 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49958_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49958"}
[junit4:junit4]   2> 12710 T2598 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 12710 T2598 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 12717 T2603 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> 12718 T2616 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> 12718 T2597 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> 12719 T2631 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> 12718 T2646 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> 13350 T2647 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 13350 T2647 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49958 collection:collection1 shard:shard1
[junit4:junit4]   2> 13355 T2647 oasc.ZkController.register We are http://127.0.0.1:49958/collection1/ and leader is http://127.0.0.1:49952/collection1/
[junit4:junit4]   2> 13356 T2647 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49958
[junit4:junit4]   2> 13356 T2647 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 13356 T2647 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C186 name=collection1 org.apache.solr.core.SolrCore@358786c3 url=http://127.0.0.1:49958/collection1 node=127.0.0.1:49958_ C186_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49958_, base_url=http://127.0.0.1:49958}
[junit4:junit4]   2> 13357 T2649 C186 P49958 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 13358 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 13358 T2647 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13359 T2649 C186 P49958 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 13359 T2649 C186 P49958 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13360 T2575 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 13361 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 13361 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13361 T2649 C186 P49958 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13623 T2575 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 13629 T2575 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49962
[junit4:junit4]   2> 13630 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 13631 T2575 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 13632 T2575 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769
[junit4:junit4]   2> 13632 T2575 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/solr.xml
[junit4:junit4]   2> 13633 T2575 oasc.CoreContainer.<init> New CoreContainer 1234065025
[junit4:junit4]   2> 13634 T2575 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/'
[junit4:junit4]   2> 13635 T2575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/'
[junit4:junit4]   2> 13685 T2575 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 13687 T2575 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 13687 T2575 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 13688 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 13688 T2575 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 13689 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 13689 T2575 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 13690 T2575 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 13690 T2575 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 13691 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 13705 T2575 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 13719 T2575 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49945/solr
[junit4:junit4]   2> 13720 T2575 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 13721 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2df7752f
[junit4:junit4]   2> 13722 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13723 T2659 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13724 T2659 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 13725 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49963
[junit4:junit4]   2> 13725 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49963
[junit4:junit4]   2> 13726 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d47000b with negotiated timeout 20000 for client /127.0.0.1:49963
[junit4:junit4]   2> 13726 T2659 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d47000b, negotiated timeout = 20000
[junit4:junit4]   2> 13727 T2660 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2df7752f name:ZooKeeperConnection Watcher:127.0.0.1:49945 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13727 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13729 T2580 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13caa906d47000b
[junit4:junit4]   2> 13730 T2577 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:49963 which had sessionid 0x13caa906d47000b
[junit4:junit4]   2> 13730 T2660 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 13730 T2575 oaz.ZooKeeper.close Session: 0x13caa906d47000b closed
[junit4:junit4]   2> 13731 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 13736 T2575 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49945/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5b2c5418
[junit4:junit4]   2> 13738 T2661 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49945. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 13738 T2575 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 13739 T2661 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49945, initiating session
[junit4:junit4]   2> 13739 T2577 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:49964
[junit4:junit4]   2> 13740 T2577 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:49964
[junit4:junit4]   2> 13741 T2579 oazs.ZooKeeperServer.finishSessionInit Established session 0x13caa906d47000c with negotiated timeout 20000 for client /127.0.0.1:49964
[junit4:junit4]   2> 13741 T2661 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49945, sessionid = 0x13caa906d47000c, negotiated timeout = 20000
[junit4:junit4]   2> 13742 T2662 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b2c5418 name:ZooKeeperConnection Watcher:127.0.0.1:49945/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 13742 T2575 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 13743 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000c type:create cxid:0x1 zxid:0xa0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13745 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000c type:create cxid:0x2 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 13747 T2575 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49962_
[junit4:junit4]   2> 13748 T2580 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13caa906d47000c type:delete cxid:0x4 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:49962_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:49962_
[junit4:junit4]   2> 13749 T2575 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49962_
[junit4:junit4]   2> 13752 T2616 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> 13752 T2646 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> 13753 T2603 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 13754 T2603 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> 13754 T2631 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 13754 T2631 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> 13754 T2597 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 13755 T2597 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> 13758 T2616 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 13758 T2646 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 13763 T2575 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13771 T2663 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/collection1
[junit4:junit4]   2> 13771 T2663 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13772 T2663 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13773 T2663 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13775 T2663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/collection1/'
[junit4:junit4]   2> 13776 T2663 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13776 T2663 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/collection1/lib/README' to classloader
[junit4:junit4]   2> 13822 T2663 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 13910 T2663 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13912 T2663 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13920 T2663 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14266 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14266 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49958_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49958"}
[junit4:junit4]   2> 14270 T2603 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> 14271 T2616 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> 14271 T2646 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> 14272 T2597 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> 14273 T2662 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> 14273 T2631 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> 14570 T2663 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14577 T2663 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14580 T2663 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14604 T2663 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14613 T2663 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14623 T2663 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14627 T2663 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14630 T2663 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360071270769/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/
[junit4:junit4]   2> 14631 T2663 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@591913b3
[junit4:junit4]   2> 14632 T2663 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 14633 T2663 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4 forceNew:false
[junit4:junit4]   2> 14634 T2663 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 14634 T2663 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index/
[junit4:junit4]   2> 14635 T2663 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14637 T2663 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index forceNew:false
[junit4:junit4]   2> 14644 T2663 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@39adc863; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14645 T2663 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14647 T2663 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index
[junit4:junit4]   2> 14647 T2663 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 14651 T2663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14651 T2663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 14652 T2663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14652 T2663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 14653 T2663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14653 T2663 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14654 T2663 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14654 T2663 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14655 T2663 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14655 T2663 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 14656 T2663 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 14656 T2663 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14657 T2663 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 14657 T2663 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 14657 T2663 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 14658 T2663 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14658 T2663 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14658 T2663 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14659 T2663 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14659 T2663 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14660 T2663 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14660 T2663 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14661 T2663 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14661 T2663 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 14662 T2663 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 14662 T2663 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 14667 T2663 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14672 T2663 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 14674 T2663 oasc.SolrCore.initDeprecatedSupport WARNING adding ShowFileRequestHandler with hidden files: [SCHEMA.XML, OLD_SYNONYMS.TXT, STOPWORDS.TXT, PROTWORDS.TXT, OPEN-EXCHANGE-RATES.JSON, SYNONYMS.TXT, CURRENCY.XML, MAPPING-ISOLATIN1ACCENT.TXT]
[junit4:junit4]   2> 14676 T2663 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 14678 T2663 oass.SolrIndexSearcher.<init> Opening Searcher@28199361 main
[junit4:junit4]   2> 14679 T2663 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14680 T2663 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14680 T2663 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 14685 T2663 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 14720 T2664 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@28199361 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14728 T2663 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14728 T2663 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15781 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15782 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49962_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49962"}
[junit4:junit4]   2> 15782 T2598 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15782 T2598 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 15788 T2631 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> 15788 T2646 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> 15789 T2662 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> 15789 T2603 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> 15789 T2616 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> 15789 T2597 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>  C186_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49958_, base_url=http://127.0.0.1:49958}
[junit4:junit4]   2> 16373 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49952/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 16373 T2649 C186 P49958 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49958 START replicas=[http://127.0.0.1:49952/collection1/] nUpdates=100
[junit4:junit4]   2> 16374 T2649 C186 P49958 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 16375 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 16375 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 16376 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 16376 T2649 C186 P49958 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 16376 T2649 C186 P49958 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49952/collection1/. core=collection1
[junit4:junit4]   2> 16377 T2649 C186 P49958 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C187 name=collection1 org.apache.solr.core.SolrCore@6366acdc url=http://127.0.0.1:49952/collection1 node=127.0.0.1:49952_ C187_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49952_, base_url=http://127.0.0.1:49952, leader=true}
[junit4:junit4]   2> 16387 T2612 C187 P49952 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 16392 T2610 C187 P49952 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 16393 T2610 C187 P49952 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2> 16396 T2610 C187 P49952 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@83a17e0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 16397 T2610 C187 P49952 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 16400 T2610 C187 P49952 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@83a17e0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@83a17e0; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 16400 T2610 C187 P49952 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 16401 T2610 C187 P49952 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2> 16402 T2610 C187 P49952 oass.SolrIndexSearcher.<init> Opening Searcher@6cd62822 realtime
[junit4:junit4]   2> 16403 T2610 C187 P49952 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 16403 T2610 C187 P49952 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4]   2> 16404 T2649 C186 P49958 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 16405 T2649 C186 P49958 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 16409 T2607 C187 P49952 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 16409 T2607 C187 P49952 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 16410 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 16410 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 16410 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 16413 T2608 C187 P49952 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2> 16414 T2608 C187 P49952 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1/index
[junit4:junit4]   2> 16414 T2608 C187 P49952 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 16415 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 16416 T2649 C186 P49958 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 forceNew:false
[junit4:junit4]   2> 16417 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16417 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41835abf; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 16421 T2612 C187 P49952 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1 
[junit4:junit4]   2> 16423 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index
[junit4:junit4]   2> 16424 T2649 C186 P49958 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 16424 T2649 C186 P49958 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130205053433818
[junit4:junit4]   2> 16426 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16426 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16427 T2649 C186 P49958 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818
[junit4:junit4]   2> 16430 T2649 C186 P49958 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41835abf; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 16430 T2649 C186 P49958 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 16431 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16432 T2649 C186 P49958 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 16432 T2649 C186 P49958 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 16432 T2649 C186 P49958 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 16433 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818
[junit4:junit4]   2> 16434 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16437 T2649 C186 P49958 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41835abf; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 16437 T2649 C186 P49958 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 16437 T2649 C186 P49958 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 16438 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16438 T2649 C186 P49958 oass.SolrIndexSearcher.<init> Opening Searcher@74e5066c main
[junit4:junit4]   2> 16440 T2648 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@74e5066c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 16441 T2648 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index
[junit4:junit4]   2> 16442 T2649 C186 P49958 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 16444 T2649 C186 P49958 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41835abf; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818 lockFactory=org.apache.lucene.store.NativeFSLockFactory@41835abf; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 16444 T2649 C186 P49958 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 16445 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 16446 T2649 C186 P49958 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 16446 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index.20130205053433818
[junit4:junit4]   2> 16446 T2649 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3/index
[junit4:junit4]   2> 16446 T2649 C186 P49958 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 16447 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 16447 T2649 C186 P49958 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 16447 T2649 C186 P49958 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16449 T2649 C186 P49958 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 16733 T2663 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16733 T2663 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49962 collection:collection1 shard:shard2
[junit4:junit4]   2> 16738 T2663 oasc.ZkController.register We are http://127.0.0.1:49962/collection1/ and leader is http://127.0.0.1:49955/collection1/
[junit4:junit4]   2> 16738 T2663 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49962
[junit4:junit4]   2> 16738 T2663 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16738 T2663 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C188 name=collection1 org.apache.solr.core.SolrCore@28c2f24 url=http://127.0.0.1:49962/collection1 node=127.0.0.1:49962_ C188_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:49962_, base_url=http://127.0.0.1:49962}
[junit4:junit4]   2> 16739 T2667 C188 P49962 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16741 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16741 T2663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16741 T2667 C188 P49962 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16742 T2667 C188 P49962 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16742 T2575 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4]   2> 16743 T2667 C188 P49962 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16743 T2575 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16743 T2575 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16751 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16753 T2575 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 16754 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17302 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17304 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49958_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49958"}
[junit4:junit4]   2> 17316 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49962_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49962"}
[junit4:junit4]   2> 17326 T2631 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> 17326 T2597 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> 17327 T2662 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> 17326 T2646 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> 17326 T2603 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> 17327 T2616 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> 17757 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18761 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C188_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:49962_, base_url=http://127.0.0.1:49962}
[junit4:junit4]   2> 19755 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:49955/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19755 T2667 C188 P49962 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49962 START replicas=[http://127.0.0.1:49955/collection1/] nUpdates=100
[junit4:junit4]   2> 19756 T2667 C188 P49962 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19756 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19757 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19757 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19758 T2667 C188 P49962 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19758 T2667 C188 P49962 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:49955/collection1/. core=collection1
[junit4:junit4]   2> 19759 T2667 C188 P49962 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C189 name=collection1 org.apache.solr.core.SolrCore@652ab010 url=http://127.0.0.1:49955/collection1 node=127.0.0.1:49955_ C189_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49955_, base_url=http://127.0.0.1:49955, leader=true}
[junit4:junit4]   2> 19766 T2624 C189 P49955 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> 19767 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19771 T2627 C189 P49955 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 19772 T2627 C189 P49955 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 19775 T2627 C189 P49955 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@388f470; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19776 T2627 C189 P49955 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19779 T2627 C189 P49955 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@388f470; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@388f470; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19779 T2627 C189 P49955 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19780 T2627 C189 P49955 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 19781 T2627 C189 P49955 oass.SolrIndexSearcher.<init> Opening Searcher@7a5824dd realtime
[junit4:junit4]   2> 19781 T2627 C189 P49955 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19782 T2627 C189 P49955 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4]   2> 19784 T2667 C188 P49962 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19784 T2667 C188 P49962 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19787 T2625 C189 P49955 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19787 T2625 C189 P49955 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 19789 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19789 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19789 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19794 T2626 C189 P49955 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 19794 T2626 C189 P49955 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2/index
[junit4:junit4]   2> 19795 T2626 C189 P49955 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
[junit4:junit4]   2> 19795 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19796 T2667 C188 P49962 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 forceNew:false
[junit4:junit4]   2> 19797 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19797 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 lockFactory=org.apache.lucene.store.NativeFSLockFactory@780541ca; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 19800 T2622 C189 P49955 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 19802 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index
[junit4:junit4]   2> 19803 T2667 C188 P49962 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19803 T2667 C188 P49962 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130205053437198
[junit4:junit4]   2> 19805 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19805 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19806 T2667 C188 P49962 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198
[junit4:junit4]   2> 19808 T2667 C188 P49962 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 lockFactory=org.apache.lucene.store.NativeFSLockFactory@780541ca; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19809 T2667 C188 P49962 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19810 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19810 T2667 C188 P49962 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19811 T2667 C188 P49962 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19811 T2667 C188 P49962 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 19812 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198
[junit4:junit4]   2> 19812 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19816 T2667 C188 P49962 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 lockFactory=org.apache.lucene.store.NativeFSLockFactory@780541ca; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19817 T2667 C188 P49962 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19817 T2667 C188 P49962 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19818 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19819 T2667 C188 P49962 oass.SolrIndexSearcher.<init> Opening Searcher@6ed067ca main
[junit4:junit4]   2> 19824 T2664 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ed067ca main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19825 T2664 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index
[junit4:junit4]   2> 19825 T2667 C188 P49962 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 19828 T2667 C188 P49962 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 lockFactory=org.apache.lucene.store.NativeFSLockFactory@780541ca; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198 lockFactory=org.apache.lucene.store.NativeFSLockFactory@780541ca; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 19829 T2667 C188 P49962 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 19830 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 19830 T2667 C188 P49962 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19830 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index.20130205053437198
[junit4:junit4]   2> 19830 T2667 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4/index
[junit4:junit4]   2> 19831 T2667 C188 P49962 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19831 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19831 T2667 C188 P49962 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19831 T2667 C188 P49962 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19833 T2667 C188 P49962 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 20349 T2598 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20350 T2598 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:49962_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:49962"}
[junit4:junit4]   2> 20356 T2646 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> 20356 T2597 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> 20356 T2631 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> 20357 T2662 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> 20356 T2603 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> 20357 T2616 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> 20771 T2575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20773 T2575 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C190 name=collection1 org.apache.solr.core.SolrCore@7bd6e1e3 url=http://127.0.0.1:49948/collection1 node=127.0.0.1:49948_ C190_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49948_, base_url=http://127.0.0.1:49948, leader=true}
[junit4:junit4]   2> 20790 T2589 C190 P49948 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data
[junit4:junit4]   2> 20795 T2589 C190 P49948 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5d4e72d8; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 20796 T2589 C190 P49948 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 20798 T2589 C190 P49948 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/control/data
[junit4:junit4]   2> 20799 T2589 C190 P49948 oass.SolrIndexSearcher.<init> Opening Searcher@455963a8 realtime
[junit4:junit4]   2> 20799 T2589 C190 P49948 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426138100601454592)} 0 10
[junit4:junit4]   2> 20804 T2623 C189 P49955 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty2
[junit4:junit4]   2> 20810 T2608 C187 P49952 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty1
[junit4:junit4]   2>  C188_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49962_, base_url=http://127.0.0.1:49962}
[junit4:junit4]   2> 20819 T2657 C188 P49962 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty4
[junit4:junit4]   2> 20820 T2657 C188 P49962 /update {update.distrib=FROMLEADER&_version_=-1426138100614037504&update.from=http://127.0.0.1:49955/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426138100614037504)} 0 4
[junit4:junit4]   2>  C186_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:49958_, base_url=http://127.0.0.1:49958}
[junit4:junit4]   2> 20824 T2641 C186 P49958 oasc.CachingDirectoryFactory.close Releasing directory:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1360071257409/jetty3
[junit4:junit4]   2> 20825 T2641 C186 P49958 /update {update.distrib=FROMLEADER&_version_=-1426138100621377536&update.from=http://127.0.0.1:49952/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1426138100621377536)} 0 3
[junit4:junit4]   2> 20827 T2608 C187 P49952 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1426138100621377536)} 0 19
[junit4:junit4]   2> 20828 T2623 C189 P49955 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426138100614037504)} 0 26
[junit4:junit4]   2> 20836 T2590 C190 P49948 /update {wt=javabin&version=2} {add=[1 (1426138100646543360)]} 0 4
[junit4:junit4]   2> 20850 T2642 C186 P49958 /update {distrib.from=http://127.0.0.1:49952/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1426138100653883392)]} 0 4
[junit4:junit4]   2> 20852 T2609 C187 P49952 /update {wt=javabin&version=2} {add=[1 (1426138100653883392)]} 0 13

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

dowingOrOverridesOnMethodsRule$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]    > Caused by: java.net.SocketException: Invalid argument
[junit4:junit4]    > 	at java.net.SocketInputStream.socketRead0(Native Method)
[junit4:junit4]    > 	at java.net.SocketInputStream.read(SocketInputStream.java:150)
[junit4:junit4]    > 	at java.net.SocketInputStream.read(SocketInputStream.java:121)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:149)
[junit4:junit4]    > 	at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:111)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:264)
[junit4:junit4]    > 	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:98)
[junit4:junit4]    > 	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:252)
[junit4:junit4]    > 	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:282)
[junit4:junit4]    > 	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:247)
[junit4:junit4]    > 	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:216)
[junit4:junit4]    > 	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:298)
[junit4:junit4]    > 	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
[junit4:junit4]    > 	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:647)
[junit4:junit4]    > 	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:464)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
[junit4:junit4]    > 	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
[junit4:junit4]    > 	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4]    > 	... 44 more
[junit4:junit4]   2> 131416 T2575 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {n_f1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), foo_b=PostingsFormat(name=TestBloomFilteredLucene41Postings), cat=PostingsFormat(name=Memory doPackFST= false), foo_d=MockVariableIntBlock(baseBlockSize=116), foo_f=PostingsFormat(name=TestBloomFilteredLucene41Postings), n_tl1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), n_d1=PostingsFormat(name=Memory doPackFST= false), rnd_b=MockVariableIntBlock(baseBlockSize=116), intDefault=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), n_td1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), timestamp=PostingsFormat(name=Memory doPackFST= false), id=MockVariableIntBlock(baseBlockSize=116), range_facet_sl=MockVariableIntBlock(baseBlockSize=116), range_facet_si=PostingsFormat(name=Memory doPackFST= false), oddField_s=MockVariableIntBlock(baseBlockSize=116), sequence_i=MockVariableIntBlock(baseBlockSize=116), name=MockVariableIntBlock(baseBlockSize=116), foo_i=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), regex_dup_B_s=PostingsFormat(name=Memory doPackFST= false), multiDefault=PostingsFormat(name=Memory doPackFST= false), n_tf1=PostingsFormat(name=Memory doPackFST= false), n_dt1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), genre_s=MockVariableIntBlock(baseBlockSize=116), author_t=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), n_ti1=MockVariableIntBlock(baseBlockSize=116), range_facet_l=PostingsFormat(name=Memory doPackFST= false), text=PostingsFormat(name=TestBloomFilteredLucene41Postings), _version_=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), val_i=MockVariableIntBlock(baseBlockSize=116), SubjectTerms_mfacet=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), series_t=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), a_t=PostingsFormat(name=Memory doPackFST= false), n_tdt1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), regex_dup_A_s=PostingsFormat(name=TestBloomFilteredLucene41Postings), price=PostingsFormat(name=TestBloomFilteredLucene41Postings), other_tl1=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), n_l1=PostingsFormat(name=Memory doPackFST= false), a_si=Pulsing41(freqCutoff=20 minBlockSize=62 maxBlockSize=207), inStock=PostingsFormat(name=TestBloomFilteredLucene41Postings)}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=ko_KR, timezone=America/Metlakatla
[junit4:junit4]   2> NOTE: Mac OS X 10.8.2 x86_64/Oracle Corporation 1.7.0_10 (64-bit)/cpus=2,threads=1,free=317951144,total=452984832
[junit4:junit4]   2> NOTE: All tests run in this JVM: [OverseerCollectionProcessorTest, DocumentAnalysisRequestHandlerTest, SolrIndexConfigTest, TestStressReorder, TestAnalyzedSuggestions, PeerSyncTest, DirectUpdateHandlerTest, TermsComponentTest, SolrCmdDistributorTest, LoggingHandlerTest, CSVRequestHandlerTest, FastVectorHighlighterTest, TestIBSimilarityFactory, SpatialFilterTest, PrimitiveFieldTypeTest, OpenExchangeRatesOrgProviderTest, TestDistributedSearch, SpellCheckComponentTest, DistributedSpellCheckComponentTest, TestBM25SimilarityFactory, HighlighterTest, SpellingQueryConverterTest, RecoveryZkTest, RequestHandlersTest, FieldMutatingUpdateProcessorTest, TestFastWriter, UniqFieldsUpdateProcessorFactoryTest, LeaderElectionTest, StatsComponentTest, ZkControllerTest, TestSuggestSpellingConverter, ClusterStateTest, DistanceFunctionTest, UUIDFieldTest, TestQueryTypes, SampleTest, SOLR749Test, AlternateDirectoryTest, JSONWriterTest, TestPseudoReturnFields, TestCollationField, SuggesterTSTTest, UpdateParamsTest, CollectionsAPIDistributedZkTest, SignatureUpdateProcessorFactoryTest, MBeansHandlerTest, TestStressVersions, TestAtomicUpdateErrorCases, TestNumberUtils, IndexBasedSpellCheckerTest, TestDocumentBuilder, TestUtils, TestReload, TestDefaultSimilarityFactory, TestSolrXMLSerializer, TestLRUCache, SchemaVersionSpecificBehaviorTest, CoreContainerCoreInitFailuresTest, TestJmxMonitoredMap, TestOmitPositions, TestSolrDeletionPolicy2, TestMultiCoreConfBootstrap, SimplePostToolTest, TestRandomFaceting, TestSort, BasicFunctionalityTest, ZkNodePropsTest, TestBadConfig, MultiTermTest, TestCoreContainer, LukeRequestHandlerTest, PluginInfoTest, TestWriterPerf, TestDistributedGrouping, MoreLikeThisHandlerTest, QueryEqualityTest, TestLFUCache, SolrCoreCheckLockOnStartupTest, TestDocSet, NumericFieldsTest, TestLMDirichletSimilarityFactory, ChaosMonkeySafeLeaderTest, TestSearchPerf, DistributedQueryElevationComponentTest, TestPartialUpdateDeduplication, CacheHeaderTest, TestComponentsName, DirectSolrConnectionTest, TestPostingsSolrHighlighter, AnalysisAfterCoreReloadTest, FieldAnalysisRequestHandlerTest, TestCSVResponseWriter, SolrCoreTest, TestCSVLoader, ShowFileRequestHandlerTest, TestHashPartitioner, DirectUpdateHandlerOptimizeTest, StatelessScriptUpdateProcessorFactoryTest, TestLuceneMatchVersion, TestLMJelinekMercerSimilarityFactory, TestRealTimeGet, FileBasedSpellCheckerTest, TestStressRecovery, ChaosMonkeyNothingIsSafeTest, TestValueSourceCache, StandardRequestHandlerTest, LegacyHTMLStripCharFilterTest, TestRangeQuery, OverseerTest, TestXIncludeConfig, DebugComponentTest, SynonymTokenizerTest, ResponseLogComponentTest, TestSolrIndexConfig, SolrRequestParserTest, PathHierarchyTokenizerFactoryTest, TimeZoneUtilsTest, SyncSliceTest, BasicZkTest, IndexReaderFactoryTest, XmlUpdateRequestHandlerTest, BasicDistributedZkTest]
[junit4:junit4] Completed in 131.74s, 1 test, 1 error <<< FAILURES!

[...truncated 380 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:346: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/build.xml:178: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/solr/common-build.xml:432: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:1176: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-trunk-MacOSX/lucene/common-build.xml:841: There were test failures: 249 suites, 1038 tests, 1 error, 14 ignored (3 assumptions)

Total time: 59 minutes 54 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 64bit/jdk1.7.0 -XX:+UseG1GC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message