You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/02/17 14:41:22 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java6 - Build # 15927 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java6/15927/
1 tests failed.
FAILED: 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:12935/pprdz/t/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@8a2320f0, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@b1d6d766]
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:12935/pprdz/t/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@8a2320f0, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@b1d6d766]
at __randomizedtesting.SeedInfo.seed([8720C825A881C325:6C6463DDFDEA319]: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 8804 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T2434 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /pprdz/t
[junit4:junit4] 2> 4 T2434 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-1361108308242
[junit4:junit4] 2> 5 T2434 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 6 T2435 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 9 T2435 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 9 T2435 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T2435 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 9 T2435 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 10 T2435 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-1361108308241/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 107 T2434 oasc.ZkTestServer.run start zk server on port:12914
[junit4:junit4] 2> 107 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6c932d8a
[junit4:junit4] 2> 108 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T2440 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 109 T2440 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 109 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12915
[junit4:junit4] 2> 109 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12915
[junit4:junit4] 2> 110 T2438 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 112 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180000 with negotiated timeout 10000 for client /140.211.11.196:12915
[junit4:junit4] 2> 112 T2440 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180000, negotiated timeout = 10000
[junit4:junit4] 2> 113 T2441 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c932d8a name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 113 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 113 T2434 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 117 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180000
[junit4:junit4] 2> 118 T2441 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 118 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12915 which had sessionid 0x13ce86091180000
[junit4:junit4] 2> 118 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180000 closed
[junit4:junit4] 2> 119 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ba9a552
[junit4:junit4] 2> 119 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 120 T2442 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 120 T2442 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 120 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12916
[junit4:junit4] 2> 121 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12916
[junit4:junit4] 2> 122 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180001 with negotiated timeout 10000 for client /140.211.11.196:12916
[junit4:junit4] 2> 122 T2442 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180001, negotiated timeout = 10000
[junit4:junit4] 2> 122 T2443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ba9a552 name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 122 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 123 T2434 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 127 T2434 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 137 T2434 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 140 T2434 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 143 T2434 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-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 144 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 159 T2434 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> 160 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 264 T2434 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> 265 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 268 T2434 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> 269 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 279 T2434 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> 280 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 283 T2434 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> 284 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 287 T2434 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> 288 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 291 T2434 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> 291 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 294 T2434 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> 295 T2434 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 298 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180001
[junit4:junit4] 2> 304 T2443 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 304 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12916 which had sessionid 0x13ce86091180001
[junit4:junit4] 2> 304 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180001 closed
[junit4:junit4] 2> 466 T2434 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 471 T2434 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12917
[junit4:junit4] 2> 472 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 472 T2434 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 473 T2434 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-1361108308542
[junit4:junit4] 2> 473 T2434 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-1361108308542/solr.xml
[junit4:junit4] 2> 474 T2434 oasc.CoreContainer.<init> New CoreContainer 1257550134
[junit4:junit4] 2> 474 T2434 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-1361108308542/'
[junit4:junit4] 2> 475 T2434 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-1361108308542/'
[junit4:junit4] 2> 521 T2434 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 522 T2434 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 522 T2434 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 523 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 523 T2434 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 523 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 524 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 524 T2434 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 525 T2434 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 525 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 546 T2434 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 565 T2434 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:12914/solr
[junit4:junit4] 2> 566 T2434 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 566 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@d811999
[junit4:junit4] 2> 567 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 568 T2453 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 568 T2453 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 568 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12918
[junit4:junit4] 2> 569 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12918
[junit4:junit4] 2> 572 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180002 with negotiated timeout 20000 for client /140.211.11.196:12918
[junit4:junit4] 2> 572 T2453 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180002, negotiated timeout = 20000
[junit4:junit4] 2> 572 T2454 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d811999 name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 572 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 574 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180002
[junit4:junit4] 2> 584 T2454 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 584 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12918 which had sessionid 0x13ce86091180002
[junit4:junit4] 2> 584 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180002 closed
[junit4:junit4] 2> 584 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 595 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@25de6aae
[junit4:junit4] 2> 596 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 596 T2455 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 597 T2455 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 597 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12919
[junit4:junit4] 2> 597 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12919
[junit4:junit4] 2> 598 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180003 with negotiated timeout 20000 for client /140.211.11.196:12919
[junit4:junit4] 2> 599 T2455 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180003, negotiated timeout = 20000
[junit4:junit4] 2> 599 T2456 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25de6aae name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 599 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 602 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 603 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 606 T2434 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12917_pprdz%2Ft
[junit4:junit4] 2> 606 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:12917_pprdz%2Ft Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:12917_pprdz%2Ft
[junit4:junit4] 2> 607 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12917_pprdz%2Ft
[junit4:junit4] 2> 611 T2434 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 623 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 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> 624 T2434 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 633 T2434 oasc.Overseer.start Overseer (id=89201594089340931-127.0.0.1:12917_pprdz%2Ft-n_0000000000) starting
[junit4:junit4] 2> 633 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 635 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 645 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 646 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 656 T2458 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 657 T2434 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 660 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 662 T2457 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 666 T2459 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-1361108308542/collection1
[junit4:junit4] 2> 667 T2459 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 667 T2459 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 667 T2459 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 669 T2459 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-1361108308542/collection1/'
[junit4:junit4] 2> 670 T2459 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-1361108308542/collection1/lib/README' to classloader
[junit4:junit4] 2> 670 T2459 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-1361108308542/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 717 T2459 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 777 T2459 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 878 T2459 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 884 T2459 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1508 T2459 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1520 T2459 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1525 T2459 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1538 T2459 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1543 T2459 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1547 T2459 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1548 T2459 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1549 T2459 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-1361108308542/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361108308241/control/data/
[junit4:junit4] 2> 1550 T2459 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@239a0feb
[junit4:junit4] 2> 1550 T2459 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1551 T2459 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-1361108308241/control/data forceNew:false
[junit4:junit4] 2> 1552 T2459 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-1361108308241/control/data
[junit4:junit4] 2> 1552 T2459 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/control/data/index/
[junit4:junit4] 2> 1553 T2459 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361108308241/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1554 T2459 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-1361108308241/control/data/index forceNew:false
[junit4:junit4] 2> 1568 T2459 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ed676f5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1568 T2459 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1570 T2459 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-1361108308241/control/data/index
[junit4:junit4] 2> 1571 T2459 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1571 T2459 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1572 T2459 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1573 T2459 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1573 T2459 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1573 T2459 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1573 T2459 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1574 T2459 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1574 T2459 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1581 T2459 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1591 T2459 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-1361108308241/control/data
[junit4:junit4] 2> 1593 T2459 oass.SolrIndexSearcher.<init> Opening Searcher@43bb93ab main
[junit4:junit4] 2> 1594 T2459 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1594 T2459 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1597 T2460 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43bb93ab main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1598 T2459 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1598 T2459 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1599 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2166 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2166 T2457 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:12917_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12917/pprdz/t"}
[junit4:junit4] 2> 2167 T2457 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2167 T2457 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2167 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2184 T2456 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> 2612 T2459 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2612 T2459 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12917/pprdz/t collection:control_collection shard:shard1
[junit4:junit4] 2> 2613 T2459 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2745 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2775 T2459 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2776 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2810 T2459 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2811 T2459 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2811 T2459 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12917/pprdz/t/collection1/
[junit4:junit4] 2> 2811 T2459 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2811 T2459 oasc.SyncStrategy.syncToMe http://127.0.0.1:12917/pprdz/t/collection1/ has no replicas
[junit4:junit4] 2> 2811 T2459 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:12917/pprdz/t/collection1/
[junit4:junit4] 2> 2812 T2459 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2816 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3694 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3712 T2456 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> 3736 T2459 oasc.ZkController.register We are http://127.0.0.1:12917/pprdz/t/collection1/ and leader is http://127.0.0.1:12917/pprdz/t/collection1/
[junit4:junit4] 2> 3736 T2459 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12917/pprdz/t
[junit4:junit4] 2> 3736 T2459 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3736 T2459 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3737 T2459 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3738 T2459 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3739 T2434 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> 3740 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3740 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3755 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3756 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@43fc0c1
[junit4:junit4] 2> 3757 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3758 T2461 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3758 T2461 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 3758 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12927
[junit4:junit4] 2> 3759 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12927
[junit4:junit4] 2> 3760 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180004 with negotiated timeout 10000 for client /140.211.11.196:12927
[junit4:junit4] 2> 3760 T2461 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180004, negotiated timeout = 10000
[junit4:junit4] 2> 3760 T2462 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43fc0c1 name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3761 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3762 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3764 T2434 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3927 T2434 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3930 T2434 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12928
[junit4:junit4] 2> 3930 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3931 T2434 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3931 T2434 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-1361108312001
[junit4:junit4] 2> 3932 T2434 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-1361108312001/solr.xml
[junit4:junit4] 2> 3932 T2434 oasc.CoreContainer.<init> New CoreContainer 227068829
[junit4:junit4] 2> 3933 T2434 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-1361108312001/'
[junit4:junit4] 2> 3933 T2434 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-1361108312001/'
[junit4:junit4] 2> 3979 T2434 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3979 T2434 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3980 T2434 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3980 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3981 T2434 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3981 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3982 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3982 T2434 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3983 T2434 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3983 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4003 T2434 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4022 T2434 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:12914/solr
[junit4:junit4] 2> 4023 T2434 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4023 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@42ef0130
[junit4:junit4] 2> 4024 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4025 T2472 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4025 T2472 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 4026 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12929
[junit4:junit4] 2> 4026 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12929
[junit4:junit4] 2> 4028 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180005 with negotiated timeout 20000 for client /140.211.11.196:12929
[junit4:junit4] 2> 4028 T2472 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180005, negotiated timeout = 20000
[junit4:junit4] 2> 4028 T2473 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42ef0130 name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4028 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4030 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180005
[junit4:junit4] 2> 4036 T2473 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4036 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12929 which had sessionid 0x13ce86091180005
[junit4:junit4] 2> 4036 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180005 closed
[junit4:junit4] 2> 4036 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4047 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2f381304
[junit4:junit4] 2> 4048 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4048 T2474 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4049 T2474 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 4049 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12930
[junit4:junit4] 2> 4049 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12930
[junit4:junit4] 2> 4051 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180006 with negotiated timeout 20000 for client /140.211.11.196:12930
[junit4:junit4] 2> 4051 T2474 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180006, negotiated timeout = 20000
[junit4:junit4] 2> 4051 T2475 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f381304 name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4051 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4052 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4054 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4062 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5065 T2434 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12928_pprdz%2Ft
[junit4:junit4] 2> 5066 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:12928_pprdz%2Ft Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:12928_pprdz%2Ft
[junit4:junit4] 2> 5067 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12928_pprdz%2Ft
[junit4:junit4] 2> 5071 T2475 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5071 T2456 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5071 T2462 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5071 T2456 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> 5079 T2476 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-1361108312001/collection1
[junit4:junit4] 2> 5079 T2476 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5080 T2476 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5080 T2476 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5082 T2476 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-1361108312001/collection1/'
[junit4:junit4] 2> 5083 T2476 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-1361108312001/collection1/lib/README' to classloader
[junit4:junit4] 2> 5083 T2476 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-1361108312001/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5130 T2476 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 5189 T2476 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5224 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5225 T2457 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:12917_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12917/pprdz/t"}
[junit4:junit4] 2> 5247 T2456 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> 5248 T2462 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> 5290 T2476 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5290 T2475 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> 5296 T2476 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5919 T2476 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5931 T2476 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5935 T2476 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5949 T2476 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5953 T2476 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5958 T2476 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5959 T2476 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5960 T2476 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-1361108312001/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty1/
[junit4:junit4] 2> 5960 T2476 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@239a0feb
[junit4:junit4] 2> 5961 T2476 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 5962 T2476 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-1361108308241/jetty1 forceNew:false
[junit4:junit4] 2> 5963 T2476 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-1361108308241/jetty1
[junit4:junit4] 2> 5963 T2476 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty1/index/
[junit4:junit4] 2> 5964 T2476 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5965 T2476 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-1361108308241/jetty1/index forceNew:false
[junit4:junit4] 2> 5971 T2476 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5972 T2476 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5973 T2476 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-1361108308241/jetty1/index
[junit4:junit4] 2> 5974 T2476 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5975 T2476 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5975 T2476 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5976 T2476 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5976 T2476 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5977 T2476 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5977 T2476 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5977 T2476 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5978 T2476 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 5985 T2476 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 5991 T2476 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-1361108308241/jetty1
[junit4:junit4] 2> 5993 T2476 oass.SolrIndexSearcher.<init> Opening Searcher@43262b04 main
[junit4:junit4] 2> 5994 T2476 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 5994 T2476 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 5998 T2477 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43262b04 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 5999 T2476 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 5999 T2476 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6753 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6753 T2457 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:12928_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12928/pprdz/t"}
[junit4:junit4] 2> 6754 T2457 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6754 T2457 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6773 T2475 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> 6773 T2456 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> 6773 T2462 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> 7002 T2476 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7002 T2476 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12928/pprdz/t collection:collection1 shard:shard1
[junit4:junit4] 2> 7003 T2476 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7019 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:delete cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7020 T2476 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7021 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7031 T2476 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7031 T2476 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7031 T2476 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 7031 T2476 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7031 T2476 oasc.SyncStrategy.syncToMe http://127.0.0.1:12928/pprdz/t/collection1/ has no replicas
[junit4:junit4] 2> 7032 T2476 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 7032 T2476 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7037 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8278 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8322 T2456 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> 8322 T2462 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> 8322 T2475 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> 8373 T2476 oasc.ZkController.register We are http://127.0.0.1:12928/pprdz/t/collection1/ and leader is http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 8373 T2476 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12928/pprdz/t
[junit4:junit4] 2> 8373 T2476 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8373 T2476 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8374 T2476 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8376 T2476 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8377 T2434 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> 8378 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8378 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8553 T2434 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8556 T2434 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12935
[junit4:junit4] 2> 8557 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8557 T2434 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8557 T2434 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-1361108316628
[junit4:junit4] 2> 8558 T2434 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-1361108316628/solr.xml
[junit4:junit4] 2> 8558 T2434 oasc.CoreContainer.<init> New CoreContainer 417456897
[junit4:junit4] 2> 8559 T2434 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-1361108316628/'
[junit4:junit4] 2> 8559 T2434 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-1361108316628/'
[junit4:junit4] 2> 8605 T2434 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8606 T2434 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8606 T2434 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8606 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8612 T2434 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8612 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8613 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8613 T2434 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8614 T2434 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8614 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8635 T2434 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8653 T2434 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:12914/solr
[junit4:junit4] 2> 8654 T2434 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8654 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@4e14e227
[junit4:junit4] 2> 8656 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8656 T2487 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8656 T2487 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 8657 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12936
[junit4:junit4] 2> 8657 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12936
[junit4:junit4] 2> 8663 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180007 with negotiated timeout 20000 for client /140.211.11.196:12936
[junit4:junit4] 2> 8663 T2487 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180007, negotiated timeout = 20000
[junit4:junit4] 2> 8663 T2488 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e14e227 name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8663 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8665 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180007
[junit4:junit4] 2> 8666 T2488 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8666 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12936 which had sessionid 0x13ce86091180007
[junit4:junit4] 2> 8666 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180007 closed
[junit4:junit4] 2> 8667 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8677 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1ac8195d
[junit4:junit4] 2> 8678 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8679 T2489 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8679 T2489 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 8679 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12937
[junit4:junit4] 2> 8680 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12937
[junit4:junit4] 2> 8681 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180008 with negotiated timeout 20000 for client /140.211.11.196:12937
[junit4:junit4] 2> 8681 T2489 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180008, negotiated timeout = 20000
[junit4:junit4] 2> 8682 T2490 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ac8195d name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8682 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8683 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8684 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8686 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9689 T2434 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12935_pprdz%2Ft
[junit4:junit4] 2> 9690 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce86091180008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:12935_pprdz%2Ft Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:12935_pprdz%2Ft
[junit4:junit4] 2> 9717 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12935_pprdz%2Ft
[junit4:junit4] 2> 9721 T2462 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9721 T2456 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9721 T2475 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9721 T2462 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> 9721 T2490 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9722 T2475 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> 9721 T2456 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> 9730 T2491 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-1361108316628/collection1
[junit4:junit4] 2> 9730 T2491 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9730 T2491 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9731 T2491 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9732 T2491 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-1361108316628/collection1/'
[junit4:junit4] 2> 9733 T2491 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-1361108316628/collection1/lib/README' to classloader
[junit4:junit4] 2> 9734 T2491 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-1361108316628/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9780 T2491 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9835 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9835 T2457 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:12928_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12928/pprdz/t"}
[junit4:junit4] 2> 9838 T2491 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9848 T2456 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> 9848 T2462 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> 9848 T2475 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> 9939 T2491 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9939 T2490 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> 9945 T2491 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10567 T2491 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10577 T2491 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10580 T2491 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10592 T2491 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10595 T2491 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10598 T2491 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10599 T2491 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10600 T2491 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-1361108316628/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty2/
[junit4:junit4] 2> 10601 T2491 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@239a0feb
[junit4:junit4] 2> 10601 T2491 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 10602 T2491 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-1361108308241/jetty2 forceNew:false
[junit4:junit4] 2> 10602 T2491 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-1361108308241/jetty2
[junit4:junit4] 2> 10602 T2491 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty2/index/
[junit4:junit4] 2> 10603 T2491 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10603 T2491 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-1361108308241/jetty2/index forceNew:false
[junit4:junit4] 2> 10608 T2491 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@654514a5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10608 T2491 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10608 T2491 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-1361108308241/jetty2/index
[junit4:junit4] 2> 10610 T2491 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10610 T2491 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10610 T2491 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10611 T2491 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10611 T2491 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10611 T2491 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10611 T2491 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10612 T2491 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10612 T2491 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10617 T2491 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10621 T2491 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-1361108308241/jetty2
[junit4:junit4] 2> 10622 T2491 oass.SolrIndexSearcher.<init> Opening Searcher@5575c6bc main
[junit4:junit4] 2> 10622 T2491 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10622 T2491 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10626 T2492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5575c6bc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10626 T2491 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10627 T2491 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11353 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11354 T2457 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:12935_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12935/pprdz/t"}
[junit4:junit4] 2> 11354 T2457 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11354 T2457 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11359 T2456 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> 11359 T2462 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> 11359 T2475 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> 11359 T2490 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> 11629 T2491 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11629 T2491 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12935/pprdz/t collection:collection1 shard:shard1
[junit4:junit4] 2> 11632 T2491 oasc.ZkController.register We are http://127.0.0.1:12935/pprdz/t/collection1/ and leader is http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 11632 T2491 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12935/pprdz/t
[junit4:junit4] 2> 11633 T2491 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11633 T2491 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C185 name=collection1 org.apache.solr.core.SolrCore@24a91ec2 url=http://127.0.0.1:12935/pprdz/t/collection1 node=127.0.0.1:12935_pprdz%2Ft C185_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:12935_pprdz%2Ft, base_url=http://127.0.0.1:12935/pprdz/t}
[junit4:junit4] 2> 11634 T2493 C185 P12935 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11634 T2491 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11635 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11635 T2493 C185 P12935 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11635 T2493 C185 P12935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11635 T2434 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> 11636 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11636 T2493 C185 P12935 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11636 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11819 T2434 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11821 T2434 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58667
[junit4:junit4] 2> 11822 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11823 T2434 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11823 T2434 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-1361108319895
[junit4:junit4] 2> 11823 T2434 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-1361108319895/solr.xml
[junit4:junit4] 2> 11824 T2434 oasc.CoreContainer.<init> New CoreContainer 302853808
[junit4:junit4] 2> 11824 T2434 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-1361108319895/'
[junit4:junit4] 2> 11825 T2434 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-1361108319895/'
[junit4:junit4] 2> 11874 T2434 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 11874 T2434 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11875 T2434 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11875 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11876 T2434 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11876 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11877 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11877 T2434 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11877 T2434 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11878 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11898 T2434 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11917 T2434 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:12914/solr
[junit4:junit4] 2> 11917 T2434 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11918 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@a2825c6
[junit4:junit4] 2> 11919 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11919 T2503 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11920 T2503 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 11920 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:12833
[junit4:junit4] 2> 11920 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:12833
[junit4:junit4] 2> 11922 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce86091180009 with negotiated timeout 20000 for client /140.211.11.196:12833
[junit4:junit4] 2> 11922 T2503 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce86091180009, negotiated timeout = 20000
[junit4:junit4] 2> 11923 T2504 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a2825c6 name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11923 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11924 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce86091180009
[junit4:junit4] 2> 11936 T2504 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11936 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:12833 which had sessionid 0x13ce86091180009
[junit4:junit4] 2> 11936 T2434 oaz.ZooKeeper.close Session: 0x13ce86091180009 closed
[junit4:junit4] 2> 11936 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 11947 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7500cb73
[junit4:junit4] 2> 11948 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11948 T2505 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11949 T2505 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 11949 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:45638
[junit4:junit4] 2> 11949 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:45638
[junit4:junit4] 2> 11951 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce8609118000a with negotiated timeout 20000 for client /140.211.11.196:45638
[junit4:junit4] 2> 11951 T2505 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce8609118000a, negotiated timeout = 20000
[junit4:junit4] 2> 11951 T2506 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7500cb73 name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11951 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11952 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11954 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11956 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12873 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12873 T2457 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:12935_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12935/pprdz/t"}
[junit4:junit4] 2> 12889 T2456 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> 12889 T2506 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> 12889 T2475 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> 12889 T2462 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> 12889 T2490 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> 12958 T2434 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58667_pprdz%2Ft
[junit4:junit4] 2> 12959 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000a type:delete cxid:0xb zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:58667_pprdz%2Ft Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:58667_pprdz%2Ft
[junit4:junit4] 2> 12960 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58667_pprdz%2Ft
[junit4:junit4] 2> 12962 T2506 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> 12963 T2456 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12963 T2462 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12963 T2490 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12963 T2456 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> 12963 T2462 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> 12963 T2490 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> 12963 T2475 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12964 T2475 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> 12965 T2506 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12972 T2507 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-1361108319895/collection1
[junit4:junit4] 2> 12972 T2507 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 12973 T2507 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 12973 T2507 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 12975 T2507 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-1361108319895/collection1/'
[junit4:junit4] 2> 12976 T2507 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-1361108319895/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 12976 T2507 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-1361108319895/collection1/lib/README' to classloader
[junit4:junit4] 2> 13023 T2507 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 13082 T2507 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13182 T2507 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13188 T2507 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13911 T2507 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13928 T2507 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13932 T2507 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13946 T2507 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13950 T2507 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13955 T2507 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13956 T2507 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13957 T2507 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-1361108319895/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty3/
[junit4:junit4] 2> 13958 T2507 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@239a0feb
[junit4:junit4] 2> 13958 T2507 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 13959 T2507 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-1361108308241/jetty3 forceNew:false
[junit4:junit4] 2> 13959 T2507 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-1361108308241/jetty3
[junit4:junit4] 2> 13960 T2507 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty3/index/
[junit4:junit4] 2> 13960 T2507 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13961 T2507 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-1361108308241/jetty3/index forceNew:false
[junit4:junit4] 2> 13967 T2507 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5f900b7d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13967 T2507 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13968 T2507 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-1361108308241/jetty3/index
[junit4:junit4] 2> 13970 T2507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13970 T2507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13971 T2507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13971 T2507 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13972 T2507 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13972 T2507 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13972 T2507 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13973 T2507 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13973 T2507 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13980 T2507 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13986 T2507 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-1361108308241/jetty3
[junit4:junit4] 2> 13988 T2507 oass.SolrIndexSearcher.<init> Opening Searcher@4ee7c70c main
[junit4:junit4] 2> 13988 T2507 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13989 T2507 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13993 T2508 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4ee7c70c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13994 T2507 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13994 T2507 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14395 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14396 T2457 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:58667_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58667/pprdz/t"}
[junit4:junit4] 2> 14396 T2457 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 14397 T2457 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14409 T2456 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> 14410 T2462 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> 14410 T2475 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> 14410 T2490 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> 14410 T2506 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> 14996 T2507 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14996 T2507 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58667/pprdz/t collection:collection1 shard:shard1
[junit4:junit4] 2> 15028 T2507 oasc.ZkController.register We are http://127.0.0.1:58667/pprdz/t/collection1/ and leader is http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 15028 T2507 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58667/pprdz/t
[junit4:junit4] 2> 15029 T2507 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 15029 T2507 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C186 name=collection1 org.apache.solr.core.SolrCore@5e02249b url=http://127.0.0.1:58667/pprdz/t/collection1 node=127.0.0.1:58667_pprdz%2Ft C186_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58667_pprdz%2Ft, base_url=http://127.0.0.1:58667/pprdz/t}
[junit4:junit4] 2> 15030 T2509 C186 P58667 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 15030 T2507 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15031 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 15031 T2509 C186 P58667 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 15031 T2509 C186 P58667 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15032 T2434 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> 15032 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 15033 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15035 T2509 C186 P58667 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15214 T2434 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 15217 T2434 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57329
[junit4:junit4] 2> 15218 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 15218 T2434 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 15219 T2434 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-1361108323290
[junit4:junit4] 2> 15219 T2434 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-1361108323290/solr.xml
[junit4:junit4] 2> 15220 T2434 oasc.CoreContainer.<init> New CoreContainer 435561071
[junit4:junit4] 2> 15220 T2434 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-1361108323290/'
[junit4:junit4] 2> 15221 T2434 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-1361108323290/'
[junit4:junit4] 2> 15266 T2434 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 15266 T2434 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 15266 T2434 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 15267 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 15267 T2434 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 15268 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 15268 T2434 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 15269 T2434 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 15269 T2434 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 15270 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15288 T2434 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 15307 T2434 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:12914/solr
[junit4:junit4] 2> 15307 T2434 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15308 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@70b7c842
[junit4:junit4] 2> 15309 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15309 T2519 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15310 T2519 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 15310 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:57330
[junit4:junit4] 2> 15310 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:57330
[junit4:junit4] 2> 15312 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce8609118000b with negotiated timeout 20000 for client /140.211.11.196:57330
[junit4:junit4] 2> 15312 T2519 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce8609118000b, negotiated timeout = 20000
[junit4:junit4] 2> 15312 T2520 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70b7c842 name:ZooKeeperConnection Watcher:127.0.0.1:12914 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15313 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15314 T2439 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13ce8609118000b
[junit4:junit4] 2> 15315 T2520 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15315 T2436 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:57330 which had sessionid 0x13ce8609118000b
[junit4:junit4] 2> 15315 T2434 oaz.ZooKeeper.close Session: 0x13ce8609118000b closed
[junit4:junit4] 2> 15316 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 15325 T2434 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:12914/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@280b8f4a
[junit4:junit4] 2> 15325 T2434 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15326 T2521 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:12914. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15326 T2521 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:12914, initiating session
[junit4:junit4] 2> 15326 T2436 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:57331
[junit4:junit4] 2> 15327 T2436 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:57331
[junit4:junit4] 2> 15328 T2438 oazs.ZooKeeperServer.finishSessionInit Established session 0x13ce8609118000c with negotiated timeout 20000 for client /140.211.11.196:57331
[junit4:junit4] 2> 15328 T2521 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:12914, sessionid = 0x13ce8609118000c, negotiated timeout = 20000
[junit4:junit4] 2> 15328 T2522 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@280b8f4a name:ZooKeeperConnection Watcher:127.0.0.1:12914/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15329 T2434 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15330 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000c type:create cxid:0x1 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15331 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000c type:create cxid:0x2 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15337 T2434 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C185_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:12935_pprdz%2Ft, base_url=http://127.0.0.1:12935/pprdz/t}
[junit4:junit4] 2> 15662 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:12928/pprdz/t/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15662 T2493 C185 P12935 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12935/pprdz/t START replicas=[http://127.0.0.1:12928/pprdz/t/collection1/] nUpdates=100
[junit4:junit4] 2> 15662 T2493 C185 P12935 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15663 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15663 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15663 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15663 T2493 C185 P12935 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15663 T2493 C185 P12935 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:12928/pprdz/t/collection1/. core=collection1
[junit4:junit4] 2> 15664 T2493 C185 P12935 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C187 name=collection1 org.apache.solr.core.SolrCore@1d340d0b url=http://127.0.0.1:12928/pprdz/t/collection1 node=127.0.0.1:12928_pprdz%2Ft C187_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12928_pprdz%2Ft, base_url=http://127.0.0.1:12928/pprdz/t, leader=true}
[junit4:junit4] 2> 15669 T2467 C187 P12928 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 15673 T2468 C187 P12928 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15675 T2468 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 15678 T2468 C187 P12928 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15679 T2468 C187 P12928 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15683 T2468 C187 P12928 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15683 T2468 C187 P12928 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15684 T2468 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 15685 T2468 C187 P12928 oass.SolrIndexSearcher.<init> Opening Searcher@9396752 realtime
[junit4:junit4] 2> 15685 T2468 C187 P12928 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15686 T2468 C187 P12928 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 15686 T2493 C185 P12935 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15687 T2493 C185 P12935 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15688 T2469 C187 P12928 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15689 T2469 C187 P12928 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 15689 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15690 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15690 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15692 T2469 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 15693 T2469 C187 P12928 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-1361108308241/jetty1/index
[junit4:junit4] 2> 15693 T2469 C187 P12928 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 15694 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15695 T2493 C185 P12935 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-1361108308241/jetty2/index.20130218003843931 forceNew:false
[junit4:junit4] 2> 15695 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15696 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Starting download to 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-1361108308241/jetty2/index.20130218003843931 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a337832; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 15699 T2469 C187 P12928 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 15700 T2493 C185 P12935 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-1361108308241/jetty2/index
[junit4:junit4] 2> 15701 T2493 C185 P12935 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15701 T2493 C185 P12935 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130218003843931
[junit4:junit4] 2> 15702 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15703 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15703 T2493 C185 P12935 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty2/index.20130218003843931
[junit4:junit4] 2> 15706 T2493 C185 P12935 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty2/index.20130218003843931 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a337832; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15707 T2493 C185 P12935 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15708 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15708 T2493 C185 P12935 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15708 T2493 C185 P12935 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15708 T2493 C185 P12935 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15709 T2493 C185 P12935 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-1361108308241/jetty2/index.20130218003843931
[junit4:junit4] 2> 15710 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15713 T2493 C185 P12935 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty2/index.20130218003843931 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a337832; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15713 T2493 C185 P12935 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15713 T2493 C185 P12935 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15714 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15714 T2493 C185 P12935 oass.SolrIndexSearcher.<init> Opening Searcher@191c8373 main
[junit4:junit4] 2> 15715 T2492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@191c8373 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15715 T2492 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-1361108308241/jetty2/index
[junit4:junit4] 2> 15716 T2493 C185 P12935 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15719 T2493 C185 P12935 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty2/index.20130218003843931 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a337832; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty2/index.20130218003843931 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a337832; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15719 T2493 C185 P12935 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15720 T2493 C185 P12935 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-1361108308241/jetty2
[junit4:junit4] 2> 15720 T2493 C185 P12935 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15721 T2493 C185 P12935 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-1361108308241/jetty2/index.20130218003843931
[junit4:junit4] 2> 15721 T2493 C185 P12935 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-1361108308241/jetty2/index
[junit4:junit4] 2> 15721 T2493 C185 P12935 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15721 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15721 T2493 C185 P12935 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15721 T2493 C185 P12935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15728 T2493 C185 P12935 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15914 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15915 T2457 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:58667_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58667/pprdz/t"}
[junit4:junit4] 2> 15919 T2457 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:12935_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12935/pprdz/t"}
[junit4:junit4] 2> 15931 T2456 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> 15931 T2506 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> 15931 T2490 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> 15931 T2462 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> 15931 T2475 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> 15931 T2522 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> 16339 T2434 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57329_pprdz%2Ft
[junit4:junit4] 2> 16340 T2439 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13ce8609118000c type:delete cxid:0xb zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:57329_pprdz%2Ft Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:57329_pprdz%2Ft
[junit4:junit4] 2> 16341 T2434 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57329_pprdz%2Ft
[junit4:junit4] 2> 16343 T2522 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> 16343 T2506 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> 16343 T2456 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16343 T2462 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16344 T2475 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16344 T2456 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> 16344 T2475 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> 16344 T2490 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16344 T2462 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> 16345 T2490 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> 16345 T2522 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16345 T2506 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16362 T2525 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-1361108323290/collection1
[junit4:junit4] 2> 16362 T2525 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 16363 T2525 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 16363 T2525 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 16364 T2525 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-1361108323290/collection1/'
[junit4:junit4] 2> 16365 T2525 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-1361108323290/collection1/lib/README' to classloader
[junit4:junit4] 2> 16366 T2525 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-1361108323290/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 16430 T2525 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 16488 T2525 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 16589 T2525 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 16595 T2525 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 17201 T2525 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 17212 T2525 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 17216 T2525 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 17229 T2525 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17233 T2525 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17237 T2525 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17239 T2525 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17240 T2525 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-1361108323290/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/
[junit4:junit4] 2> 17240 T2525 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@239a0feb
[junit4:junit4] 2> 17241 T2525 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 17241 T2525 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-1361108308241/jetty4 forceNew:false
[junit4:junit4] 2> 17242 T2525 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-1361108308241/jetty4
[junit4:junit4] 2> 17242 T2525 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/index/
[junit4:junit4] 2> 17243 T2525 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 17243 T2525 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-1361108308241/jetty4/index forceNew:false
[junit4:junit4] 2> 17249 T2525 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b479082; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 17249 T2525 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 17250 T2525 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-1361108308241/jetty4/index
[junit4:junit4] 2> 17251 T2525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 17252 T2525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 17252 T2525 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 17253 T2525 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 17253 T2525 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 17254 T2525 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 17254 T2525 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 17254 T2525 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 17255 T2525 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 17261 T2525 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 17267 T2525 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-1361108308241/jetty4
[junit4:junit4] 2> 17268 T2525 oass.SolrIndexSearcher.<init> Opening Searcher@a6d7dac main
[junit4:junit4] 2> 17269 T2525 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 17269 T2525 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 17276 T2526 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a6d7dac main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 17277 T2525 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 17277 T2525 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17443 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17443 T2457 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:57329_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57329/pprdz/t"}
[junit4:junit4] 2> 17444 T2457 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 17444 T2457 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 17486 T2456 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> 17486 T2506 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> 17486 T2490 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> 17486 T2475 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> 17486 T2522 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> 17486 T2462 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> C186_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58667_pprdz%2Ft, base_url=http://127.0.0.1:58667/pprdz/t}
[junit4:junit4] 2> 18057 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:12928/pprdz/t/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 18057 T2509 C186 P58667 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58667/pprdz/t START replicas=[http://127.0.0.1:12928/pprdz/t/collection1/] nUpdates=100
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 18058 T2509 C186 P58667 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:12928/pprdz/t/collection1/. core=collection1
[junit4:junit4] 2> 18059 T2509 C186 P58667 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18060 T2467 C187 P12928 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 18073 T2470 C187 P12928 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 18078 T2470 C187 P12928 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18079 T2470 C187 P12928 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18079 T2470 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 18080 T2470 C187 P12928 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18080 T2470 C187 P12928 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 18081 T2509 C186 P58667 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18081 T2509 C186 P58667 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18084 T2469 C187 P12928 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 18085 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 18085 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18085 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18087 T2469 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 18088 T2469 C187 P12928 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-1361108308241/jetty1/index
[junit4:junit4] 2> 18088 T2469 C187 P12928 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 18089 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18090 T2509 C186 P58667 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-1361108308241/jetty3/index.20130218003846326 forceNew:false
[junit4:junit4] 2> 18090 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18091 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Starting download to 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-1361108308241/jetty3/index.20130218003846326 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ef32df8; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 18094 T2469 C187 P12928 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 18095 T2509 C186 P58667 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-1361108308241/jetty3/index
[junit4:junit4] 2> 18096 T2509 C186 P58667 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18096 T2509 C186 P58667 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130218003846326
[junit4:junit4] 2> 18097 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18098 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18098 T2509 C186 P58667 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty3/index.20130218003846326
[junit4:junit4] 2> 18101 T2509 C186 P58667 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty3/index.20130218003846326 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ef32df8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18101 T2509 C186 P58667 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18103 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18103 T2509 C186 P58667 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18103 T2509 C186 P58667 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18103 T2509 C186 P58667 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 18104 T2509 C186 P58667 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-1361108308241/jetty3/index.20130218003846326
[junit4:junit4] 2> 18105 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18108 T2509 C186 P58667 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty3/index.20130218003846326 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ef32df8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18108 T2509 C186 P58667 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18108 T2509 C186 P58667 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18109 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18109 T2509 C186 P58667 oass.SolrIndexSearcher.<init> Opening Searcher@3d741f74 main
[junit4:junit4] 2> 18110 T2508 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d741f74 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 18110 T2508 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-1361108308241/jetty3/index
[junit4:junit4] 2> 18110 T2509 C186 P58667 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 18113 T2509 C186 P58667 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty3/index.20130218003846326 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ef32df8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty3/index.20130218003846326 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ef32df8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 18114 T2509 C186 P58667 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 18115 T2509 C186 P58667 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-1361108308241/jetty3
[junit4:junit4] 2> 18115 T2509 C186 P58667 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18115 T2509 C186 P58667 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-1361108308241/jetty3/index.20130218003846326
[junit4:junit4] 2> 18115 T2509 C186 P58667 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-1361108308241/jetty3/index
[junit4:junit4] 2> 18115 T2509 C186 P58667 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18116 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18116 T2509 C186 P58667 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18116 T2509 C186 P58667 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18124 T2509 C186 P58667 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 18280 T2525 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18280 T2525 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57329/pprdz/t collection:collection1 shard:shard1
[junit4:junit4] 2> 18283 T2525 oasc.ZkController.register We are http://127.0.0.1:57329/pprdz/t/collection1/ and leader is http://127.0.0.1:12928/pprdz/t/collection1/
[junit4:junit4] 2> 18283 T2525 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57329/pprdz/t
[junit4:junit4] 2> 18284 T2525 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 18284 T2525 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C188 name=collection1 org.apache.solr.core.SolrCore@1ac72967 url=http://127.0.0.1:57329/pprdz/t/collection1 node=127.0.0.1:57329_pprdz%2Ft C188_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57329_pprdz%2Ft, base_url=http://127.0.0.1:57329/pprdz/t}
[junit4:junit4] 2> 18284 T2529 C188 P57329 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 18285 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 18285 T2525 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18285 T2529 C188 P57329 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 18285 T2529 C188 P57329 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18286 T2434 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> 18287 T2434 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 18287 T2529 C188 P57329 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18287 T2434 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18303 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18304 T2434 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 18305 T2434 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 18305 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18991 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18992 T2457 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:58667_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58667/pprdz/t"}
[junit4:junit4] 2> 19001 T2457 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:57329_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57329/pprdz/t"}
[junit4:junit4] 2> 19011 T2456 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> 19011 T2475 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> 19012 T2506 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> 19011 T2462 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> 19011 T2490 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> 19011 T2522 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> 19307 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20309 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C188_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57329_pprdz%2Ft, base_url=http://127.0.0.1:57329/pprdz/t}
[junit4:junit4] 2> 21306 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:12928/pprdz/t/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21306 T2529 C188 P57329 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57329/pprdz/t START replicas=[http://127.0.0.1:12928/pprdz/t/collection1/] nUpdates=100
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21307 T2529 C188 P57329 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:12928/pprdz/t/collection1/. core=collection1
[junit4:junit4] 2> 21308 T2529 C188 P57329 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21309 T2467 C187 P12928 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 21311 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21318 T2465 C187 P12928 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21322 T2465 C187 P12928 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21323 T2465 C187 P12928 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21323 T2465 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 21324 T2465 C187 P12928 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21324 T2465 C187 P12928 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 21325 T2529 C188 P57329 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21325 T2529 C188 P57329 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21327 T2469 C187 P12928 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 21328 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 21328 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21328 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21330 T2469 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 21331 T2469 C187 P12928 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-1361108308241/jetty1/index
[junit4:junit4] 2> 21331 T2469 C187 P12928 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 21332 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21333 T2529 C188 P57329 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-1361108308241/jetty4/index.20130218003849569 forceNew:false
[junit4:junit4] 2> 21333 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21334 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Starting download to 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-1361108308241/jetty4/index.20130218003849569 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e559bc; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 21337 T2469 C187 P12928 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 21338 T2529 C188 P57329 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-1361108308241/jetty4/index
[junit4:junit4] 2> 21339 T2529 C188 P57329 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21339 T2529 C188 P57329 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130218003849569
[junit4:junit4] 2> 21341 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21341 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21341 T2529 C188 P57329 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 21344 T2529 C188 P57329 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty4/index.20130218003849569 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e559bc; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21345 T2529 C188 P57329 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21346 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21346 T2529 C188 P57329 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21347 T2529 C188 P57329 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21347 T2529 C188 P57329 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 21347 T2529 C188 P57329 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-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 21348 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21351 T2529 C188 P57329 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty4/index.20130218003849569 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e559bc; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21351 T2529 C188 P57329 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21352 T2529 C188 P57329 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21352 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21352 T2529 C188 P57329 oass.SolrIndexSearcher.<init> Opening Searcher@58a7f788 main
[junit4:junit4] 2> 21353 T2526 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@58a7f788 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 21354 T2526 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-1361108308241/jetty4/index
[junit4:junit4] 2> 21354 T2529 C188 P57329 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21357 T2529 C188 P57329 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty4/index.20130218003849569 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e559bc; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty4/index.20130218003849569 lockFactory=org.apache.lucene.store.NativeFSLockFactory@21e559bc; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 21357 T2529 C188 P57329 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 21358 T2529 C188 P57329 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-1361108308241/jetty4
[junit4:junit4] 2> 21358 T2529 C188 P57329 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21359 T2529 C188 P57329 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-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 21359 T2529 C188 P57329 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-1361108308241/jetty4/index
[junit4:junit4] 2> 21359 T2529 C188 P57329 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21359 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21359 T2529 C188 P57329 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21360 T2529 C188 P57329 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21367 T2529 C188 P57329 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 22027 T2457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22028 T2457 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:57329_pprdz%2Ft",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57329/pprdz/t"}
[junit4:junit4] 2> 22043 T2456 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> 22043 T2475 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> 22043 T2506 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> 22043 T2462 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> 22043 T2490 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> 22043 T2522 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> 22313 T2434 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22314 T2434 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C189 name=collection1 org.apache.solr.core.SolrCore@6e37471d url=http://127.0.0.1:12917/pprdz/t/collection1 node=127.0.0.1:12917_pprdz%2Ft C189_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:12917_pprdz%2Ft, base_url=http://127.0.0.1:12917/pprdz/t, leader=true}
[junit4:junit4] 2> 22324 T2446 C189 P12917 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 22325 T2446 C189 P12917 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-1361108308241/control/data
[junit4:junit4] 2> 22329 T2446 C189 P12917 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=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-1361108308241/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ed676f5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22330 T2446 C189 P12917 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22334 T2446 C189 P12917 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=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-1361108308241/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ed676f5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=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-1361108308241/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ed676f5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22334 T2446 C189 P12917 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22336 T2446 C189 P12917 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-1361108308241/control/data
[junit4:junit4] 2> 22338 T2446 C189 P12917 oass.SolrIndexSearcher.<init> Opening Searcher@3732deac main
[junit4:junit4] 2> 22338 T2446 C189 P12917 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22339 T2460 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3732deac main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22339 T2460 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-1361108308241/control/data/index
[junit4:junit4] 2> 22340 T2446 C189 P12917 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 22350 T2468 C187 P12928 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 22353 T2468 C187 P12928 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=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-1361108308241/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bdd084; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22354 T2468 C187 P12928 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22355 T2468 C187 P12928 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-1361108308241/jetty1
[junit4:junit4] 2> 22355 T2468 C187 P12928 oass.SolrIndexSearcher.<init> Opening Searcher@71b5b84b main
[junit4:junit4] 2> 22356 T2468 C187 P12928 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-1361108308241/jetty1/index
[junit4:junit4] 2> 22356 T2468 C187 P12928 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22357 T2477 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71b5b84b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22357 T2477 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-1361108308241/jetty1/index
[junit4:junit4] 2> 22357 T2468 C187 P12928 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:12935/pprdz/t/collection1/, StdNode: http://127.0.0.1:58667/pprdz/t/collection1/, StdNode: http://127.0.0.1:57329/pprdz/t/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C188_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57329_pprdz%2Ft, base_url=http://127.0.0.1:57329/pprdz/t}
[junit4:junit4] 2> 22371 T2512 C188 P57329 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> C185_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, st
[...truncated too long message...]
in searcher on request.
[junit4:junit4] 2> 162680 T2522 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-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 162680 T2522 oasc.CachingDirectoryFactory.close Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 162680 T2522 oash.SnapPuller$2.preClose removing old index files 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-1361108308241/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b479082; maxCacheMB=48.0 maxMergeSizeMB=4.0)
[junit4:junit4] 2> 162681 T2522 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-1361108308241/jetty4/index.20130218003849569
[junit4:junit4] 2> 162681 T2522 oash.SnapPuller$2.postClose removing old index directory 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-1361108308241/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b479082; maxCacheMB=48.0 maxMergeSizeMB=4.0)
[junit4:junit4] 2> 162681 T2522 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-1361108308241/jetty4
[junit4:junit4] 2> 162682 T2522 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-1361108308241/jetty4
[junit4:junit4] 2> 162682 T2522 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-1361108308241/jetty4/index
[junit4:junit4] 2> 162682 T2522 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-1361108308241/jetty4/index
[junit4:junit4] 2> 162682 T2522 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 162683 T2522 oasc.LeaderElector$1.process WARNING org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election/89201594089340940-127.0.0.1:57329_pprdz%2Ft_collection1-n_0000000003
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:153)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:150)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:150)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:243)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 162683 T2522 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> 162683 T2522 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 162684 T2522 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 162684 T2522 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> 162684 T2522 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 162684 T2522 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=sq_AL, timezone=Asia/Sakhalin
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=4,free=172640216,total=301793280
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestLuceneMatchVersion, TestGroupingSearch, SortByFunctionTest, TestPartialUpdateDeduplication, QueryElevationComponentTest, TestLMJelinekMercerSimilarityFactory, TestExtendedDismaxParser, TestStressReorder, SuggesterFSTTest, NoCacheHeaderTest, PluginInfoTest, SolrPluginUtilsTest, ScriptEngineTest, TestConfig, TestIndexingPerformance, TestStressRecovery, ShardRoutingCustomTest, ChaosMonkeyNothingIsSafeTest, CurrencyFieldTest, ResourceLoaderTest, DateFieldTest, LeaderElectionIntegrationTest, TestPseudoReturnFields, RegexBoostProcessorTest, SolrRequestParserTest, TestQuerySenderNoQuery, TestNumberUtils, ZkControllerTest, SampleTest, CoreContainerCoreInitFailuresTest, TestWordDelimiterFilterFactory, LoggingHandlerTest, MBeansHandlerTest, TestRandomFaceting, UpdateRequestProcessorFactoryTest, AlternateDirectoryTest, SimpleFacetsTest, TestReload, WordBreakSolrSpellCheckerTest, TestFastOutputStream, ClusterStateUpdateTest, TestSearchPerf, ZkCLITest, TestCoreContainer, TestSuggestSpellingConverter, SpellPossibilityIteratorTest, NotRequiredUniqueKeyTest, JSONWriterTest, TestPerFieldSimilarity, NumericFieldsTest, TestElisionMultitermQuery, TestFuzzyAnalyzedSuggestions, TestJmxMonitoredMap, TestFastLRUCache, TestLFUCache, OverseerCollectionProcessorTest, PreAnalyzedFieldTest, TestRangeQuery, FileBasedSpellCheckerTest, SystemInfoHandlerTest, ResponseLogComponentTest, DateMathParserTest, DirectUpdateHandlerOptimizeTest, BasicDistributedZkTest, SpellCheckCollatorTest, AutoCommitTest, TestFaceting, DistributedTermsComponentTest, StatsComponentTest, IndexBasedSpellCheckerTest, DirectUpdateHandlerTest, TestSort, TestFiltering, ConvertedLegacyTest, PeerSyncTest, SignatureUpdateProcessorFactoryTest, TestBinaryResponseWriter, TestJmxIntegration, TestIndexSearcher, CoreAdminHandlerTest, DirectSolrConnectionTest, TestRemoteStreaming, CacheHeaderTest, QueryEqualityTest, PolyFieldTest, SpatialFilterTest, TestCSVResponseWriter, MoreLikeThisHandlerTest, DocumentBuilderTest, BinaryUpdateRequestHandlerTest, TermsComponentTest, DistanceFunctionTest, MinimalSchemaTest, StandardRequestHandlerTest, TestQueryTypes, XmlUpdateRequestHandlerTest, PingRequestHandlerTest, JsonLoaderTest, TestSurroundQueryParser, FastVectorHighlighterTest, DebugComponentTest, RequestHandlersTest, TestOmitPositions, TestArbitraryIndexDir, SolrCmdDistributorTest, SolrCoreCheckLockOnStartupTest, TestPropInject, BadComponentTest, HighlighterConfigTest, DefaultValueUpdateProcessorTest, TestCollationField, OutputWriterTest, TestBM25SimilarityFactory, TestLMDirichletSimilarityFactory, TestDFRSimilarityFactory, TestCodecSupport, TestBadConfig, ZkNodePropsTest, CircularListTest, TestDocumentBuilder, ClusterStateTest, ShardRoutingTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 163.10s, 1 test, 1 failure <<< FAILURES!
[...truncated 10 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: 251 suites, 1049 tests, 1 failure, 22 ignored (4 assumptions)
Total time: 47 minutes 23 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure