lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Apache Jenkins Server <jenk...@builds.apache.org>
Subject [JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3725 - Failure
Date Mon, 11 Feb 2013 12:00:33 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3725/

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

Error Message:
Captured an uncaught exception in thread: Thread[id=1166, name=testExecutor-796-thread-3, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]

Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=1166, name=testExecutor-796-thread-3, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
Caused by: java.lang.RuntimeException: org.apache.solr.client.solrj.SolrServerException: Timeout occured while waiting response from server at: http://127.0.0.1:43729
	at __randomizedtesting.SeedInfo.seed([ED2CA16D1CFDA1B6]:0)
	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:722)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)
Caused by: org.apache.solr.client.solrj.SolrServerException: Timeout occured while waiting response from server at: http://127.0.0.1:43729
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:412)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.cloud.BasicDistributedZkTest$2.run(BasicDistributedZkTest.java:720)
	... 3 more
Caused by: java.net.SocketTimeoutException: Read timed out
	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)
	... 5 more


REGRESSION:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
Test Setup Failure: shard1 should have just been set up to be inconsistent - but it's still consistent. Leader:http://127.0.0.1:43589/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@22294ce8, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@f28a1d08]

Stack Trace:
java.lang.AssertionError: Test Setup Failure: shard1 should have just been set up to be inconsistent - but it's still consistent. Leader:http://127.0.0.1:43589/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@22294ce8, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@f28a1d08]
	at __randomizedtesting.SeedInfo.seed([ED2CA16D1CFDA1B6:6CCA2F756BA2C18A]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.junit.Assert.assertTrue(Assert.java:43)
	at org.junit.Assert.assertNotNull(Assert.java:526)
	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:216)
	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)




