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-Java6 - Build # 15910 - Failure
Date Mon, 11 Feb 2013 04:22:50 GMT
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java6/15910/

1 tests failed.
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:23844/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@da25a88c, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@c661f225]

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:23844/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@da25a88c, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@c661f225]
	at __randomizedtesting.SeedInfo.seed([2B34A65A95360876:AAD22842E269684A]: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:616)
	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:679)




Build Log:
[...truncated 8644 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4]   2> 1 T803 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 4 T803 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4]   2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1360555381069
[junit4:junit4]   2> 5 T803 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 5 T804 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 9 T804 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 9 T804 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 9 T804 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 10 T804 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 10 T804 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 106 T803 oasc.ZkTestServer.run start zk server on port:49139
[junit4:junit4]   2> 107 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@37cbcec3
[junit4:junit4]   2> 108 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 108 T809 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 109 T809 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 109 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:32898
[junit4:junit4]   2> 109 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:32898
[junit4:junit4]   2> 109 T807 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 112 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540000 with negotiated timeout 10000 for client /140.211.11.196:32898
[junit4:junit4]   2> 112 T809 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540000, negotiated timeout = 10000
[junit4:junit4]   2> 112 T810 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37cbcec3 name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 113 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 113 T803 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 117 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540000
[junit4:junit4]   2> 125 T810 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 125 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:32898 which had sessionid 0x13cc76b91540000
[junit4:junit4]   2> 125 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540000 closed
[junit4:junit4]   2> 126 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@2c111e4d
[junit4:junit4]   2> 127 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 127 T811 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 128 T811 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 128 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:57958
[junit4:junit4]   2> 128 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:57958
[junit4:junit4]   2> 129 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540001 with negotiated timeout 10000 for client /140.211.11.196:57958
[junit4:junit4]   2> 129 T811 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540001, negotiated timeout = 10000
[junit4:junit4]   2> 130 T812 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2c111e4d name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 130 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 130 T803 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 138 T803 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 141 T803 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 145 T803 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 153 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig.xml to /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 153 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 179 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 180 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 284 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4]   2> 285 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 288 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4]   2> 288 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 292 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4]   2> 292 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 303 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 304 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 306 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 307 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 309 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 310 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 318 T803 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4]   2> 318 T803 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 321 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540001
[junit4:junit4]   2> 322 T812 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 322 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:57958 which had sessionid 0x13cc76b91540001
[junit4:junit4]   2> 322 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540001 closed
[junit4:junit4]   2> 433 T803 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 440 T803 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63384
[junit4:junit4]   2> 441 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 441 T803 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 442 T803 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387
[junit4:junit4]   2> 442 T803 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/solr.xml
[junit4:junit4]   2> 442 T803 oasc.CoreContainer.<init> New CoreContainer 875214478
[junit4:junit4]   2> 443 T803 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/'
[junit4:junit4]   2> 443 T803 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/'
[junit4:junit4]   2> 475 T803 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 475 T803 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 476 T803 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 476 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 476 T803 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 477 T803 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 477 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 477 T803 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 477 T803 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 478 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 492 T803 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 504 T803 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49139/solr
[junit4:junit4]   2> 505 T803 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 505 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4b22adee
[junit4:junit4]   2> 506 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 506 T822 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 508 T822 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 508 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:19569
[junit4:junit4]   2> 508 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:19569
[junit4:junit4]   2> 509 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540002 with negotiated timeout 20000 for client /140.211.11.196:19569
[junit4:junit4]   2> 510 T822 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540002, negotiated timeout = 20000
[junit4:junit4]   2> 510 T823 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b22adee name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 510 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 511 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540002
[junit4:junit4]   2> 512 T823 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 512 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:19569 which had sessionid 0x13cc76b91540002
[junit4:junit4]   2> 512 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540002 closed
[junit4:junit4]   2> 513 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 520 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1a6921e0
[junit4:junit4]   2> 521 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 521 T824 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 522 T824 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 522 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:43494
[junit4:junit4]   2> 522 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:43494
[junit4:junit4]   2> 523 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540003 with negotiated timeout 20000 for client /140.211.11.196:43494
[junit4:junit4]   2> 523 T824 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540003, negotiated timeout = 20000
[junit4:junit4]   2> 523 T825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a6921e0 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 524 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 526 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 535 T803 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 537 T803 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63384_
[junit4:junit4]   2> 538 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63384_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63384_
[junit4:junit4]   2> 539 T803 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63384_
[junit4:junit4]   2> 549 T803 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 562 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 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> 563 T803 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 566 T803 oasc.Overseer.start Overseer (id=89165357454196739-127.0.0.1:63384_-n_0000000000) starting
[junit4:junit4]   2> 567 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 568 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 578 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 579 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 586 T827 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 587 T803 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 590 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 592 T826 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 595 T828 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/collection1
[junit4:junit4]   2> 595 T828 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 596 T828 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 596 T828 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 597 T828 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/collection1/'
[junit4:junit4]   2> 598 T828 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 599 T828 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/collection1/lib/README' to classloader
[junit4:junit4]   2> 657 T828 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 730 T828 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 831 T828 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 837 T828 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1476 T828 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1487 T828 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1491 T828 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1506 T828 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1511 T828 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1516 T828 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1517 T828 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1518 T828 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1360555381387/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/
[junit4:junit4]   2> 1518 T828 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@327124af
[junit4:junit4]   2> 1519 T828 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 1520 T828 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data forceNew:false
[junit4:junit4]   2> 1521 T828 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data
[junit4:junit4]   2> 1521 T828 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/index/
[junit4:junit4]   2> 1522 T828 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1523 T828 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/index forceNew:false
[junit4:junit4]   2> 1529 T828 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d89759; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1530 T828 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1531 T828 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data/index
[junit4:junit4]   2> 1531 T828 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 1533 T828 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1533 T828 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 1533 T828 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1534 T828 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 1534 T828 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1535 T828 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1535 T828 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1535 T828 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1536 T828 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1536 T828 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 1537 T828 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 1537 T828 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1538 T828 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 1538 T828 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 1538 T828 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 1539 T828 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1539 T828 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1539 T828 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1540 T828 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1540 T828 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1541 T828 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1541 T828 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1542 T828 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1542 T828 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 1542 T828 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 1543 T828 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 1550 T828 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1555 T828 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 1556 T828 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> 1559 T828 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/control/data
[junit4:junit4]   2> 1561 T828 oass.SolrIndexSearcher.<init> Opening Searcher@308092db main
[junit4:junit4]   2> 1562 T828 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1562 T828 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1562 T828 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 1580 T828 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 1642 T829 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@308092db main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1645 T828 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1645 T828 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1646 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 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> 2095 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 2096 T826 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:63384_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:63384"}
[junit4:junit4]   2> 2096 T826 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 2097 T826 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2097 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 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> 2115 T825 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> 2658 T828 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2658 T828 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63384 collection:control_collection shard:shard1
[junit4:junit4]   2> 2659 T828 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2676 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 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> 2677 T828 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2678 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x74 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2680 T828 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2680 T828 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2680 T828 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63384/collection1/
[junit4:junit4]   2> 2680 T828 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2681 T828 oasc.SyncStrategy.syncToMe http://127.0.0.1:63384/collection1/ has no replicas
[junit4:junit4]   2> 2681 T828 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63384/collection1/
[junit4:junit4]   2> 2681 T828 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2685 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540003 type:create cxid:0x7e zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3625 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3648 T825 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> 3707 T828 oasc.ZkController.register We are http://127.0.0.1:63384/collection1/ and leader is http://127.0.0.1:63384/collection1/
[junit4:junit4]   2> 3707 T828 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63384
[junit4:junit4]   2> 3707 T828 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3707 T828 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3708 T828 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3709 T828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3710 T803 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0
[junit4:junit4]   2> 3711 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3712 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3725 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3733 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@200db873
[junit4:junit4]   2> 3734 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3735 T830 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 3735 T830 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 3735 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:48383
[junit4:junit4]   2> 3736 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:48383
[junit4:junit4]   2> 3737 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540004 with negotiated timeout 10000 for client /140.211.11.196:48383
[junit4:junit4]   2> 3737 T830 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540004, negotiated timeout = 10000
[junit4:junit4]   2> 3737 T831 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@200db873 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3738 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3739 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3741 T803 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3909 T803 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3912 T803 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:52940
[junit4:junit4]   2> 3912 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3913 T803 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3913 T803 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805
[junit4:junit4]   2> 3914 T803 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/solr.xml
[junit4:junit4]   2> 3914 T803 oasc.CoreContainer.<init> New CoreContainer 505847021
[junit4:junit4]   2> 3915 T803 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/'
[junit4:junit4]   2> 3915 T803 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/'
[junit4:junit4]   2> 3964 T803 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 3965 T803 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3966 T803 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3966 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3966 T803 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3967 T803 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3967 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3968 T803 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3968 T803 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3969 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3988 T803 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 4007 T803 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49139/solr
[junit4:junit4]   2> 4008 T803 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 4008 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@23fcb72b
[junit4:junit4]   2> 4009 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4010 T841 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 4011 T841 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 4011 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:47564
[junit4:junit4]   2> 4012 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:47564
[junit4:junit4]   2> 4028 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540005 with negotiated timeout 20000 for client /140.211.11.196:47564
[junit4:junit4]   2> 4029 T841 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540005, negotiated timeout = 20000
[junit4:junit4]   2> 4029 T842 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@23fcb72b name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4029 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4031 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540005
[junit4:junit4]   2> 4050 T842 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 4051 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:47564 which had sessionid 0x13cc76b91540005
[junit4:junit4]   2> 4050 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540005 closed
[junit4:junit4]   2> 4051 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 4060 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@47f00415
[junit4:junit4]   2> 4061 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 4062 T843 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 4062 T843 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 4062 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:49475
[junit4:junit4]   2> 4063 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:49475
[junit4:junit4]   2> 4064 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540006 with negotiated timeout 20000 for client /140.211.11.196:49475
[junit4:junit4]   2> 4064 T843 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540006, negotiated timeout = 20000
[junit4:junit4]   2> 4065 T844 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47f00415 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 4065 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 4066 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4091 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 4093 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4095 T803 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52940_
[junit4:junit4]   2> 4096 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52940_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52940_
[junit4:junit4]   2> 4097 T803 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52940_
[junit4:junit4]   2> 4100 T825 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 4101 T831 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4101 T844 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4102 T825 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4114 T845 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/collection1
[junit4:junit4]   2> 4114 T845 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4115 T845 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4115 T845 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4116 T845 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/collection1/'
[junit4:junit4]   2> 4117 T845 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/collection1/lib/README' to classloader
[junit4:junit4]   2> 4118 T845 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4173 T845 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4246 T845 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4347 T845 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4353 T845 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 4958 T845 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 4969 T845 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 4973 T845 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 4987 T845 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4992 T845 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 4996 T845 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4997 T845 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 4998 T845 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1360555384805/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/
[junit4:junit4]   2> 4999 T845 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@327124af
[junit4:junit4]   2> 4999 T845 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 5000 T845 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1 forceNew:false
[junit4:junit4]   2> 5000 T845 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 5001 T845 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index/
[junit4:junit4]   2> 5001 T845 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5002 T845 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index forceNew:false
[junit4:junit4]   2> 5008 T845 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5008 T845 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5009 T845 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index
[junit4:junit4]   2> 5010 T845 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 5012 T845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5012 T845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 5012 T845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5013 T845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 5013 T845 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5013 T845 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5014 T845 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5014 T845 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5015 T845 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5015 T845 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 5016 T845 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 5016 T845 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5017 T845 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 5017 T845 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 5017 T845 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 5018 T845 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5018 T845 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5019 T845 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5019 T845 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5020 T845 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5020 T845 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5021 T845 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5021 T845 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5021 T845 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 5022 T845 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 5023 T845 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 5030 T845 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5034 T845 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 5035 T845 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> 5038 T845 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 5040 T845 oass.SolrIndexSearcher.<init> Opening Searcher@6f34a809 main
[junit4:junit4]   2> 5041 T845 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5041 T845 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5041 T845 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 5048 T845 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 5105 T846 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f34a809 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5109 T845 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5109 T845 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 5161 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5162 T826 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:63384_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:63384"}
[junit4:junit4]   2> 5172 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52940_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52940"}
[junit4:junit4]   2> 5172 T826 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4]   2> 5172 T826 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 5185 T844 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> 5185 T825 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> 5185 T831 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> 6112 T845 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 6112 T845 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52940 collection:collection1 shard:shard1
[junit4:junit4]   2> 6113 T845 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 6130 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 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> 6131 T845 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 6132 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 type:create cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6141 T845 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 6141 T845 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 6141 T845 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 6141 T845 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 6141 T845 oasc.SyncStrategy.syncToMe http://127.0.0.1:52940/collection1/ has no replicas
[junit4:junit4]   2> 6142 T845 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 6142 T845 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 6152 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540006 type:create cxid:0x50 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 6701 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6718 T831 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> 6718 T825 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> 6718 T844 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> 6766 T845 oasc.ZkController.register We are http://127.0.0.1:52940/collection1/ and leader is http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 6766 T845 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52940
[junit4:junit4]   2> 6766 T845 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 6766 T845 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 6766 T845 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6768 T845 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6769 T803 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0
[junit4:junit4]   2> 6770 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 6770 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 6950 T803 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 6954 T803 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:23844
[junit4:junit4]   2> 6954 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 6955 T803 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 6955 T803 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848
[junit4:junit4]   2> 6956 T803 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/solr.xml
[junit4:junit4]   2> 6956 T803 oasc.CoreContainer.<init> New CoreContainer 1496026375
[junit4:junit4]   2> 6957 T803 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/'
[junit4:junit4]   2> 6957 T803 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/'
[junit4:junit4]   2> 7006 T803 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 7006 T803 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 7007 T803 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 7007 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 7008 T803 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 7008 T803 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 7009 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 7009 T803 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 7010 T803 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 7010 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 7031 T803 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 7056 T803 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49139/solr
[junit4:junit4]   2> 7057 T803 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 7057 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7c83c92a
[junit4:junit4]   2> 7058 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7059 T856 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 7060 T856 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 7060 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:33172
[junit4:junit4]   2> 7060 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:33172
[junit4:junit4]   2> 7063 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540007 with negotiated timeout 20000 for client /140.211.11.196:33172
[junit4:junit4]   2> 7063 T856 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540007, negotiated timeout = 20000
[junit4:junit4]   2> 7063 T857 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c83c92a name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7063 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7065 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540007
[junit4:junit4]   2> 7079 T857 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 7079 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:33172 which had sessionid 0x13cc76b91540007
[junit4:junit4]   2> 7079 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540007 closed
[junit4:junit4]   2> 7080 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 7091 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2f5b6cc8
[junit4:junit4]   2> 7092 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 7093 T858 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 7093 T858 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 7093 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:26900
[junit4:junit4]   2> 7094 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:26900
[junit4:junit4]   2> 7095 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540008 with negotiated timeout 20000 for client /140.211.11.196:26900
[junit4:junit4]   2> 7095 T858 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540008, negotiated timeout = 20000
[junit4:junit4]   2> 7095 T859 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f5b6cc8 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 7095 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 7096 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7102 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540008 type:create cxid:0x2 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7104 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 7106 T803 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:23844_
[junit4:junit4]   2> 7107 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b91540008 type:delete cxid:0x9 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:23844_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:23844_
[junit4:junit4]   2> 7108 T803 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:23844_
[junit4:junit4]   2> 7110 T844 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> 7110 T825 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> 7111 T831 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7111 T859 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7111 T831 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> 7112 T825 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7112 T844 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 7125 T860 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/collection1
[junit4:junit4]   2> 7125 T860 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 7126 T860 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 7126 T860 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 7127 T860 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/collection1/'
[junit4:junit4]   2> 7128 T860 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/collection1/lib/README' to classloader
[junit4:junit4]   2> 7129 T860 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 7183 T860 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 7257 T860 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 7358 T860 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 7364 T860 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 7986 T860 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 7997 T860 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 8001 T860 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 8040 T860 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8046 T860 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 8051 T860 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8052 T860 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 8053 T860 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1360555387848/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/
[junit4:junit4]   2> 8053 T860 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@327124af
[junit4:junit4]   2> 8054 T860 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 8055 T860 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2 forceNew:false
[junit4:junit4]   2> 8055 T860 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 8056 T860 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index/
[junit4:junit4]   2> 8056 T860 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 8057 T860 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index forceNew:false
[junit4:junit4]   2> 8103 T860 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a0c665b; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 8103 T860 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 8104 T860 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index
[junit4:junit4]   2> 8105 T860 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 8107 T860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 8107 T860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 8107 T860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 8108 T860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 8108 T860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 8108 T860 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 8109 T860 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 8109 T860 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 8110 T860 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 8110 T860 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 8111 T860 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 8111 T860 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 8112 T860 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 8112 T860 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 8112 T860 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 8113 T860 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 8113 T860 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8114 T860 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8114 T860 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8115 T860 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8115 T860 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8116 T860 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8116 T860 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8117 T860 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 8117 T860 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 8118 T860 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 8125 T860 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 8130 T860 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 8131 T860 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> 8134 T860 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 8135 T860 oass.SolrIndexSearcher.<init> Opening Searcher@62d6a33f main
[junit4:junit4]   2> 8136 T860 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 8137 T860 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 8137 T860 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 8152 T860 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 8204 T861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@62d6a33f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 8208 T860 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 8209 T860 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8223 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8224 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:52940_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:52940"}
[junit4:junit4]   2> 8228 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:23844_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:23844"}
[junit4:junit4]   2> 8229 T826 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 8229 T826 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 8245 T825 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> 8245 T831 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> 8245 T844 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> 8245 T859 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> 9211 T860 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 9211 T860 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:23844 collection:collection1 shard:shard1
[junit4:junit4]   2> 9214 T860 oasc.ZkController.register We are http://127.0.0.1:23844/collection1/ and leader is http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 9215 T860 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:23844
[junit4:junit4]   2> 9215 T860 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 9215 T860 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C62 name=collection1 org.apache.solr.core.SolrCore@2fd2d7c9 url=http://127.0.0.1:23844/collection1 node=127.0.0.1:23844_ C62_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:23844_, base_url=http://127.0.0.1:23844}
[junit4:junit4]   2> 9216 T862 C62 P23844 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 9216 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 9216 T860 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9216 T862 C62 P23844 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 9217 T862 C62 P23844 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 9218 T862 C62 P23844 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 9218 T803 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0
[junit4:junit4]   2> 9219 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 9219 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 9418 T803 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 9421 T803 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:13297
[junit4:junit4]   2> 9421 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 9422 T803 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 9422 T803 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304
[junit4:junit4]   2> 9423 T803 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/solr.xml
[junit4:junit4]   2> 9423 T803 oasc.CoreContainer.<init> New CoreContainer 266249613
[junit4:junit4]   2> 9424 T803 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/'
[junit4:junit4]   2> 9424 T803 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/'
[junit4:junit4]   2> 9476 T803 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 9476 T803 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 9477 T803 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 9477 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 9478 T803 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 9478 T803 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 9479 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 9479 T803 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 9479 T803 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 9480 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 9501 T803 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 9519 T803 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49139/solr
[junit4:junit4]   2> 9520 T803 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 9520 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@63639c5
[junit4:junit4]   2> 9521 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9522 T872 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 9523 T872 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 9523 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:54559
[junit4:junit4]   2> 9523 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:54559
[junit4:junit4]   2> 9526 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b91540009 with negotiated timeout 20000 for client /140.211.11.196:54559
[junit4:junit4]   2> 9526 T872 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b91540009, negotiated timeout = 20000
[junit4:junit4]   2> 9526 T873 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63639c5 name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9526 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9528 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b91540009
[junit4:junit4]   2> 9540 T873 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 9540 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:54559 which had sessionid 0x13cc76b91540009
[junit4:junit4]   2> 9540 T803 oaz.ZooKeeper.close Session: 0x13cc76b91540009 closed
[junit4:junit4]   2> 9541 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 9552 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@529d8124
[junit4:junit4]   2> 9553 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 9553 T874 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 9553 T874 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 9554 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:48631
[junit4:junit4]   2> 9554 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:48631
[junit4:junit4]   2> 9555 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b9154000a with negotiated timeout 20000 for client /140.211.11.196:48631
[junit4:junit4]   2> 9555 T874 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b9154000a, negotiated timeout = 20000
[junit4:junit4]   2> 9556 T875 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@529d8124 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 9556 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 9557 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000a type:create cxid:0x1 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9563 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000a type:create cxid:0x2 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 9564 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9566 T803 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:13297_
[junit4:junit4]   2> 9567 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000a type:delete cxid:0x9 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:13297_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:13297_
[junit4:junit4]   2> 9568 T803 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:13297_
[junit4:junit4]   2> 9571 T844 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> 9571 T825 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> 9572 T875 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 9572 T831 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 9572 T859 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 9572 T831 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> 9572 T859 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> 9573 T844 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 9574 T825 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 9585 T876 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/collection1
[junit4:junit4]   2> 9586 T876 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9586 T876 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9587 T876 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9588 T876 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/collection1/'
[junit4:junit4]   2> 9589 T876 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/collection1/lib/README' to classloader
[junit4:junit4]   2> 9590 T876 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9645 T876 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9717 T876 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9811 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9811 T826 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:23844_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:23844"}
[junit4:junit4]   2> 9818 T876 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9825 T844 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> 9825 T875 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> 9825 T825 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> 9825 T876 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9825 T831 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> 9825 T859 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> 10475 T876 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 10488 T876 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 10493 T876 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 10527 T876 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10533 T876 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 10538 T876 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10539 T876 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 10541 T876 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1360555390304/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/
[junit4:junit4]   2> 10541 T876 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@327124af
[junit4:junit4]   2> 10541 T876 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 10542 T876 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3 forceNew:false
[junit4:junit4]   2> 10543 T876 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 10543 T876 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index/
[junit4:junit4]   2> 10544 T876 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 10545 T876 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index forceNew:false
[junit4:junit4]   2> 10552 T876 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5785b615; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 10552 T876 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 10553 T876 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index
[junit4:junit4]   2> 10553 T876 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 10556 T876 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 10556 T876 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 10557 T876 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 10557 T876 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 10558 T876 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 10558 T876 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 10558 T876 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 10559 T876 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 10559 T876 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 10560 T876 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 10561 T876 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 10561 T876 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 10562 T876 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 10562 T876 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 10562 T876 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 10563 T876 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 10563 T876 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10564 T876 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10564 T876 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10565 T876 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10565 T876 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10566 T876 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10566 T876 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10567 T876 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 10567 T876 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 10568 T876 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 10577 T876 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 10582 T876 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 10583 T876 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> 10586 T876 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 10588 T876 oass.SolrIndexSearcher.<init> Opening Searcher@a10a9cd main
[junit4:junit4]   2> 10589 T876 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 10589 T876 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 10590 T876 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 10597 T876 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 10652 T877 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a10a9cd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 10656 T876 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 10656 T876 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11330 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11331 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:13297_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:13297"}
[junit4:junit4]   2> 11331 T826 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 11331 T826 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 11345 T844 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> 11345 T831 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> 11345 T875 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> 11345 T859 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> 11345 T825 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> 11659 T876 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11659 T876 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:13297 collection:collection1 shard:shard1
[junit4:junit4]   2> 11663 T876 oasc.ZkController.register We are http://127.0.0.1:13297/collection1/ and leader is http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 11663 T876 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:13297
[junit4:junit4]   2> 11663 T876 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 11663 T876 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C63 name=collection1 org.apache.solr.core.SolrCore@3ee456d8 url=http://127.0.0.1:13297/collection1 node=127.0.0.1:13297_ C63_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:13297_, base_url=http://127.0.0.1:13297}
[junit4:junit4]   2> 11664 T878 C63 P13297 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 11665 T876 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11665 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 11665 T878 C63 P13297 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 11665 T878 C63 P13297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11666 T803 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0
[junit4:junit4]   2> 11667 T878 C63 P13297 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11667 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 11668 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 11878 T803 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 11881 T803 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:45101
[junit4:junit4]   2> 11882 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 11883 T803 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 11883 T803 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755
[junit4:junit4]   2> 11883 T803 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/solr.xml
[junit4:junit4]   2> 11884 T803 oasc.CoreContainer.<init> New CoreContainer 146466730
[junit4:junit4]   2> 11885 T803 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/'
[junit4:junit4]   2> 11885 T803 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/'
[junit4:junit4]   2> 11940 T803 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 60000
[junit4:junit4]   2> 11941 T803 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 11941 T803 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 11942 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 11942 T803 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 11943 T803 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 11943 T803 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 11943 T803 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 11944 T803 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 11944 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=60000&connTimeout=15000&retry=false
[junit4:junit4]   2> 11966 T803 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 11987 T803 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:49139/solr
[junit4:junit4]   2> 11987 T803 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 11988 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@59b2947f
[junit4:junit4]   2> 11989 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 11990 T888 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 11991 T888 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 11991 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:58795
[junit4:junit4]   2> 11991 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:58795
[junit4:junit4]   2> 11994 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b9154000b with negotiated timeout 20000 for client /140.211.11.196:58795
[junit4:junit4]   2> 11995 T888 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b9154000b, negotiated timeout = 20000
[junit4:junit4]   2> 11995 T889 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59b2947f name:ZooKeeperConnection Watcher:127.0.0.1:49139 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 11995 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 11997 T808 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cc76b9154000b
[junit4:junit4]   2> 12009 T889 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12009 T805 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:58795 which had sessionid 0x13cc76b9154000b
[junit4:junit4]   2> 12009 T803 oaz.ZooKeeper.close Session: 0x13cc76b9154000b closed
[junit4:junit4]   2> 12010 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=60000&connTimeout=15000
[junit4:junit4]   2> 12021 T803 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:49139/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@504b9ec5
[junit4:junit4]   2> 12022 T803 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12023 T890 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:49139. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4]   2> 12023 T890 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:49139, initiating session
[junit4:junit4]   2> 12024 T805 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:11837
[junit4:junit4]   2> 12024 T805 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:11837
[junit4:junit4]   2> 12025 T807 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cc76b9154000c with negotiated timeout 20000 for client /140.211.11.196:11837
[junit4:junit4]   2> 12025 T890 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:49139, sessionid = 0x13cc76b9154000c, negotiated timeout = 20000
[junit4:junit4]   2> 12026 T891 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@504b9ec5 name:ZooKeeperConnection Watcher:127.0.0.1:49139/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12026 T803 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12027 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000c type:create cxid:0x1 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12029 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000c type:create cxid:0x2 zxid:0x92 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12039 T803 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 12042 T803 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45101_
[junit4:junit4]   2> 12042 T808 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cc76b9154000c type:delete cxid:0x9 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:45101_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:45101_
[junit4:junit4]   2> 12044 T803 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45101_
[junit4:junit4]   2> 12046 T844 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> 12046 T875 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> 12046 T825 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> 12047 T831 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12047 T859 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12047 T891 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12047 T831 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> 12047 T859 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> 12048 T844 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12049 T875 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12049 T825 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 12056 T892 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/collection1
[junit4:junit4]   2> 12057 T892 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 12057 T892 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 12057 T892 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 12063 T892 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/collection1/'
[junit4:junit4]   2> 12064 T892 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/collection1/lib/README' to classloader
[junit4:junit4]   2> 12065 T892 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 12126 T892 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 12211 T892 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2>  C62_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:23844_, base_url=http://127.0.0.1:23844}
[junit4:junit4]   2> 12243 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52940/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 12243 T862 C62 P23844 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:23844 START replicas=[http://127.0.0.1:52940/collection1/] nUpdates=100
[junit4:junit4]   2> 12243 T862 C62 P23844 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 12244 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 12244 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 12245 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 12245 T862 C62 P23844 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 12245 T862 C62 P23844 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52940/collection1/. core=collection1
[junit4:junit4]   2> 12245 T862 C62 P23844 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C64 name=collection1 org.apache.solr.core.SolrCore@4561b2fb url=http://127.0.0.1:52940/collection1 node=127.0.0.1:52940_ C64_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52940_, base_url=http://127.0.0.1:52940, leader=true}
[junit4:junit4]   2> 12253 T836 C64 P52940 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 12258 T837 C64 P52940 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 12259 T837 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 12263 T837 C64 P52940 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 12264 T837 C64 P52940 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 12268 T837 C64 P52940 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 12268 T837 C64 P52940 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 12269 T837 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 12270 T837 C64 P52940 oass.SolrIndexSearcher.<init> Opening Searcher@571737cd realtime
[junit4:junit4]   2> 12270 T837 C64 P52940 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 12270 T837 C64 P52940 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4]   2> 12271 T862 C62 P23844 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 12272 T862 C62 P23844 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 12274 T838 C64 P52940 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 12275 T838 C64 P52940 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 12275 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 12276 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 12276 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 12278 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 12279 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index
[junit4:junit4]   2> 12279 T838 C64 P52940 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1 
[junit4:junit4]   2> 12280 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 12281 T862 C62 P23844 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 forceNew:false
[junit4:junit4]   2> 12282 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12283 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a521361; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 12286 T838 C64 P52940 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0 
[junit4:junit4]   2> 12287 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index
[junit4:junit4]   2> 12288 T862 C62 P23844 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 12289 T862 C62 P23844 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130211050313344
[junit4:junit4]   2> 12290 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12290 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12291 T862 C62 P23844 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344
[junit4:junit4]   2> 12294 T862 C62 P23844 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a521361; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 12294 T862 C62 P23844 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 12296 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12296 T862 C62 P23844 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 12296 T862 C62 P23844 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 12296 T862 C62 P23844 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 12297 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344
[junit4:junit4]   2> 12298 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12301 T862 C62 P23844 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a521361; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 12301 T862 C62 P23844 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 12301 T862 C62 P23844 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 12302 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12302 T862 C62 P23844 oass.SolrIndexSearcher.<init> Opening Searcher@5bbe1466 main
[junit4:junit4]   2> 12303 T861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5bbe1466 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 12304 T861 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index
[junit4:junit4]   2> 12304 T862 C62 P23844 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 12308 T862 C62 P23844 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a521361; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6a521361; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 12308 T862 C62 P23844 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 12309 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2
[junit4:junit4]   2> 12309 T862 C62 P23844 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 12309 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index.20130211050313344
[junit4:junit4]   2> 12310 T862 C62 P23844 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty2/index
[junit4:junit4]   2> 12310 T862 C62 P23844 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 12310 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 12310 T862 C62 P23844 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12310 T862 C62 P23844 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12312 T892 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 12317 T862 C62 P23844 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 12324 T892 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 12851 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12852 T826 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:13297_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:13297"}
[junit4:junit4]   2> 12857 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:23844_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:23844"}
[junit4:junit4]   2> 12871 T875 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> 12871 T831 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> 12871 T891 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> 12871 T859 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> 12871 T844 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> 12871 T825 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> 12922 T892 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 12933 T892 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 12938 T892 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 12953 T892 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12958 T892 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 12962 T892 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12964 T892 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 12965 T892 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1360555392755/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/
[junit4:junit4]   2> 12965 T892 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@327124af
[junit4:junit4]   2> 12966 T892 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 12973 T892 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4 forceNew:false
[junit4:junit4]   2> 12974 T892 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 12974 T892 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index/
[junit4:junit4]   2> 12975 T892 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 12977 T892 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index forceNew:false
[junit4:junit4]   2> 13031 T892 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cda761; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 13031 T892 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 13033 T892 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index
[junit4:junit4]   2> 13033 T892 oasc.SolrCore.initWriters created xml: solr.XMLResponseWriter
[junit4:junit4]   2> 13035 T892 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 13036 T892 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe-allfields"
[junit4:junit4]   2> 13036 T892 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 13037 T892 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "uniq-fields"
[junit4:junit4]   2> 13037 T892 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 13038 T892 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 13038 T892 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 13039 T892 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 13040 T892 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 13041 T892 oasc.RequestHandlers.initHandlersFromConfig created dismax: solr.SearchHandler
[junit4:junit4]   2> 13041 T892 oasc.RequestHandlers.initHandlersFromConfig created mock: org.apache.solr.core.MockQuerySenderListenerReqHandler
[junit4:junit4]   2> 13042 T892 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 13043 T892 oasc.RequestHandlers.initHandlersFromConfig created defaults: solr.StandardRequestHandler
[junit4:junit4]   2> 13043 T892 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.StandardRequestHandler
[junit4:junit4]   2> 13044 T892 oasc.RequestHandlers.initHandlersFromConfig created lazy: solr.StandardRequestHandler
[junit4:junit4]   2> 13044 T892 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 13045 T892 oasc.RequestHandlers.initHandlersFromConfig created /terms: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13045 T892 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13046 T892 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13046 T892 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13047 T892 oasc.RequestHandlers.initHandlersFromConfig created spellCheckWithWordbreak_Direct: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13047 T892 oasc.RequestHandlers.initHandlersFromConfig created spellCheckCompRH1: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13048 T892 oasc.RequestHandlers.initHandlersFromConfig created mltrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13048 T892 oasc.RequestHandlers.initHandlersFromConfig created tvrh: org.apache.solr.handler.component.SearchHandler
[junit4:junit4]   2> 13049 T892 oasc.RequestHandlers.initHandlersFromConfig created /mlt: solr.MoreLikeThisHandler
[junit4:junit4]   2> 13049 T892 oasc.RequestHandlers.initHandlersFromConfig created /debug/dump: solr.DumpRequestHandler
[junit4:junit4]   2> 13057 T892 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 13061 T892 oasc.SolrCore.initDeprecatedSupport WARNING solrconfig.xml uses deprecated <admin/gettableFiles>, Please update your config to use the ShowFileRequestHandler.
[junit4:junit4]   2> 13063 T892 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> 13066 T892 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 13068 T892 oass.SolrIndexSearcher.<init> Opening Searcher@4ff7fd0 main
[junit4:junit4]   2> 13069 T892 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 13069 T892 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 13070 T892 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4]   2> 13107 T892 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4]   2> 13164 T895 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4ff7fd0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 13169 T892 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 13169 T892 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 14384 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14384 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:45101_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45101"}
[junit4:junit4]   2> 14385 T826 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 14385 T826 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 14400 T844 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> 14400 T891 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> 14400 T859 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> 14400 T875 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> 14400 T831 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> 14400 T825 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> 15172 T892 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 15172 T892 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45101 collection:collection1 shard:shard1
[junit4:junit4]   2> 15175 T892 oasc.ZkController.register We are http://127.0.0.1:45101/collection1/ and leader is http://127.0.0.1:52940/collection1/
[junit4:junit4]   2> 15176 T892 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45101
[junit4:junit4]   2> 15176 T892 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 15176 T892 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C65 name=collection1 org.apache.solr.core.SolrCore@6fea0da0 url=http://127.0.0.1:45101/collection1 node=127.0.0.1:45101_ C65_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:45101_, base_url=http://127.0.0.1:45101}
[junit4:junit4]   2> 15177 T896 C65 P45101 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 15178 T896 C65 P45101 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 15178 T892 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15178 T896 C65 P45101 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 15178 T896 C65 P45101 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15179 T803 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0
[junit4:junit4]   2> 15179 T803 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 15179 T896 C65 P45101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15179 T803 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15191 T803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15192 T803 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 15193 T803 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 15193 T803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C63_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:13297_, base_url=http://127.0.0.1:13297}
[junit4:junit4]   2> 15691 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52940/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 15691 T878 C63 P13297 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:13297 START replicas=[http://127.0.0.1:52940/collection1/] nUpdates=100
[junit4:junit4]   2> 15692 T878 C63 P13297 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 15692 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 15692 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 15692 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 15692 T878 C63 P13297 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 15692 T878 C63 P13297 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52940/collection1/. core=collection1
[junit4:junit4]   2> 15693 T878 C63 P13297 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 15694 T836 C64 P52940 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 15705 T840 C64 P52940 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 15710 T840 C64 P52940 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 15710 T840 C64 P52940 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 15711 T840 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 15711 T840 C64 P52940 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 15712 T840 C64 P52940 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4]   2> 15712 T878 C63 P13297 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 15713 T878 C63 P13297 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 15715 T838 C64 P52940 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 15716 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4]   2> 15716 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 15716 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 15718 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 15719 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index
[junit4:junit4]   2> 15719 T838 C64 P52940 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1 
[junit4:junit4]   2> 15720 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 15721 T878 C63 P13297 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 forceNew:false
[junit4:junit4]   2> 15722 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15722 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44177e34; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 15725 T838 C64 P52940 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0 
[junit4:junit4]   2> 15726 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index
[junit4:junit4]   2> 15727 T878 C63 P13297 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 15727 T878 C63 P13297 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130211050316784
[junit4:junit4]   2> 15728 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15729 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15729 T878 C63 P13297 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784
[junit4:junit4]   2> 15733 T878 C63 P13297 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44177e34; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 15733 T878 C63 P13297 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 15735 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15735 T878 C63 P13297 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 15735 T878 C63 P13297 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 15736 T878 C63 P13297 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 15737 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784
[junit4:junit4]   2> 15737 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15741 T878 C63 P13297 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44177e34; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 15741 T878 C63 P13297 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4]   2> 15741 T878 C63 P13297 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 15742 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15742 T878 C63 P13297 oass.SolrIndexSearcher.<init> Opening Searcher@7b603010 main
[junit4:junit4]   2> 15743 T877 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7b603010 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   2> 15744 T877 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index
[junit4:junit4]   2> 15744 T878 C63 P13297 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 15747 T878 C63 P13297 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44177e34; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44177e34; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 15747 T878 C63 P13297 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 15749 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3
[junit4:junit4]   2> 15749 T878 C63 P13297 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 15749 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index.20130211050316784
[junit4:junit4]   2> 15749 T878 C63 P13297 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty3/index
[junit4:junit4]   2> 15749 T878 C63 P13297 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 15750 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 15750 T878 C63 P13297 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 15750 T878 C63 P13297 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15757 T878 C63 P13297 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 15905 T826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15906 T826 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":"recovering",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:45101_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:45101"}
[junit4:junit4]   2> 15910 T826 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":"collection1",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:13297_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:13297"}
[junit4:junit4]   2> 15926 T844 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> 15926 T875 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> 15926 T891 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> 15927 T859 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> 15926 T831 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> 15926 T825 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> 16195 T803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17197 T803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C65_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:45101_, base_url=http://127.0.0.1:45101}
[junit4:junit4]   2> 18194 T896 C65 P45101 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52940/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 18194 T896 C65 P45101 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45101 START replicas=[http://127.0.0.1:52940/collection1/] nUpdates=100
[junit4:junit4]   2> 18195 T896 C65 P45101 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 18195 T896 C65 P45101 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 18195 T896 C65 P45101 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 18195 T896 C65 P45101 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 18195 T896 C65 P45101 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 18195 T896 C65 P45101 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52940/collection1/. core=collection1
[junit4:junit4]   2> 18196 T896 C65 P45101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 18197 T836 C64 P52940 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 18200 T803 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18210 T834 C64 P52940 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 18216 T834 C64 P52940 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@61db327f; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 18217 T834 C64 P52940 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 18218 T834 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 18218 T834 C64 P52940 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 18218 T834 C64 P52940 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4]   2> 18219 T896 C65 P45101 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 18220 T896 C65 P45101 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 18222 T838 C64 P52940 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 18223 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4]   2> 18223 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 18223 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 18226 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1
[junit4:junit4]   2> 18227 T838 C64 P52940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty1/index
[junit4:junit4]   2> 18227 T838 C64 P52940 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1 
[junit4:junit4]   2> 18228 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 18229 T896 C65 P45101 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292 forceNew:false
[junit4:junit4]   2> 18230 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18231 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Starting download to RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f0c0cb9; maxCacheMB=48.0 maxMergeSizeMB=4.0)) fullCopy=true
[junit4:junit4]   2> 18234 T838 C64 P52940 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0 
[junit4:junit4]   2> 18236 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index
[junit4:junit4]   2> 18236 T896 C65 P45101 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 18237 T896 C65 P45101 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130211050319292
[junit4:junit4]   2> 18238 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18238 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18239 T896 C65 P45101 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292
[junit4:junit4]   2> 18242 T896 C65 P45101 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f0c0cb9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 18243 T896 C65 P45101 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 18244 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18244 T896 C65 P45101 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 18245 T896 C65 P45101 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 18245 T896 C65 P45101 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4]   2> 18246 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292
[junit4:junit4]   2> 18246 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18250 T896 C65 P45101 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-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index.20130211050319292 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f0c0cb9; maxCacheMB=48.0 maxMergeSizeMB=4.0)),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4]   2> 18250 T896 C65 P45101 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4]   2> 18250 T896 C65 P45101 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 18251 T896 C65 P45101 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 18251 T896 C65 P45101 oass.SolrIndexSearcher.<init> Opening Searcher@563698b4 main
[junit4:junit4]   2> 18252 T895 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@563698b4 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4]   2> 18253 T895 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index
[junit4:junit4]   2> 18253 T896 C65 P45101 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4]   2> 18291 T896 C65 P45101 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=RateLimitedDirectoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOF

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

ctoryWrapper(NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cda761; maxCacheMB=48.0 maxMergeSizeMB=4.0))
[junit4:junit4]   2> 892604 T803 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index
[junit4:junit4]   2> 892604 T803 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4/index
[junit4:junit4]   2> 892604 T803 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 892605 T803 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1360555381068/jetty4
[junit4:junit4]   2> 904891 T891 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 904891 T803 oaz.ZooKeeper.close Session: 0x13cc76b9154000c closed
[junit4:junit4]   2> 904893 T803 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 905114 T803 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4]   1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=2B34A65A95360876 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_AE -Dtests.timezone=Europe/Ljubljana -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE  905s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: 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:23844/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@da25a88c, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@c661f225]
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([2B34A65A95360876:AAD22842E269684A]:0)
[junit4:junit4]    > 	at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4]    > 	at org.junit.Assert.assertTrue(Assert.java:43)
[junit4:junit4]    > 	at org.junit.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:616)
[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:679)
[junit4:junit4]   2> 905254 T803 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=ar_AE, timezone=Europe/Ljubljana
[junit4:junit4]   2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=216578216,total=471924736
[junit4:junit4]   2> NOTE: All tests run in this JVM: [OverseerCollectionProcessorTest, TestPseudoReturnFields, CopyFieldTest, TestSolrIndexConfig, IndexBasedSpellCheckerTest, SampleTest, UpdateRequestProcessorFactoryTest, TestCoreContainer, CircularListTest, RequestHandlersTest, DistributedSpellCheckComponentTest, TestPerFieldSimilarity, JsonLoaderTest, BasicDistributedZkTest, FastVectorHighlighterTest, SolrPluginUtilsTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 905.28s, 1 test, 1 failure <<< FAILURES!

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

Total time: 53 minutes 36 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