Build Log:
[...truncated 9116 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4]   2> 1 T659 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 4 T659 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZkTest-1360582328343
[junit4:junit4]   2> 5 T659 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 6 T660 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 8 T660 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 8 T660 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 8 T660 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 9 T660 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 10 T660 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 107 T659 oasc.ZkTestServer.run start zk server on port:43698
[junit4:junit4]   2> 107 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6b3a6b18
[junit4:junit4]   2> 108 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 108 T665 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 109 T665 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 109 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43699
[junit4:junit4]   2> 109 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43699
[junit4:junit4]   2> 110 T663 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 112 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0000 with negotiated timeout 10000 for client /140.211.11.196:43699
[junit4:junit4]   2> 112 T665 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0000, negotiated timeout = 10000
[junit4:junit4]   2> 113 T666 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b3a6b18 name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 113 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 113 T659 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 117 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0000
[junit4:junit4]   2> 125 T666 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 126 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43699 which had sessionid 0x13cc906c01c0000
[junit4:junit4]   2> 125 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0000 closed
[junit4:junit4]   2> 126 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6085861c
[junit4:junit4]   2> 127 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 127 T667 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 128 T667 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 128 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43700
[junit4:junit4]   2> 129 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43700
[junit4:junit4]   2> 130 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0001 with negotiated timeout 10000 for client /140.211.11.196:43700
[junit4:junit4]   2> 130 T667 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0001, negotiated timeout = 10000
[junit4:junit4]   2> 130 T668 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6085861c name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 130 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 131 T659 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 142 T659 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 146 T659 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 154 T659 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 158 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 159 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 172 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 173 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 281 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 282 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 286 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 286 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 298 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 299 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 303 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 304 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 308 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 308 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 312 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 312 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 317 T659 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 317 T659 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 321 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0001
[junit4:junit4]   2> 322 T668 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 322 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0001 closed
[junit4:junit4]   2> 322 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43700 which had sessionid 0x13cc906c01c0001
[junit4:junit4]   2> 450 T659 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 454 T659 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43701
[junit4:junit4]   2> 454 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 455 T659 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 455 T659 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661
[junit4:junit4]   2> 455 T659 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/solr.xml
[junit4:junit4]   2> 456 T659 oasc.CoreContainer.<init> New CoreContainer 922144566
[junit4:junit4]   2> 456 T659 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/'
[junit4:junit4]   2> 457 T659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/'
[junit4:junit4]   2> 498 T659 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 498 T659 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 499 T659 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 499 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 499 T659 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 500 T659 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 500 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 500 T659 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 501 T659 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 501 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 520 T659 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 535 T659 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43698/solr
[junit4:junit4]   2> 535 T659 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 535 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4a94ca6e
[junit4:junit4]   2> 536 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 537 T678 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 537 T678 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 538 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43702
[junit4:junit4]   2> 538 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43702
[junit4:junit4]   2> 540 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0002 with negotiated timeout 20000 for client /140.211.11.196:43702
[junit4:junit4]   2> 540 T678 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0002, negotiated timeout = 20000
[junit4:junit4]   2> 541 T679 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a94ca6e name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 541 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 543 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0002
[junit4:junit4]   2> 544 T679 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 544 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0002 closed
[junit4:junit4]   2> 544 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43702 which had sessionid 0x13cc906c01c0002
[junit4:junit4]   2> 544 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 557 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ecb42
[junit4:junit4]   2> 558 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 558 T680 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 559 T680 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 559 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43703
[junit4:junit4]   2> 560 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43703
[junit4:junit4]   2> 561 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0003 with negotiated timeout 20000 for client /140.211.11.196:43703
[junit4:junit4]   2> 561 T680 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0003, negotiated timeout = 20000
[junit4:junit4]   2> 562 T681 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ecb42 name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 562 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 565 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 573 T659 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 576 T659 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43701_
[junit4:junit4]   2> 577 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43701_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43701_
[junit4:junit4]   2> 578 T659 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43701_
[junit4:junit4]   2> 584 T659 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 597 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 599 T659 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 608 T659 oasc.Overseer.start Overseer (id=89167123470614531-127.0.0.1:43701_-n_0000000000) starting
[junit4:junit4]   2> 609 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 610 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 612 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 621 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 623 T683 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 624 T659 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 629 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 633 T682 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 638 T684 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/collection1
[junit4:junit4]   2> 639 T684 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 640 T684 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 640 T684 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 642 T684 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/collection1/'
[junit4:junit4]   2> 643 T684 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 644 T684 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/collection1/lib/README' to classloader
[junit4:junit4]   2> 701 T684 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 772 T684 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 873 T684 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 878 T684 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1364 T684 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1373 T684 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1376 T684 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1399 T684 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1404 T684 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1408 T684 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1410 T684 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1412 T684 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1360582328661/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/
[junit4:junit4]   2> 1413 T684 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52c9f3c7
[junit4:junit4]   2> 1413 T684 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 1443 T684 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data forceNew:false
[junit4:junit4]   2> 1443 T684 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data
[junit4:junit4]   2> 1443 T684 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index/
[junit4:junit4]   2> 1444 T684 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1445 T684 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index forceNew:false
[junit4:junit4]   2> 1453 T684 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a3b1ae7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1453 T684 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1454 T684 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index
[junit4:junit4]   2> 1454 T684 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 1456 T684 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1456 T684 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 1456 T684 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1457 T684 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 1457 T684 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1457 T684 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1458 T684 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1458 T684 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1458 T684 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1459 T684 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 1459 T684 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 1460 T684 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1460 T684 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 1460 T684 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 1460 T684 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 1461 T684 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1461 T684 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1462 T684 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1462 T684 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1462 T684 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1463 T684 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1463 T684 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1464 T684 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1464 T684 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1464 T684 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 1465 T684 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 1475 T684 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1479 T684 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 1481 T684 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> 1483 T684 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data
[junit4:junit4]   2> 1484 T684 oass.SolrIndexSearcher.<init> Opening Searcher@13e7e387 main
[junit4:junit4]   2> 1485 T684 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1485 T684 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1485 T684 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 1501 T684 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 1542 T685 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13e7e387 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1546 T684 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1546 T684 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1547 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x51 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4]   2> 2138 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2140 T682 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:43701_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43701"}
[junit4:junit4]   2> 2140 T682 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2145 T682 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2146 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x59 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4]   2> 2196 T681 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> 2560 T684 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2560 T684 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43701 collection:control_collection shard:shard1
[junit4:junit4]   2> 2561 T684 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2581 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:delete cxid:0x73 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> 2582 T684 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2582 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x74 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2586 T684 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2586 T684 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2586 T684 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43701/collection1/
[junit4:junit4]   2> 2587 T684 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2587 T684 oasc.SyncStrategy.syncToMe http://127.0.0.1:43701/collection1/ has no replicas
[junit4:junit4]   2> 2587 T684 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43701/collection1/
[junit4:junit4]   2> 2587 T684 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2594 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0003 type:create cxid:0x7e zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3721 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3746 T681 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> 3769 T684 oasc.ZkController.register We are http://127.0.0.1:43701/collection1/ and leader is http://127.0.0.1:43701/collection1/
[junit4:junit4]   2> 3769 T684 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43701
[junit4:junit4]   2> 3769 T684 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3769 T684 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3770 T684 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3772 T684 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3773 T659 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3774 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3774 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3786 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3798 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@2d017f57
[junit4:junit4]   2> 3799 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3800 T686 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3801 T686 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 3801 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43728
[junit4:junit4]   2> 3801 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43728
[junit4:junit4]   2> 3803 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0004 with negotiated timeout 10000 for client /140.211.11.196:43728
[junit4:junit4]   2> 3803 T686 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0004, negotiated timeout = 10000
[junit4:junit4]   2> 3803 T687 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d017f57 name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3803 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3805 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3809 T659 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3947 T659 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3949 T659 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43729
[junit4:junit4]   2> 3950 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3950 T659 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3951 T659 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148
[junit4:junit4]   2> 3951 T659 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/solr.xml
[junit4:junit4]   2> 3951 T659 oasc.CoreContainer.<init> New CoreContainer 231171400
[junit4:junit4]   2> 3952 T659 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/'
[junit4:junit4]   2> 3952 T659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/'
[junit4:junit4]   2> 3997 T659 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 3997 T659 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3998 T659 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3998 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3998 T659 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3999 T659 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3999 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3999 T659 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 4000 T659 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 4000 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 4016 T659 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4032 T659 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43698/solr
[junit4:junit4]   2> 4032 T659 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4033 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3df02958
[junit4:junit4]   2> 4034 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4034 T697 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4035 T697 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 4035 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43730
[junit4:junit4]   2> 4036 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43730
[junit4:junit4]   2> 4038 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0005 with negotiated timeout 20000 for client /140.211.11.196:43730
[junit4:junit4]   2> 4038 T697 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0005, negotiated timeout = 20000
[junit4:junit4]   2> 4038 T698 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3df02958 name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4038 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4040 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0005
[junit4:junit4]   2> 4050 T698 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4050 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0005 closed
[junit4:junit4]   2> 4051 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43730 which had sessionid 0x13cc906c01c0005
[junit4:junit4]   2> 4051 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 4061 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@ac4626e
[junit4:junit4]   2> 4062 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4062 T699 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 4063 T699 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 4063 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43731
[junit4:junit4]   2> 4064 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43731
[junit4:junit4]   2> 4065 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0006 with negotiated timeout 20000 for client /140.211.11.196:43731
[junit4:junit4]   2> 4065 T699 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0006, negotiated timeout = 20000
[junit4:junit4]   2> 4065 T700 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ac4626e name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4066 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4067 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4069 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4077 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4080 T659 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43729_
[junit4:junit4]   2> 4080 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43729_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43729_
[junit4:junit4]   2> 4082 T659 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43729_
[junit4:junit4]   2> 4086 T681 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4086 T681 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> 4086 T700 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4087 T687 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4099 T701 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/collection1
[junit4:junit4]   2> 4099 T701 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4100 T701 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4100 T701 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4102 T701 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/collection1/'
[junit4:junit4]   2> 4103 T701 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4103 T701 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/collection1/lib/README' to classloader
[junit4:junit4]   2> 4150 T701 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4211 T701 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4312 T701 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4317 T701 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4922 T701 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4934 T701 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4939 T701 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 4961 T701 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4967 T701 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4973 T701 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4975 T701 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4977 T701 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1360582332148/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/
[junit4:junit4]   2> 4977 T701 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52c9f3c7
[junit4:junit4]   2> 4978 T701 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 4979 T701 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1 forceNew:false
[junit4:junit4]   2> 4980 T701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1
[junit4:junit4]   2> 4980 T701 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index/
[junit4:junit4]   2> 4981 T701 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 4982 T701 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index forceNew:false
[junit4:junit4]   2> 5002 T701 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@62e664bd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5003 T701 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5004 T701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index
[junit4:junit4]   2> 5004 T701 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 5007 T701 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5007 T701 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 5008 T701 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5008 T701 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 5009 T701 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5009 T701 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5009 T701 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5010 T701 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5011 T701 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5012 T701 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 5012 T701 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 5013 T701 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5014 T701 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 5014 T701 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 5014 T701 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 5015 T701 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5016 T701 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5016 T701 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5017 T701 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5018 T701 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5019 T701 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5019 T701 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5020 T701 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5021 T701 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5021 T701 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 5022 T701 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 5037 T701 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5043 T701 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 5045 T701 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> 5047 T701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1
[junit4:junit4]   2> 5049 T701 oass.SolrIndexSearcher.<init> Opening Searcher@1c98bf3d main
[junit4:junit4]   2> 5051 T701 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5051 T701 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5051 T701 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 5060 T701 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 5123 T702 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c98bf3d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5130 T701 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5130 T701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 5255 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5256 T682 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:43701_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43701"}
[junit4:junit4]   2> 5263 T682 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:43729_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43729"}
[junit4:junit4]   2> 5264 T682 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 5265 T682 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 5272 T681 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> 5272 T687 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> 5272 T700 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> 6134 T701 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 6134 T701 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43729 collection:collection1 shard:shard1
[junit4:junit4]   2> 6136 T701 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 6168 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:delete cxid:0x45 zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 6169 T701 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 6170 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:create cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6180 T701 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 6181 T701 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 6181 T701 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43729/collection1/
[junit4:junit4]   2> 6182 T701 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 6182 T701 oasc.SyncStrategy.syncToMe http://127.0.0.1:43729/collection1/ has no replicas
[junit4:junit4]   2> 6182 T701 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43729/collection1/
[junit4:junit4]   2> 6182 T701 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 6191 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0006 type:create cxid:0x50 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6789 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6811 T681 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> 6811 T700 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> 6811 T687 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> 6864 T701 oasc.ZkController.register We are http://127.0.0.1:43729/collection1/ and leader is http://127.0.0.1:43729/collection1/
[junit4:junit4]   2> 6864 T701 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43729
[junit4:junit4]   2> 6864 T701 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 6865 T701 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 6865 T701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6868 T701 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6870 T659 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 6871 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 6872 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 7063 T659 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 7068 T659 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43732
[junit4:junit4]   2> 7069 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 7070 T659 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 7071 T659 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226
[junit4:junit4]   2> 7071 T659 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/solr.xml
[junit4:junit4]   2> 7072 T659 oasc.CoreContainer.<init> New CoreContainer 202524832
[junit4:junit4]   2> 7072 T659 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/'
[junit4:junit4]   2> 7073 T659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/'
[junit4:junit4]   2> 7136 T659 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 7137 T659 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 7138 T659 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 7138 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 7139 T659 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 7139 T659 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 7140 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 7140 T659 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 7141 T659 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 7141 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 7163 T659 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 7182 T659 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43698/solr
[junit4:junit4]   2> 7183 T659 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 7184 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@6f3f3cc1
[junit4:junit4]   2> 7185 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7185 T712 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 7186 T712 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 7186 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43733
[junit4:junit4]   2> 7187 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43733
[junit4:junit4]   2> 7212 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0007 with negotiated timeout 20000 for client /140.211.11.196:43733
[junit4:junit4]   2> 7212 T712 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0007, negotiated timeout = 20000
[junit4:junit4]   2> 7213 T713 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f3f3cc1 name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7213 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7215 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0007
[junit4:junit4]   2> 7218 T713 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 7218 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43733 which had sessionid 0x13cc906c01c0007
[junit4:junit4]   2> 7218 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0007 closed
[junit4:junit4]   2> 7219 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 7230 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5511c5a6
[junit4:junit4]   2> 7231 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7231 T714 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 7232 T714 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 7232 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43734
[junit4:junit4]   2> 7233 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43734
[junit4:junit4]   2> 7267 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0008 with negotiated timeout 20000 for client /140.211.11.196:43734
[junit4:junit4]   2> 7267 T714 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0008, negotiated timeout = 20000
[junit4:junit4]   2> 7267 T715 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5511c5a6 name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7268 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7269 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7271 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7314 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 7317 T659 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43732_
[junit4:junit4]   2> 7318 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:delete cxid:0x9 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43732_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43732_
[junit4:junit4]   2> 7320 T659 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43732_
[junit4:junit4]   2> 7325 T681 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7325 T687 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7325 T681 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> 7325 T715 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7325 T700 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7325 T687 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> 7326 T700 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> 7385 T716 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/collection1
[junit4:junit4]   2> 7386 T716 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 7387 T716 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 7387 T716 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 7389 T716 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/collection1/'
[junit4:junit4]   2> 7391 T716 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 7391 T716 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/collection1/lib/README' to classloader
[junit4:junit4]   2> 7451 T716 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 7529 T716 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 7630 T716 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 7636 T716 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 8292 T716 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 8305 T716 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 8309 T716 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 8327 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8328 T682 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:43729_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43729"}
[junit4:junit4]   2> 8360 T716 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8367 T716 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8376 T681 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> 8376 T715 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> 8376 T687 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> 8376 T700 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> 8381 T716 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8383 T716 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8385 T716 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1360582335226/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/
[junit4:junit4]   2> 8385 T716 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52c9f3c7
[junit4:junit4]   2> 8386 T716 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 8387 T716 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2 forceNew:false
[junit4:junit4]   2> 8388 T716 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 8388 T716 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index/
[junit4:junit4]   2> 8389 T716 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 8390 T716 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index forceNew:false
[junit4:junit4]   2> 8398 T716 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7900679e; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 8398 T716 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 8399 T716 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index
[junit4:junit4]   2> 8400 T716 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 8402 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 8403 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 8403 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 8403 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 8404 T716 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 8404 T716 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 8405 T716 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 8406 T716 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 8406 T716 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 8407 T716 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 8408 T716 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 8408 T716 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 8409 T716 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 8409 T716 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 8410 T716 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 8411 T716 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 8411 T716 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8412 T716 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8413 T716 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8413 T716 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8414 T716 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8415 T716 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8415 T716 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8416 T716 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8417 T716 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 8418 T716 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 8433 T716 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 8439 T716 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 8441 T716 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> 8444 T716 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 8446 T716 oass.SolrIndexSearcher.<init> Opening Searcher@5918aae8 main
[junit4:junit4]   2> 8447 T716 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 8447 T716 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 8448 T716 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 8457 T716 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 8508 T717 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5918aae8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 8515 T716 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 8516 T716 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9884 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9885 T682 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:43732_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43732"}
[junit4:junit4]   2> 9885 T682 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 9886 T682 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 9910 T700 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> 9910 T687 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> 9910 T681 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> 9910 T715 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> 10520 T716 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 10520 T716 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43732 collection:collection1 shard:shard2
[junit4:junit4]   2> 10521 T716 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 10538 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:delete cxid:0x46 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> 10545 T716 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 10546 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:create cxid:0x47 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 10554 T716 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 10555 T716 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 10555 T716 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:43732/collection1/
[junit4:junit4]   2> 10555 T716 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 10555 T716 oasc.SyncStrategy.syncToMe http://127.0.0.1:43732/collection1/ has no replicas
[junit4:junit4]   2> 10556 T716 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:43732/collection1/
[junit4:junit4]   2> 10556 T716 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 10564 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c0008 type:create cxid:0x50 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11418 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11437 T681 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> 11437 T715 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> 11437 T687 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> 11437 T700 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> 11490 T716 oasc.ZkController.register We are http://127.0.0.1:43732/collection1/ and leader is http://127.0.0.1:43732/collection1/
[junit4:junit4]   2> 11490 T716 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43732
[junit4:junit4]   2> 11490 T716 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 11491 T716 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 11491 T716 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11500 T716 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11502 T659 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 11502 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 11503 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11647 T659 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 11649 T659 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43735
[junit4:junit4]   2> 11650 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 11650 T659 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 11651 T659 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853
[junit4:junit4]   2> 11651 T659 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/solr.xml
[junit4:junit4]   2> 11651 T659 oasc.CoreContainer.<init> New CoreContainer 1234278619
[junit4:junit4]   2> 11652 T659 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/'
[junit4:junit4]   2> 11652 T659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/'
[junit4:junit4]   2> 11702 T659 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 11703 T659 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 11703 T659 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 11704 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 11704 T659 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 11704 T659 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 11705 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 11705 T659 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 11706 T659 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 11706 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 11722 T659 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 11738 T659 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43698/solr
[junit4:junit4]   2> 11738 T659 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 11739 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@529fbd95
[junit4:junit4]   2> 11740 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 11740 T727 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 11741 T727 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 11742 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43736
[junit4:junit4]   2> 11742 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43736
[junit4:junit4]   2> 11753 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c0009 with negotiated timeout 20000 for client /140.211.11.196:43736
[junit4:junit4]   2> 11753 T727 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c0009, negotiated timeout = 20000
[junit4:junit4]   2> 11753 T728 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@529fbd95 name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 11753 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 11755 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c0009
[junit4:junit4]   2> 11762 T728 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 11763 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43736 which had sessionid 0x13cc906c01c0009
[junit4:junit4]   2> 11762 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c0009 closed
[junit4:junit4]   2> 11763 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 11772 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@371dac13
[junit4:junit4]   2> 11773 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 11774 T729 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 11774 T729 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 11774 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43737
[junit4:junit4]   2> 11775 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43737
[junit4:junit4]   2> 11776 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c000a with negotiated timeout 20000 for client /140.211.11.196:43737
[junit4:junit4]   2> 11776 T729 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c000a, negotiated timeout = 20000
[junit4:junit4]   2> 11777 T730 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@371dac13 name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 11777 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 11778 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11780 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000a type:create cxid:0x2 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11782 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 11785 T659 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43735_
[junit4:junit4]   2> 11786 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000a type:delete cxid:0x9 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43735_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43735_
[junit4:junit4]   2> 11792 T659 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43735_
[junit4:junit4]   2> 11803 T687 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11803 T700 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11803 T730 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11803 T681 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11803 T700 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> 11803 T687 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> 11803 T715 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 11804 T681 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> 11804 T715 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> 11814 T731 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/collection1
[junit4:junit4]   2> 11814 T731 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 11815 T731 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 11815 T731 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 11817 T731 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/collection1/'
[junit4:junit4]   2> 11819 T731 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 11819 T731 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/collection1/lib/README' to classloader
[junit4:junit4]   2> 11879 T731 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 11954 T731 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 12055 T731 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 12062 T731 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 12705 T731 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 12718 T731 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 12722 T731 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 12744 T731 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12750 T731 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12756 T731 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12758 T731 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12759 T731 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1360582339853/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/
[junit4:junit4]   2> 12760 T731 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52c9f3c7
[junit4:junit4]   2> 12761 T731 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 12762 T731 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3 forceNew:false
[junit4:junit4]   2> 12763 T731 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 12763 T731 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index/
[junit4:junit4]   2> 12764 T731 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 12765 T731 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index forceNew:false
[junit4:junit4]   2> 12771 T731 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@39d36aca; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 12772 T731 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 12773 T731 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index
[junit4:junit4]   2> 12773 T731 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 12776 T731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 12776 T731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 12777 T731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 12777 T731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 12778 T731 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 12778 T731 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 12778 T731 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 12779 T731 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 12780 T731 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 12781 T731 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 12781 T731 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 12782 T731 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 12783 T731 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 12783 T731 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 12783 T731 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 12784 T731 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 12785 T731 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12786 T731 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12786 T731 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12787 T731 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12788 T731 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12788 T731 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12789 T731 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12790 T731 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 12791 T731 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 12791 T731 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 12807 T731 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 12813 T731 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 12815 T731 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> 12817 T731 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 12819 T731 oass.SolrIndexSearcher.<init> Opening Searcher@14f0d175 main
[junit4:junit4]   2> 12821 T731 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 12821 T731 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 12821 T731 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 12839 T731 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 12912 T732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14f0d175 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 12919 T731 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 12919 T731 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12952 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12954 T682 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:43732_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43732"}
[junit4:junit4]   2> 12959 T682 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:43735_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43735"}
[junit4:junit4]   2> 12960 T682 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 12960 T682 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 12976 T681 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> 12977 T687 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> 12977 T715 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> 12977 T730 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> 12977 T700 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> 13923 T731 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 13923 T731 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43735 collection:collection1 shard:shard1
[junit4:junit4]   2> 13928 T731 oasc.ZkController.register We are http://127.0.0.1:43735/collection1/ and leader is http://127.0.0.1:43729/collection1/
[junit4:junit4]   2> 13929 T731 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43735
[junit4:junit4]   2> 13929 T731 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 13929 T731 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C95 name=collection1 org.apache.solr.core.SolrCore@76be827f url=http://127.0.0.1:43735/collection1 node=127.0.0.1:43735_ C95_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43735_, base_url=http://127.0.0.1:43735}
[junit4:junit4]   2> 13938 T733 C95 P43735 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 13938 T731 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 13938 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 13939 T733 C95 P43735 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 13939 T733 C95 P43735 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 13940 T659 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 13941 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 13941 T733 C95 P43735 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 13941 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 14206 T659 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 14209 T659 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43739
[junit4:junit4]   2> 14210 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 14211 T659 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 14211 T659 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303
[junit4:junit4]   2> 14212 T659 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/solr.xml
[junit4:junit4]   2> 14212 T659 oasc.CoreContainer.<init> New CoreContainer 213174965
[junit4:junit4]   2> 14213 T659 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/'
[junit4:junit4]   2> 14214 T659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/'
[junit4:junit4]   2> 14280 T659 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 14281 T659 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 14281 T659 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 14282 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 14282 T659 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 14283 T659 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 14284 T659 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 14284 T659 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 14285 T659 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 14285 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 14308 T659 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 14330 T659 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:43698/solr
[junit4:junit4]   2> 14330 T659 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 14331 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@49be7569
[junit4:junit4]   2> 14332 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 14333 T743 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 14334 T743 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 14334 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43740
[junit4:junit4]   2> 14334 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43740
[junit4:junit4]   2> 14336 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c000b with negotiated timeout 20000 for client /140.211.11.196:43740
[junit4:junit4]   2> 14336 T743 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c000b, negotiated timeout = 20000
[junit4:junit4]   2> 14337 T744 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@49be7569 name:ZooKeeperConnection Watcher:127.0.0.1:43698 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 14337 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 14339 T664 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc906c01c000b
[junit4:junit4]   2> 14340 T744 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 14340 T659 oaz.ZooKeeper.close Session: 0x13cc906c01c000b closed
[junit4:junit4]   2> 14340 T661 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:43740 which had sessionid 0x13cc906c01c000b
[junit4:junit4]   2> 14341 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 14354 T659 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:43698/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@376d24be
[junit4:junit4]   2> 14355 T659 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 14355 T745 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:43698. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 14356 T745 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:43698, initiating session
[junit4:junit4]   2> 14356 T661 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43741
[junit4:junit4]   2> 14356 T661 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43741
[junit4:junit4]   2> 14358 T663 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc906c01c000c with negotiated timeout 20000 for client /140.211.11.196:43741
[junit4:junit4]   2> 14358 T745 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:43698, sessionid = 0x13cc906c01c000c, negotiated timeout = 20000
[junit4:junit4]   2> 14358 T746 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@376d24be name:ZooKeeperConnection Watcher:127.0.0.1:43698/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 14359 T659 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 14360 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000c type:create cxid:0x1 zxid:0xa0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 14362 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000c type:create cxid:0x2 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 14370 T659 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 14374 T659 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43739_
[junit4:junit4]   2> 14375 T664 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc906c01c000c type:delete cxid:0x9 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:43739_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:43739_
[junit4:junit4]   2> 14376 T659 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43739_
[junit4:junit4]   2> 14379 T730 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> 14380 T681 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14380 T715 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14380 T687 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14381 T700 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14381 T681 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> 14381 T746 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14381 T700 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> 14381 T715 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> 14382 T687 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> 14383 T730 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 14392 T747 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/collection1
[junit4:junit4]   2> 14392 T747 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 14393 T747 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 14394 T747 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 14396 T747 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/collection1/'
[junit4:junit4]   2> 14397 T747 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/collection1/lib/README' to classloader
[junit4:junit4]   2> 14398 T747 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 14458 T747 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 14494 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14495 T682 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:43735_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43735"}
[junit4:junit4]   2> 14516 T687 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> 14516 T715 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> 14516 T681 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> 14517 T700 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> 14517 T746 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> 14517 T730 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> 14536 T747 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 14637 T747 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 14644 T747 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 15323 T747 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 15336 T747 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 15341 T747 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 15361 T747 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15367 T747 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 15373 T747 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15374 T747 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 15376 T747 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1360582342303/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/
[junit4:junit4]   2> 15377 T747 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52c9f3c7
[junit4:junit4]   2> 15377 T747 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 15378 T747 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4 forceNew:false
[junit4:junit4]   2> 15379 T747 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 15380 T747 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index/
[junit4:junit4]   2> 15380 T747 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 15381 T747 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index forceNew:false
[junit4:junit4]   2> 15421 T747 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6534bfaf; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 15422 T747 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 15423 T747 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index
[junit4:junit4]   2> 15423 T747 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 15426 T747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 15426 T747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 15427 T747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 15427 T747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 15428 T747 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 15428 T747 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 15429 T747 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 15429 T747 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 15430 T747 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 15431 T747 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 15432 T747 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 15432 T747 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 15433 T747 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 15433 T747 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 15434 T747 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 15434 T747 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 15435 T747 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15436 T747 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15436 T747 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15437 T747 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15438 T747 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15439 T747 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15439 T747 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15440 T747 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 15441 T747 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 15441 T747 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 15455 T747 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 15461 T747 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 15463 T747 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> 15465 T747 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 15467 T747 oass.SolrIndexSearcher.<init> Opening Searcher@719cff20 main
[junit4:junit4]   2> 15469 T747 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 15469 T747 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 15470 T747 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 15477 T747 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 15537 T748 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@719cff20 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 15545 T747 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 15545 T747 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16025 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16026 T682 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:43739_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43739"}
[junit4:junit4]   2> 16026 T682 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 16026 T682 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 16040 T715 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> 16040 T746 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> 16040 T700 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> 16040 T730 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> 16040 T681 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> 16040 T687 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> 16548 T747 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16548 T747 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43739 collection:collection1 shard:shard2
[junit4:junit4]   2> 16561 T747 oasc.ZkController.register We are http://127.0.0.1:43739/collection1/ and leader is http://127.0.0.1:43732/collection1/
[junit4:junit4]   2> 16561 T747 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43739
[junit4:junit4]   2> 16562 T747 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16562 T747 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C96 name=collection1 org.apache.solr.core.SolrCore@34ff584e url=http://127.0.0.1:43739/collection1 node=127.0.0.1:43739_ C96_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43739_, base_url=http://127.0.0.1:43739}
[junit4:junit4]   2> 16563 T749 C96 P43739 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16564 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16564 T747 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16564 T749 C96 P43739 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16564 T749 C96 P43739 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16565 T659 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16566 T659 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16566 T659 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16571 T749 C96 P43739 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16593 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16596 T659 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 16597 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C95_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43735_, base_url=http://127.0.0.1:43735}
[junit4:junit4]   2> 16991 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43729/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 16991 T733 C95 P43735 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43735 START replicas=[http://127.0.0.1:43729/collection1/] nUpdates=100
[junit4:junit4]   2> 16992 T733 C95 P43735 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 16992 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 16992 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 16993 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 16993 T733 C95 P43735 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 16994 T733 C95 P43735 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43729/collection1/. core=collection1
[junit4:junit4]   2> 16994 T733 C95 P43735 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C97 name=collection1 org.apache.solr.core.SolrCore@6e6b46a1 url=http://127.0.0.1:43729/collection1 node=127.0.0.1:43729_ C97_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43729_, base_url=http://127.0.0.1:43729, leader=true}
[junit4:junit4]   2> 17007 T691 C97 P43729 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 17011 T692 C97 P43729 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 17012 T692 C97 P43729 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1
[junit4:junit4]   2> 17016 T692 C97 P43729 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@62e664bd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 17017 T692 C97 P43729 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 17021 T692 C97 P43729 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@62e664bd; 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@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@62e664bd; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 17021 T692 C97 P43729 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 17022 T692 C97 P43729 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1
[junit4:junit4]   2> 17023 T692 C97 P43729 oass.SolrIndexSearcher.<init> Opening Searcher@7d487005 realtime
[junit4:junit4]   2> 17023 T692 C97 P43729 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 17023 T692 C97 P43729 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4]   2> 17025 T733 C95 P43735 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 17025 T733 C95 P43735 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> 17048 T733 C95 P43735 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 17050 T693 C97 P43729 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 17051 T693 C97 P43729 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 17052 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 17052 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 17052 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 17055 T693 C97 P43729 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1
[junit4:junit4]   2> 17056 T693 C97 P43729 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty1/index
[junit4:junit4]   2> 17057 T693 C97 P43729 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
[junit4:junit4]   2> 17058 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 17059 T733 C95 P43735 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 forceNew:false
[junit4:junit4]   2> 17060 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17061 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5be650c; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 17082 T693 C97 P43729 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=6 
[junit4:junit4]   2> 17090 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index
[junit4:junit4]   2> 17090 T733 C95 P43735 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 17116 T733 C95 P43735 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130211033225396
[junit4:junit4]   2> 17118 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17119 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17119 T733 C95 P43735 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396
[junit4:junit4]   2> 17124 T733 C95 P43735 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5be650c; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 17124 T733 C95 P43735 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 17126 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17131 T733 C95 P43735 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 17131 T733 C95 P43735 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 17132 T733 C95 P43735 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 17133 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396
[junit4:junit4]   2> 17134 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17138 T733 C95 P43735 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5be650c; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 17139 T733 C95 P43735 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 17139 T733 C95 P43735 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 17140 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17140 T733 C95 P43735 oass.SolrIndexSearcher.<init> Opening Searcher@269de3d6 main
[junit4:junit4]   2> 17143 T732 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@269de3d6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 17143 T732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index
[junit4:junit4]   2> 17144 T733 C95 P43735 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 17163 T733 C95 P43735 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5be650c; 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@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5be650c; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 17164 T733 C95 P43735 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 17165 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3
[junit4:junit4]   2> 17166 T733 C95 P43735 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 17166 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index.20130211033225396
[junit4:junit4]   2> 17166 T733 C95 P43735 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty3/index
[junit4:junit4]   2> 17167 T733 C95 P43735 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 17167 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 17167 T733 C95 P43735 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 17167 T733 C95 P43735 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 17170 T733 C95 P43735 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 17548 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17549 T682 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:43739_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43739"}
[junit4:junit4]   2> 17555 T682 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:43735_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43735"}
[junit4:junit4]   2> 17566 T681 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> 17566 T746 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> 17566 T730 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> 17566 T700 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> 17566 T687 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> 17566 T715 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> 17599 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18603 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C96_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43739_, base_url=http://127.0.0.1:43739}
[junit4:junit4]   2> 19596 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:43732/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19596 T749 C96 P43739 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43739 START replicas=[http://127.0.0.1:43732/collection1/] nUpdates=100
[junit4:junit4]   2> 19597 T749 C96 P43739 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19597 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19597 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19598 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19598 T749 C96 P43739 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19599 T749 C96 P43739 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:43732/collection1/. core=collection1
[junit4:junit4]   2> 19599 T749 C96 P43739 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19605 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C98 name=collection1 org.apache.solr.core.SolrCore@83c577f url=http://127.0.0.1:43732/collection1 node=127.0.0.1:43732_ C98_STATE=coll:collection1 core:collection1 props:{shard=shard2, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43732_, base_url=http://127.0.0.1:43732, leader=true}
[junit4:junit4]   2> 19609 T706 C98 P43732 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 19617 T707 C98 P43732 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 19618 T707 C98 P43732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 19622 T707 C98 P43732 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7900679e; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19623 T707 C98 P43732 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19653 T707 C98 P43732 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7900679e; 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@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7900679e; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19653 T707 C98 P43732 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19654 T707 C98 P43732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 19655 T707 C98 P43732 oass.SolrIndexSearcher.<init> Opening Searcher@31c0ff8a realtime
[junit4:junit4]   2> 19655 T707 C98 P43732 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19656 T707 C98 P43732 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 40
[junit4:junit4]   2> 19657 T749 C96 P43739 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19657 T749 C96 P43739 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19660 T708 C98 P43732 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19660 T708 C98 P43732 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1 
[junit4:junit4]   2> 19661 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19661 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19661 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19664 T708 C98 P43732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 19665 T708 C98 P43732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2/index
[junit4:junit4]   2> 19666 T708 C98 P43732 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
[junit4:junit4]   2> 19666 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19668 T749 C96 P43739 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 forceNew:false
[junit4:junit4]   2> 19668 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19669 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79b11d17; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 19672 T708 C98 P43732 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 19674 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index
[junit4:junit4]   2> 19674 T749 C96 P43739 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19675 T749 C96 P43739 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130211033228005
[junit4:junit4]   2> 19676 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19677 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19677 T749 C96 P43739 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index/ new=./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005
[junit4:junit4]   2> 19682 T749 C96 P43739 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79b11d17; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19682 T749 C96 P43739 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19684 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19684 T749 C96 P43739 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19684 T749 C96 P43739 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19685 T749 C96 P43739 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 19685 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005
[junit4:junit4]   2> 19686 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19690 T749 C96 P43739 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79b11d17; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19690 T749 C96 P43739 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19691 T749 C96 P43739 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19691 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19692 T749 C96 P43739 oass.SolrIndexSearcher.<init> Opening Searcher@437f3af8 main
[junit4:junit4]   2> 19694 T748 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@437f3af8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19695 T748 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index
[junit4:junit4]   2> 19695 T749 C96 P43739 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 19711 T749 C96 P43739 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79b11d17; 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@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005 lockFactory=org.apache.lucene.store.NativeFSLockFactory@79b11d17; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 19712 T749 C96 P43739 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 19713 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4
[junit4:junit4]   2> 19713 T749 C96 P43739 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19714 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index.20130211033228005
[junit4:junit4]   2> 19714 T749 C96 P43739 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty4/index
[junit4:junit4]   2> 19714 T749 C96 P43739 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19714 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19715 T749 C96 P43739 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19715 T749 C96 P43739 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19718 T749 C96 P43739 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 20585 T682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20587 T682 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:43739_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:43739"}
[junit4:junit4]   2> 20601 T681 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> 20601 T687 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> 20602 T700 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> 20602 T746 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> 20602 T730 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> 20602 T715 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> 20695 T659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20790 T659 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C99 name=collection1 org.apache.solr.core.SolrCore@161b0ee2 url=http://127.0.0.1:43701/collection1 node=127.0.0.1:43701_ C99_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:43701_, base_url=http://127.0.0.1:43701, leader=true}
[junit4:junit4]   2> 20804 T671 C99 P43701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data
[junit4:junit4]   2> 20809 T671 C99 P43701 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a3b1ae7; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 20810 T671 C99 P43701 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 20811 T671 C99 P43701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/control/data
[junit4:junit4]   2> 20812 T671 C99 P43701 oass.SolrIndexSearcher.<init> Opening Searcher@5e3fd1d1 realtime
[junit4:junit4]   2> 20813 T671 C99 P43701 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1426673997332873216)} 0 10
[junit4:junit4]   2> 20831 T709 C98 P43732 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZkTest-1360582328342/jetty2
[junit4:junit4]   2> 20860 T694 C97 P43729 oasc.CachingDirectoryFactory.

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

Assert.assertNotNull(Assert.java:526)
[junit4:junit4]    > 	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:216)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:794)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4]    > 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[junit4:junit4]    > 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    > 	at java.lang.reflect.Method.invoke(Method.java:601)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4]    > 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4]    > 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4]    > 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:722)
[junit4:junit4]   2> 868762 T2511 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {range_facet_l=MockVariableIntBlock(baseBlockSize=113), text=PostingsFormat(name=SimpleText), _version_=PostingsFormat(name=TestBloomFilteredLucene41Postings), rnd_b=PostingsFormat(name=MockRandom), intDefault=PostingsFormat(name=TestBloomFilteredLucene41Postings), timestamp=MockVariableIntBlock(baseBlockSize=113), id=PostingsFormat(name=MockRandom), a_t=MockVariableIntBlock(baseBlockSize=113), range_facet_sl=PostingsFormat(name=MockRandom), range_facet_si=MockVariableIntBlock(baseBlockSize=113), other_tl1=PostingsFormat(name=TestBloomFilteredLucene41Postings), multiDefault=MockVariableIntBlock(baseBlockSize=113), a_si=PostingsFormat(name=TestBloomFilteredLucene41Postings)}, docValues:{}, sim=DefaultSimilarity, locale=hu, timezone=Asia/Ashgabat
[junit4:junit4]   2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_09 (64-bit)/cpus=16,threads=2,free=185045608,total=536870912
[junit4:junit4]   2> NOTE: All tests run in this JVM: [TestPhraseSuggestions, TestJmxIntegration, TestBinaryField, DistributedQueryElevationComponentTest, OutputWriterTest, PrimUtilsTest, TestQuerySenderListener, FieldMutatingUpdateProcessorTest, SolrIndexSplitterTest, DirectSolrSpellCheckerTest, UUIDFieldTest, SuggesterTest, DocumentAnalysisRequestHandlerTest, HardAutoCommitTest, SolrCoreTest, StandardRequestHandlerTest, SuggesterTSTTest, TestDocSet, BasicZkTest, ExternalFileFieldSortTest, TestPropInjectDefaults, IndexReaderFactoryTest, TestReload, PeerSyncTest, TestAnalyzedSuggestions, HighlighterTest, XsltUpdateRequestHandlerTest, TestLRUCache, AnalysisAfterCoreReloadTest, QueryEqualityTest, TestRemoteStreaming, DisMaxRequestHandlerTest, SignatureUpdateProcessorFactoryTest, RequiredFieldsTest, TestTrie, DebugComponentTest, SpellingQueryConverterTest, StatelessScriptUpdateProcessorFactoryTest, EchoParamsTest, TestWriterPerf, TestMultiCoreConfBootstrap, TestCSVResponseWriter, ClusterStateTest, PrimitiveFieldTypeTest, TestSolrXMLSerializer, TestMergePolicyConfig, TestBM25SimilarityFactory, MultiTermTest, TestPropInject, ZkSolrClientTest, TestSolrDeletionPolicy2, LukeRequestHandlerTest, TestArbitraryIndexDir, TestPluginEnable, TestDistributedGrouping, TestStressLucene, FileUtilsTest, TestQueryUtils, ShowFileRequestHandlerTest, BasicDistributedZkTest, TestDistributedSearch, SpellCheckCollatorTest, SoftAutoCommitTest, AutoCommitTest, TestHashPartitioner, StatsComponentTest, TestRecovery, TestCoreContainer, TestGroupingSearch, SampleTest, CoreAdminHandlerTest, SolrRequestParserTest, DirectSolrConnectionTest, TestWordDelimiterFilterFactory, PolyFieldTest, MoreLikeThisHandlerTest, CurrencyFieldTest, IndexSchemaTest, QueryParsingTest, SolrInfoMBeanTest, TestQueryTypes, XmlUpdateRequestHandlerTest, PingRequestHandlerTest, SuggesterWFSTTest, IndexSchemaRuntimeFieldTest, TestReversedWildcardFilterFactory, SearchHandlerTest, TestOmitPositions, UpdateParamsTest, NotRequiredUniqueKeyTest, BadIndexSchemaTest, TestFoldingMultitermQuery, UpdateRequestProcessorFactoryTest, NoCacheHeaderTest, TestUpdate, SolrIndexConfigTest, TestNumberUtils, TestSolrCoreProperties, SpellPossibilityIteratorTest, LegacyHTMLStripCharFilterTest, TestCodecSupport, TimeZoneUtilsTest, OpenExchangeRatesOrgProviderTest, DOMUtilTest, RAMDirectoryFactoryTest, TestUtils, PreAnalyzedFieldTest, ZkNodePropsTest, TestDocumentBuilder, PathHierarchyTokenizerFactoryTest, TestCharFilters, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest, ShardRoutingTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 868.79s, 1 test, 1 failure <<< FAILURES!

[...truncated 11 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:361: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1202: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:865: There were test failures: 250 suites, 1040 tests, 1 error, 1 failure, 22 ignored (4 assumptions)

Total time: 57 minutes 12 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message