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/22 01:31:13 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1361 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1361/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
Test Setup Failure: shard1 should have just been set up to be inconsistent - but it's still consistent. Leader:http://127.0.0.1:21578/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@1466a1a9, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@1466a1a9]
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:21578/collection1skip list:[org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@1466a1a9, org.apache.solr.cloud.AbstractFullDistribZkTestBase$CloudJettyRunner@1466a1a9]
at __randomizedtesting.SeedInfo.seed([1B00C734498264C1:9AE6492C3EDD04FD]: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 9012 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T3101 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 5 T3101 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1361492843175
[junit4:junit4] 2> 6 T3101 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 7 T3102 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 10 T3102 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 10 T3102 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 10 T3102 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 10 T3102 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 12 T3102 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 108 T3101 oasc.ZkTestServer.run start zk server on port:10304
[junit4:junit4] 2> 108 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@405e3660
[junit4:junit4] 2> 109 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 110 T3107 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 110 T3107 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 110 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:32809
[junit4:junit4] 2> 111 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:32809
[junit4:junit4] 2> 111 T3105 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 115 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0000 with negotiated timeout 10000 for client /140.211.11.196:32809
[junit4:junit4] 2> 115 T3107 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0000, negotiated timeout = 10000
[junit4:junit4] 2> 115 T3108 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@405e3660 name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 116 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 116 T3101 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 119 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0000
[junit4:junit4] 2> 120 T3108 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 121 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:32809 which had sessionid 0x13cff4c1aad0000
[junit4:junit4] 2> 120 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0000 closed
[junit4:junit4] 2> 121 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@14c59a34
[junit4:junit4] 2> 122 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 122 T3109 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 123 T3109 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 123 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59690
[junit4:junit4] 2> 123 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59690
[junit4:junit4] 2> 129 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0001 with negotiated timeout 10000 for client /140.211.11.196:59690
[junit4:junit4] 2> 129 T3109 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0001, negotiated timeout = 10000
[junit4:junit4] 2> 129 T3110 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14c59a34 name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 130 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 130 T3101 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 133 T3101 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 143 T3101 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 146 T3101 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 148 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 149 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 159 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 160 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 263 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 264 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 267 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 268 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 277 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 278 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 280 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 281 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 284 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 285 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 287 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 288 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 295 T3101 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 296 T3101 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 298 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0001
[junit4:junit4] 2> 300 T3110 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 300 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0001 closed
[junit4:junit4] 2> 300 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59690 which had sessionid 0x13cff4c1aad0001
[junit4:junit4] 2> 487 T3101 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 492 T3101 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:51163
[junit4:junit4] 2> 493 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 493 T3101 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 494 T3101 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469
[junit4:junit4] 2> 494 T3101 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/solr.xml
[junit4:junit4] 2> 495 T3101 oasc.CoreContainer.<init> New CoreContainer 588789281
[junit4:junit4] 2> 495 T3101 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/'
[junit4:junit4] 2> 496 T3101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/'
[junit4:junit4] 2> 550 T3101 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 550 T3101 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 551 T3101 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 551 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 552 T3101 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 552 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 553 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 553 T3101 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 554 T3101 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 554 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 575 T3101 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 609 T3101 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:10304/solr
[junit4:junit4] 2> 610 T3101 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 611 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@52756ed1
[junit4:junit4] 2> 612 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612 T3120 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 613 T3120 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 613 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:11726
[junit4:junit4] 2> 614 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:11726
[junit4:junit4] 2> 617 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0002 with negotiated timeout 20000 for client /140.211.11.196:11726
[junit4:junit4] 2> 617 T3120 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0002, negotiated timeout = 20000
[junit4:junit4] 2> 618 T3121 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52756ed1 name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 618 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 619 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0002
[junit4:junit4] 2> 627 T3121 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 627 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:11726 which had sessionid 0x13cff4c1aad0002
[junit4:junit4] 2> 627 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0002 closed
[junit4:junit4] 2> 627 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 636 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@58bf5b
[junit4:junit4] 2> 637 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 638 T3122 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 638 T3122 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 638 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:40667
[junit4:junit4] 2> 639 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:40667
[junit4:junit4] 2> 640 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0003 with negotiated timeout 20000 for client /140.211.11.196:40667
[junit4:junit4] 2> 640 T3122 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0003, negotiated timeout = 20000
[junit4:junit4] 2> 640 T3123 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58bf5b name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 641 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 645 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 647 T3101 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51163_
[junit4:junit4] 2> 648 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:51163_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:51163_
[junit4:junit4] 2> 655 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51163_
[junit4:junit4] 2> 658 T3101 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 670 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 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> 672 T3101 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 681 T3101 oasc.Overseer.start Overseer (id=89226794970710019-127.0.0.1:51163_-n_0000000000) starting
[junit4:junit4] 2> 682 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 683 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 691 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 692 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 693 T3125 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 694 T3101 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 706 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 708 T3124 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 713 T3126 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/collection1
[junit4:junit4] 2> 713 T3126 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 714 T3126 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 714 T3126 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 715 T3126 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/collection1/'
[junit4:junit4] 2> 716 T3126 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 717 T3126 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/collection1/lib/README' to classloader
[junit4:junit4] 2> 765 T3126 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 823 T3126 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 924 T3126 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 931 T3126 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1545 T3126 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1557 T3126 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1561 T3126 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1573 T3126 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1577 T3126 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1582 T3126 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1583 T3126 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1584 T3126 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1361492843469/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/
[junit4:junit4] 2> 1584 T3126 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6545d2
[junit4:junit4] 2> 1584 T3126 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 1618 T3126 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data forceNew:false
[junit4:junit4] 2> 1619 T3126 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data
[junit4:junit4] 2> 1619 T3126 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index/
[junit4:junit4] 2> 1620 T3126 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1621 T3126 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index forceNew:false
[junit4:junit4] 2> 1688 T3126 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a6b8a4c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1689 T3126 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1690 T3126 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index
[junit4:junit4] 2> 1692 T3126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1692 T3126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1693 T3126 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1694 T3126 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1694 T3126 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1694 T3126 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1695 T3126 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1695 T3126 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1696 T3126 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1703 T3126 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1709 T3126 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data
[junit4:junit4] 2> 1710 T3126 oass.SolrIndexSearcher.<init> Opening Searcher@21b5a042 main
[junit4:junit4] 2> 1711 T3126 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1712 T3126 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1715 T3127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@21b5a042 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1716 T3126 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1717 T3126 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1717 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 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> 2211 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2212 T3124 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:51163_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51163"}
[junit4:junit4] 2> 2212 T3124 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2212 T3124 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2213 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 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> 2235 T3123 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> 2789 T3126 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2789 T3126 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51163 collection:control_collection shard:shard1
[junit4:junit4] 2> 2790 T3126 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2832 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 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> 2833 T3126 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2834 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2844 T3126 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2844 T3126 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2845 T3126 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51163/collection1/
[junit4:junit4] 2> 2845 T3126 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2845 T3126 oasc.SyncStrategy.syncToMe http://127.0.0.1:51163/collection1/ has no replicas
[junit4:junit4] 2> 2845 T3126 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51163/collection1/
[junit4:junit4] 2> 2845 T3126 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2849 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3744 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3760 T3123 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> 3775 T3126 oasc.ZkController.register We are http://127.0.0.1:51163/collection1/ and leader is http://127.0.0.1:51163/collection1/
[junit4:junit4] 2> 3775 T3126 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51163
[junit4:junit4] 2> 3775 T3126 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3775 T3126 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3776 T3126 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3777 T3126 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3778 T3101 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3779 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3779 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3794 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3795 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@72c3acba
[junit4:junit4] 2> 3796 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3797 T3128 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3797 T3128 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 3797 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:64353
[junit4:junit4] 2> 3798 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:64353
[junit4:junit4] 2> 3799 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0004 with negotiated timeout 10000 for client /140.211.11.196:64353
[junit4:junit4] 2> 3799 T3128 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0004, negotiated timeout = 10000
[junit4:junit4] 2> 3799 T3129 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72c3acba name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3799 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3800 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3802 T3101 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3968 T3101 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3972 T3101 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:50336
[junit4:junit4] 2> 3972 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3973 T3101 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3973 T3101 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971
[junit4:junit4] 2> 3974 T3101 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/solr.xml
[junit4:junit4] 2> 3974 T3101 oasc.CoreContainer.<init> New CoreContainer 1335517860
[junit4:junit4] 2> 3975 T3101 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/'
[junit4:junit4] 2> 3976 T3101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/'
[junit4:junit4] 2> 4023 T3101 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4024 T3101 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4024 T3101 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4025 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4025 T3101 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4025 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4026 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4026 T3101 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4027 T3101 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4027 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4048 T3101 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4066 T3101 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:10304/solr
[junit4:junit4] 2> 4067 T3101 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4067 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2a408b7d
[junit4:junit4] 2> 4068 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4068 T3139 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4069 T3139 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 4069 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:42022
[junit4:junit4] 2> 4070 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:42022
[junit4:junit4] 2> 4071 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0005 with negotiated timeout 20000 for client /140.211.11.196:42022
[junit4:junit4] 2> 4071 T3139 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0005, negotiated timeout = 20000
[junit4:junit4] 2> 4072 T3140 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a408b7d name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4072 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4073 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0005
[junit4:junit4] 2> 4074 T3140 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4074 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:42022 which had sessionid 0x13cff4c1aad0005
[junit4:junit4] 2> 4074 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0005 closed
[junit4:junit4] 2> 4074 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4086 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1271c384
[junit4:junit4] 2> 4087 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4087 T3141 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4087 T3141 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 4088 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:42949
[junit4:junit4] 2> 4088 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:42949
[junit4:junit4] 2> 4089 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0006 with negotiated timeout 20000 for client /140.211.11.196:42949
[junit4:junit4] 2> 4089 T3141 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0006, negotiated timeout = 20000
[junit4:junit4] 2> 4089 T3142 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1271c384 name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4090 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4090 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4092 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4101 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5103 T3101 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50336_
[junit4:junit4] 2> 5104 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:50336_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:50336_
[junit4:junit4] 2> 5105 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50336_
[junit4:junit4] 2> 5108 T3142 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5108 T3123 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5108 T3129 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5108 T3123 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> 5123 T3143 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/collection1
[junit4:junit4] 2> 5123 T3143 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5124 T3143 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5124 T3143 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5125 T3143 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/collection1/'
[junit4:junit4] 2> 5127 T3143 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/collection1/lib/README' to classloader
[junit4:junit4] 2> 5127 T3143 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5178 T3143 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 5239 T3143 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5273 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5274 T3124 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:51163_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51163"}
[junit4:junit4] 2> 5278 T3123 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> 5278 T3129 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> 5340 T3143 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5340 T3142 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> 5346 T3143 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5945 T3143 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5956 T3143 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5960 T3143 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 5971 T3143 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5976 T3143 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 5980 T3143 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5981 T3143 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 5982 T3143 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1361492846971/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/
[junit4:junit4] 2> 5982 T3143 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6545d2
[junit4:junit4] 2> 5983 T3143 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 5984 T3143 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1 forceNew:false
[junit4:junit4] 2> 5984 T3143 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 5984 T3143 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index/
[junit4:junit4] 2> 5985 T3143 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 5986 T3143 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index forceNew:false
[junit4:junit4] 2> 5992 T3143 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 5992 T3143 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 5993 T3143 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 5995 T3143 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 5996 T3143 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 5996 T3143 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 5997 T3143 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 5997 T3143 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 5998 T3143 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 5998 T3143 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 5999 T3143 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 5999 T3143 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6006 T3143 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6012 T3143 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 6013 T3143 oass.SolrIndexSearcher.<init> Opening Searcher@5e57a8ca main
[junit4:junit4] 2> 6014 T3143 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6014 T3143 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6019 T3144 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e57a8ca main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6021 T3143 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 6021 T3143 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6792 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6793 T3124 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:50336_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50336"}
[junit4:junit4] 2> 6793 T3124 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6793 T3124 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6812 T3123 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> 6812 T3129 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> 6812 T3142 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> 7024 T3143 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7024 T3143 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50336 collection:collection1 shard:shard1
[junit4:junit4] 2> 7025 T3143 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7041 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 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> 7042 T3143 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7042 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7044 T3143 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7044 T3143 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7044 T3143 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 7045 T3143 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7045 T3143 oasc.SyncStrategy.syncToMe http://127.0.0.1:50336/collection1/ has no replicas
[junit4:junit4] 2> 7045 T3143 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 7045 T3143 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7048 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8316 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8341 T3123 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> 8341 T3142 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> 8341 T3129 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> 8376 T3143 oasc.ZkController.register We are http://127.0.0.1:50336/collection1/ and leader is http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 8376 T3143 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50336
[junit4:junit4] 2> 8376 T3143 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8376 T3143 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8377 T3143 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8378 T3143 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8379 T3101 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 8380 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8381 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8559 T3101 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8562 T3101 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:21578
[junit4:junit4] 2> 8563 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8564 T3101 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8564 T3101 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563
[junit4:junit4] 2> 8565 T3101 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/solr.xml
[junit4:junit4] 2> 8565 T3101 oasc.CoreContainer.<init> New CoreContainer 1787849244
[junit4:junit4] 2> 8566 T3101 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/'
[junit4:junit4] 2> 8566 T3101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/'
[junit4:junit4] 2> 8613 T3101 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8613 T3101 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8614 T3101 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8614 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8615 T3101 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8615 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8616 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8616 T3101 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8617 T3101 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8617 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8635 T3101 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8653 T3101 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:10304/solr
[junit4:junit4] 2> 8654 T3101 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8654 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@b6aa423
[junit4:junit4] 2> 8655 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8656 T3154 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8656 T3154 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 8657 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:24693
[junit4:junit4] 2> 8657 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:24693
[junit4:junit4] 2> 8659 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0007 with negotiated timeout 20000 for client /140.211.11.196:24693
[junit4:junit4] 2> 8659 T3154 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0007, negotiated timeout = 20000
[junit4:junit4] 2> 8659 T3155 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b6aa423 name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8659 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8660 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0007
[junit4:junit4] 2> 8661 T3155 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8661 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:24693 which had sessionid 0x13cff4c1aad0007
[junit4:junit4] 2> 8661 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0007 closed
[junit4:junit4] 2> 8662 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8671 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@30a329af
[junit4:junit4] 2> 8672 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8672 T3156 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8673 T3156 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 8673 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:29434
[junit4:junit4] 2> 8673 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:29434
[junit4:junit4] 2> 8675 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0008 with negotiated timeout 20000 for client /140.211.11.196:29434
[junit4:junit4] 2> 8675 T3156 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0008, negotiated timeout = 20000
[junit4:junit4] 2> 8675 T3157 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30a329af name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8675 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8676 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8677 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8679 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9681 T3101 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:21578_
[junit4:junit4] 2> 9682 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad0008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:21578_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:21578_
[junit4:junit4] 2> 9684 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:21578_
[junit4:junit4] 2> 9686 T3129 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> 9686 T3157 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9686 T3123 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9686 T3142 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9687 T3142 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> 9687 T3123 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> 9695 T3129 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9700 T3158 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/collection1
[junit4:junit4] 2> 9701 T3158 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9701 T3158 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9701 T3158 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9703 T3158 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/collection1/'
[junit4:junit4] 2> 9704 T3158 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/collection1/lib/README' to classloader
[junit4:junit4] 2> 9705 T3158 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9755 T3158 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 9824 T3158 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9847 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9848 T3124 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:50336_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50336"}
[junit4:junit4] 2> 9852 T3123 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> 9852 T3129 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> 9852 T3142 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> 9925 T3158 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9925 T3157 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> 9931 T3158 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10532 T3158 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10543 T3158 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10547 T3158 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10559 T3158 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10563 T3158 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10567 T3158 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10568 T3158 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10569 T3158 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1361492851563/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/
[junit4:junit4] 2> 10570 T3158 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6545d2
[junit4:junit4] 2> 10570 T3158 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 10571 T3158 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2 forceNew:false
[junit4:junit4] 2> 10572 T3158 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 10572 T3158 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index/
[junit4:junit4] 2> 10573 T3158 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10573 T3158 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index forceNew:false
[junit4:junit4] 2> 10608 T3158 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@79750213; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10609 T3158 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10610 T3158 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index
[junit4:junit4] 2> 10612 T3158 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10612 T3158 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10612 T3158 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10613 T3158 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10614 T3158 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10614 T3158 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10614 T3158 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10615 T3158 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10615 T3158 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10622 T3158 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10628 T3158 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 10630 T3158 oass.SolrIndexSearcher.<init> Opening Searcher@76ec55a4 main
[junit4:junit4] 2> 10631 T3158 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10631 T3158 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10636 T3159 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@76ec55a4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10638 T3158 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10638 T3158 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11367 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11368 T3124 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:21578_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21578"}
[junit4:junit4] 2> 11368 T3124 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11368 T3124 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11381 T3142 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> 11381 T3129 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> 11381 T3123 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> 11381 T3157 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> 11640 T3158 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11640 T3158 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:21578 collection:collection1 shard:shard1
[junit4:junit4] 2> 11660 T3158 oasc.ZkController.register We are http://127.0.0.1:21578/collection1/ and leader is http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 11660 T3158 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:21578
[junit4:junit4] 2> 11661 T3158 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11661 T3158 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C186 name=collection1 org.apache.solr.core.SolrCore@52fe3bf5 url=http://127.0.0.1:21578/collection1 node=127.0.0.1:21578_ C186_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:21578_, base_url=http://127.0.0.1:21578}
[junit4:junit4] 2> 11662 T3160 C186 P21578 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11662 T3158 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11663 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11664 T3160 C186 P21578 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11664 T3160 C186 P21578 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11664 T3101 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 11665 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11665 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11682 T3160 C186 P21578 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11845 T3101 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11848 T3101 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:52871
[junit4:junit4] 2> 11849 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11849 T3101 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11850 T3101 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848
[junit4:junit4] 2> 11850 T3101 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/solr.xml
[junit4:junit4] 2> 11851 T3101 oasc.CoreContainer.<init> New CoreContainer 473760214
[junit4:junit4] 2> 11851 T3101 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/'
[junit4:junit4] 2> 11852 T3101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/'
[junit4:junit4] 2> 11899 T3101 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 11899 T3101 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11900 T3101 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11900 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11901 T3101 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11901 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11902 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11902 T3101 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11903 T3101 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11903 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11923 T3101 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11941 T3101 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:10304/solr
[junit4:junit4] 2> 11942 T3101 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11942 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@547419b0
[junit4:junit4] 2> 11943 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11944 T3170 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11944 T3170 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 11945 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:51517
[junit4:junit4] 2> 11945 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:51517
[junit4:junit4] 2> 11947 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad0009 with negotiated timeout 20000 for client /140.211.11.196:51517
[junit4:junit4] 2> 11947 T3170 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad0009, negotiated timeout = 20000
[junit4:junit4] 2> 11948 T3171 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@547419b0 name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11948 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11949 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad0009
[junit4:junit4] 2> 11961 T3171 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11962 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:51517 which had sessionid 0x13cff4c1aad0009
[junit4:junit4] 2> 11961 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad0009 closed
[junit4:junit4] 2> 11962 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 11973 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@33ddcc30
[junit4:junit4] 2> 11974 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11974 T3172 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11975 T3172 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 11975 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:53305
[junit4:junit4] 2> 11975 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:53305
[junit4:junit4] 2> 11977 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad000a with negotiated timeout 20000 for client /140.211.11.196:53305
[junit4:junit4] 2> 11977 T3172 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad000a, negotiated timeout = 20000
[junit4:junit4] 2> 11977 T3173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33ddcc30 name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11977 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11978 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11980 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11987 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12885 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12886 T3124 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:21578_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21578"}
[junit4:junit4] 2> 12899 T3129 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> 12899 T3173 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> 12899 T3123 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> 12899 T3157 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> 12899 T3142 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> 12989 T3101 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52871_
[junit4:junit4] 2> 12990 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000a type:delete cxid:0xb zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:52871_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:52871_
[junit4:junit4] 2> 12991 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52871_
[junit4:junit4] 2> 12993 T3129 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> 12993 T3157 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> 12993 T3123 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12994 T3173 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12994 T3142 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12994 T3123 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> 12994 T3173 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> 12994 T3129 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12994 T3142 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> 12995 T3157 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13008 T3174 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/collection1
[junit4:junit4] 2> 13008 T3174 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13009 T3174 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13009 T3174 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13010 T3174 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/collection1/'
[junit4:junit4] 2> 13011 T3174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/collection1/lib/README' to classloader
[junit4:junit4] 2> 13012 T3174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13058 T3174 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 13122 T3174 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13223 T3174 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13229 T3174 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13830 T3174 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13842 T3174 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13847 T3174 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13859 T3174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13864 T3174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13868 T3174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13869 T3174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13871 T3174 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1361492854848/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/
[junit4:junit4] 2> 13871 T3174 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6545d2
[junit4:junit4] 2> 13872 T3174 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 13873 T3174 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3 forceNew:false
[junit4:junit4] 2> 13873 T3174 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 13874 T3174 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index/
[junit4:junit4] 2> 13874 T3174 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13875 T3174 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index forceNew:false
[junit4:junit4] 2> 13889 T3174 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7272399c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13889 T3174 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13891 T3174 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 13893 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13893 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13894 T3174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13894 T3174 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13895 T3174 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13895 T3174 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13896 T3174 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13896 T3174 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13897 T3174 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13904 T3174 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13910 T3174 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 13911 T3174 oass.SolrIndexSearcher.<init> Opening Searcher@c2a9bae main
[junit4:junit4] 2> 13912 T3174 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13913 T3174 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13917 T3175 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c2a9bae main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13919 T3174 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13920 T3174 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14403 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14404 T3124 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:52871_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52871"}
[junit4:junit4] 2> 14404 T3124 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 14405 T3124 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14410 T3123 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 T3173 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 T3142 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 T3157 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 T3129 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> 14923 T3174 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14923 T3174 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52871 collection:collection1 shard:shard1
[junit4:junit4] 2> 14926 T3174 oasc.ZkController.register We are http://127.0.0.1:52871/collection1/ and leader is http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 14927 T3174 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52871
[junit4:junit4] 2> 14927 T3174 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 14927 T3174 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C187 name=collection1 org.apache.solr.core.SolrCore@7fffbf4e url=http://127.0.0.1:52871/collection1 node=127.0.0.1:52871_ C187_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:52871_, base_url=http://127.0.0.1:52871}
[junit4:junit4] 2> 14929 T3176 C187 P52871 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 14929 T3174 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14929 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 14930 T3176 C187 P52871 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 14930 T3176 C187 P52871 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14930 T3101 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 14931 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 14931 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14933 T3176 C187 P52871 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15110 T3101 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 15113 T3101 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:29800
[junit4:junit4] 2> 15114 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 15115 T3101 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 15115 T3101 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115
[junit4:junit4] 2> 15115 T3101 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/solr.xml
[junit4:junit4] 2> 15116 T3101 oasc.CoreContainer.<init> New CoreContainer 575134207
[junit4:junit4] 2> 15117 T3101 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/'
[junit4:junit4] 2> 15117 T3101 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/'
[junit4:junit4] 2> 15164 T3101 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 15164 T3101 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 15165 T3101 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 15165 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 15166 T3101 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 15166 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 15167 T3101 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 15167 T3101 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 15168 T3101 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 15168 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15187 T3101 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 15205 T3101 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:10304/solr
[junit4:junit4] 2> 15205 T3101 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15206 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3cb45a38
[junit4:junit4] 2> 15207 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15207 T3186 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15208 T3186 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 15208 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:31140
[junit4:junit4] 2> 15209 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:31140
[junit4:junit4] 2> 15210 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad000b with negotiated timeout 20000 for client /140.211.11.196:31140
[junit4:junit4] 2> 15210 T3186 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad000b, negotiated timeout = 20000
[junit4:junit4] 2> 15211 T3187 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3cb45a38 name:ZooKeeperConnection Watcher:127.0.0.1:10304 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15211 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15212 T3106 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13cff4c1aad000b
[junit4:junit4] 2> 15213 T3187 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15213 T3103 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:31140 which had sessionid 0x13cff4c1aad000b
[junit4:junit4] 2> 15213 T3101 oaz.ZooKeeper.close Session: 0x13cff4c1aad000b closed
[junit4:junit4] 2> 15214 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 15223 T3101 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:10304/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3f6b4794
[junit4:junit4] 2> 15224 T3101 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15224 T3188 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:10304. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15225 T3188 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:10304, initiating session
[junit4:junit4] 2> 15225 T3103 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:51953
[junit4:junit4] 2> 15225 T3103 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:51953
[junit4:junit4] 2> 15227 T3105 oazs.ZooKeeperServer.finishSessionInit Established session 0x13cff4c1aad000c with negotiated timeout 20000 for client /140.211.11.196:51953
[junit4:junit4] 2> 15227 T3188 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:10304, sessionid = 0x13cff4c1aad000c, negotiated timeout = 20000
[junit4:junit4] 2> 15227 T3189 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f6b4794 name:ZooKeeperConnection Watcher:127.0.0.1:10304/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15227 T3101 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15228 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000c type:create cxid:0x1 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15229 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000c type:create cxid:0x2 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15238 T3101 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[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:21578_, base_url=http://127.0.0.1:21578}
[junit4:junit4] 2> 15695 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50336/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15695 T3160 C186 P21578 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:21578 START replicas=[http://127.0.0.1:50336/collection1/] nUpdates=100
[junit4:junit4] 2> 15695 T3160 C186 P21578 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15696 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15696 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15696 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15696 T3160 C186 P21578 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15696 T3160 C186 P21578 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50336/collection1/. core=collection1
[junit4:junit4] 2> 15697 T3160 C186 P21578 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C188 name=collection1 org.apache.solr.core.SolrCore@4701980e url=http://127.0.0.1:50336/collection1 node=127.0.0.1:50336_ C188_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50336_, base_url=http://127.0.0.1:50336, leader=true}
[junit4:junit4] 2> 15702 T3134 C188 P50336 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 15707 T3135 C188 P50336 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15708 T3135 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 15712 T3135 C188 P50336 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15713 T3135 C188 P50336 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15717 T3135 C188 P50336 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15717 T3135 C188 P50336 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15718 T3135 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 15719 T3135 C188 P50336 oass.SolrIndexSearcher.<init> Opening Searcher@10d38f43 realtime
[junit4:junit4] 2> 15719 T3135 C188 P50336 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15719 T3135 C188 P50336 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 15720 T3160 C186 P21578 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15720 T3160 C186 P21578 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15722 T3136 C188 P50336 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15722 T3136 C188 P50336 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 15723 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15723 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15723 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15725 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 15726 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 15726 T3136 C188 P50336 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 15727 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15728 T3160 C186 P21578 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 forceNew:false
[junit4:junit4] 2> 15728 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15729 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b11b049; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 15732 T3136 C188 P50336 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 15733 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index
[junit4:junit4] 2> 15733 T3160 C186 P21578 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15734 T3160 C186 P21578 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130222022738896
[junit4:junit4] 2> 15735 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15736 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15736 T3160 C186 P21578 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896
[junit4:junit4] 2> 15739 T3160 C186 P21578 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b11b049; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15740 T3160 C186 P21578 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15741 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15741 T3160 C186 P21578 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15741 T3160 C186 P21578 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15742 T3160 C186 P21578 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15742 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896
[junit4:junit4] 2> 15743 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15746 T3160 C186 P21578 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b11b049; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15746 T3160 C186 P21578 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15747 T3160 C186 P21578 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15747 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15747 T3160 C186 P21578 oass.SolrIndexSearcher.<init> Opening Searcher@5f03affe main
[junit4:junit4] 2> 15748 T3159 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5f03affe main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15749 T3159 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index
[junit4:junit4] 2> 15749 T3160 C186 P21578 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 15752 T3160 C186 P21578 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b11b049; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b11b049; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 15752 T3160 C186 P21578 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 15753 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2
[junit4:junit4] 2> 15754 T3160 C186 P21578 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15754 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index.20130222022738896
[junit4:junit4] 2> 15754 T3160 C186 P21578 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty2/index
[junit4:junit4] 2> 15754 T3160 C186 P21578 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15754 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15755 T3160 C186 P21578 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15755 T3160 C186 P21578 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15756 T3160 C186 P21578 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 15922 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15923 T3124 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:52871_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52871"}
[junit4:junit4] 2> 15926 T3124 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:21578_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21578"}
[junit4:junit4] 2> 15938 T3142 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> 15938 T3189 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> 15938 T3123 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> 15938 T3173 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> 15938 T3157 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> 15938 T3129 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> 16241 T3101 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29800_
[junit4:junit4] 2> 16242 T3106 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13cff4c1aad000c type:delete cxid:0xb zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:29800_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:29800_
[junit4:junit4] 2> 16243 T3101 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:29800_
[junit4:junit4] 2> 16245 T3129 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> 16245 T3157 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> 16246 T3173 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16245 T3189 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16246 T3123 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16245 T3142 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16246 T3189 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> 16246 T3123 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> 16246 T3173 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> 16246 T3142 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> 16247 T3129 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16254 T3157 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16271 T3192 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/collection1
[junit4:junit4] 2> 16271 T3192 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 16272 T3192 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 16272 T3192 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 16273 T3192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/collection1/'
[junit4:junit4] 2> 16274 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/collection1/lib/README' to classloader
[junit4:junit4] 2> 16275 T3192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 16338 T3192 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 16393 T3192 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 16494 T3192 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 16501 T3192 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 17095 T3192 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 17103 T3192 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 17106 T3192 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 17116 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17120 T3192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17123 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17124 T3192 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17125 T3192 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1361492858115/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/
[junit4:junit4] 2> 17125 T3192 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@6545d2
[junit4:junit4] 2> 17125 T3192 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 17126 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4 forceNew:false
[junit4:junit4] 2> 17127 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 17127 T3192 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index/
[junit4:junit4] 2> 17128 T3192 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 17128 T3192 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index forceNew:false
[junit4:junit4] 2> 17139 T3192 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@48b5626b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 17140 T3192 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 17140 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index
[junit4:junit4] 2> 17142 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 17142 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 17142 T3192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 17143 T3192 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 17143 T3192 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 17143 T3192 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 17144 T3192 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 17144 T3192 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 17144 T3192 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 17151 T3192 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 17156 T3192 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 17157 T3192 oass.SolrIndexSearcher.<init> Opening Searcher@419a1286 main
[junit4:junit4] 2> 17158 T3192 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 17159 T3192 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 17162 T3193 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@419a1286 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 17163 T3192 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 17164 T3192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17450 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17451 T3124 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:29800_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29800"}
[junit4:junit4] 2> 17451 T3124 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 17451 T3124 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 17474 T3129 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> 17474 T3123 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> 17474 T3173 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> 17474 T3142 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> 17474 T3189 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> 17474 T3157 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> C187_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:52871_, base_url=http://127.0.0.1:52871}
[junit4:junit4] 2> 17949 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50336/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 17949 T3176 C187 P52871 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52871 START replicas=[http://127.0.0.1:50336/collection1/] nUpdates=100
[junit4:junit4] 2> 17949 T3176 C187 P52871 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 17950 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 17950 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 17950 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 17950 T3134 C188 P50336 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 17950 T3176 C187 P52871 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 17951 T3176 C187 P52871 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50336/collection1/. core=collection1
[junit4:junit4] 2> 17951 T3176 C187 P52871 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 17965 T3137 C188 P50336 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 17997 T3137 C188 P50336 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 17997 T3137 C188 P50336 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 17998 T3137 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 17999 T3137 C188 P50336 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 17999 T3137 C188 P50336 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 34
[junit4:junit4] 2> 18000 T3176 C187 P52871 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18000 T3176 C187 P52871 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18002 T3136 C188 P50336 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 18002 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 18003 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18003 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18005 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 18005 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 18006 T3136 C188 P50336 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 18006 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18007 T3176 C187 P52871 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 forceNew:false
[junit4:junit4] 2> 18007 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18008 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 18010 T3136 C188 P50336 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 18011 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 18011 T3176 C187 P52871 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18012 T3176 C187 P52871 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130222022741175
[junit4:junit4] 2> 18012 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18013 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18013 T3176 C187 P52871 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 18015 T3176 C187 P52871 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18015 T3176 C187 P52871 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18016 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18016 T3176 C187 P52871 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18017 T3176 C187 P52871 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18017 T3176 C187 P52871 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 18017 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 18018 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18020 T3176 C187 P52871 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18020 T3176 C187 P52871 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18020 T3176 C187 P52871 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18020 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18021 T3176 C187 P52871 oass.SolrIndexSearcher.<init> Opening Searcher@64bfa061 main
[junit4:junit4] 2> 18021 T3175 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64bfa061 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 18022 T3175 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 18022 T3176 C187 P52871 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 18025 T3176 C187 P52871 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 18025 T3176 C187 P52871 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18026 T3176 C187 P52871 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18028 T3176 C187 P52871 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 18173 T3192 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18173 T3192 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:29800 collection:collection1 shard:shard1
[junit4:junit4] 2> 18176 T3192 oasc.ZkController.register We are http://127.0.0.1:29800/collection1/ and leader is http://127.0.0.1:50336/collection1/
[junit4:junit4] 2> 18176 T3192 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29800
[junit4:junit4] 2> 18176 T3192 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 18176 T3192 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C189 name=collection1 org.apache.solr.core.SolrCore@56354233 url=http://127.0.0.1:29800/collection1 node=127.0.0.1:29800_ C189_STATE=coll:collection1 core:collection1 props:{shard=null, roles=null, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:29800_, base_url=http://127.0.0.1:29800}
[junit4:junit4] 2> 18177 T3196 C189 P29800 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 18177 T3192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18178 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 18178 T3196 C189 P29800 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 18178 T3196 C189 P29800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18179 T3101 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 18179 T3101 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 18180 T3101 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18189 T3196 C189 P29800 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18193 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18194 T3101 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 18195 T3101 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 18196 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18978 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18979 T3124 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:52871_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52871"}
[junit4:junit4] 2> 18988 T3124 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:29800_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29800"}
[junit4:junit4] 2> 19006 T3123 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> 19006 T3142 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> 19006 T3157 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> 19006 T3189 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> 19006 T3129 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> 19006 T3173 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> 19197 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20199 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C189_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:29800_, base_url=http://127.0.0.1:29800}
[junit4:junit4] 2> 21201 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50336/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21201 T3196 C189 P29800 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:29800 START replicas=[http://127.0.0.1:50336/collection1/] nUpdates=100
[junit4:junit4] 2> 21201 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21201 T3196 C189 P29800 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21202 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21202 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21202 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21202 T3196 C189 P29800 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21203 T3196 C189 P29800 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50336/collection1/. core=collection1
[junit4:junit4] 2> 21203 T3196 C189 P29800 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21204 T3134 C188 P50336 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 21213 T3132 C188 P50336 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21244 T3132 C188 P50336 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21244 T3132 C188 P50336 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21245 T3132 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 21246 T3132 C188 P50336 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21246 T3132 C188 P50336 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 33
[junit4:junit4] 2> 21247 T3196 C189 P29800 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21247 T3196 C189 P29800 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21249 T3136 C188 P50336 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 21250 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 21250 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21250 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21252 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 21253 T3136 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 21253 T3136 C188 P50336 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 21254 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21255 T3196 C189 P29800 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 forceNew:false
[junit4:junit4] 2> 21256 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21256 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74c2edab; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=true
[junit4:junit4] 2> 21266 T3136 C188 P50336 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 21268 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index
[junit4:junit4] 2> 21268 T3196 C189 P29800 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21269 T3196 C189 P29800 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130222022744423
[junit4:junit4] 2> 21270 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21271 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21271 T3196 C189 P29800 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423
[junit4:junit4] 2> 21274 T3196 C189 P29800 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74c2edab; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21275 T3196 C189 P29800 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21276 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21276 T3196 C189 P29800 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21276 T3196 C189 P29800 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21277 T3196 C189 P29800 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 21277 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423
[junit4:junit4] 2> 21278 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21281 T3196 C189 P29800 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74c2edab; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21281 T3196 C189 P29800 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21282 T3196 C189 P29800 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21282 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21283 T3196 C189 P29800 oass.SolrIndexSearcher.<init> Opening Searcher@38b05b3b main
[junit4:junit4] 2> 21283 T3193 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38b05b3b main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 21284 T3193 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index
[junit4:junit4] 2> 21284 T3196 C189 P29800 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=false,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 21287 T3196 C189 P29800 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74c2edab; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423 lockFactory=org.apache.lucene.store.NativeFSLockFactory@74c2edab; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 21288 T3196 C189 P29800 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 21289 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4
[junit4:junit4] 2> 21289 T3196 C189 P29800 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21289 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index.20130222022744423
[junit4:junit4] 2> 21289 T3196 C189 P29800 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty4/index
[junit4:junit4] 2> 21290 T3196 C189 P29800 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21290 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21290 T3196 C189 P29800 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21290 T3196 C189 P29800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21298 T3196 C189 P29800 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 22021 T3124 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22022 T3124 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:29800_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29800"}
[junit4:junit4] 2> 22031 T3123 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> 22031 T3142 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> 22031 T3173 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> 22031 T3189 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> 22031 T3157 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> 22031 T3129 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> 22203 T3101 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22204 T3101 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C190 name=collection1 org.apache.solr.core.SolrCore@7b0c5100 url=http://127.0.0.1:51163/collection1 node=127.0.0.1:51163_ C190_STATE=coll:control_collection core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:51163_, base_url=http://127.0.0.1:51163, leader=true}
[junit4:junit4] 2> 22214 T3113 C190 P51163 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 22216 T3113 C190 P51163 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data
[junit4:junit4] 2> 22220 T3113 C190 P51163 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a6b8a4c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22220 T3113 C190 P51163 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22225 T3113 C190 P51163 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a6b8a4c; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@5a6b8a4c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22225 T3113 C190 P51163 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22226 T3113 C190 P51163 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data
[junit4:junit4] 2> 22229 T3113 C190 P51163 oass.SolrIndexSearcher.<init> Opening Searcher@67284c6 main
[junit4:junit4] 2> 22229 T3113 C190 P51163 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22230 T3127 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@67284c6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22230 T3127 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/control/data/index
[junit4:junit4] 2> 22231 T3113 C190 P51163 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 22240 T3135 C188 P50336 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 22244 T3135 C188 P50336 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b4d383e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22245 T3135 C188 P50336 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22245 T3135 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1
[junit4:junit4] 2> 22246 T3135 C188 P50336 oass.SolrIndexSearcher.<init> Opening Searcher@2bf61332 main
[junit4:junit4] 2> 22247 T3135 C188 P50336 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 22247 T3135 C188 P50336 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22248 T3144 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2bf61332 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22248 T3144 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty1/index
[junit4:junit4] 2> 22248 T3135 C188 P50336 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:21578/collection1/, StdNode: http://127.0.0.1:52871/collection1/, StdNode: http://127.0.0.1:29800/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C187_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52871_, base_url=http://127.0.0.1:52871}
[junit4:junit4] 2> 22262 T3163 C187 P52871 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> C189_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:29800_, base_url=http://127.0.0.1:29800}
[junit4:junit4] 2> 22262 T3179 C189 P29800 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> C186_STATE=coll:collection1 core:collection1 props:{shard=shard1, roles=null, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:21578_, base_url=http://127.0.0.1:21578}
[junit4:junit4] 2> 22263 T3147 C186 P21578 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false}
[junit4:junit4] 2> 22278 T3163 C187 P52871 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-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6165168a; 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
[...truncated too long message...]
SliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 159552 T3173 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 159554 T3173 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 159554 T3173 oasc.CachingDirectoryFactory.close Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 159554 T3173 oash.SnapPuller$2.preClose removing old index files NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7272399c; maxCacheMB=48.0 maxMergeSizeMB=4.0)
[junit4:junit4] 2> 159555 T3173 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index.20130222022741175
[junit4:junit4] 2> 159555 T3173 oash.SnapPuller$2.postClose removing old index directory NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7272399c; maxCacheMB=48.0 maxMergeSizeMB=4.0)
[junit4:junit4] 2> 159556 T3173 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 159556 T3173 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3
[junit4:junit4] 2> 159556 T3173 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 159556 T3173 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-1361492843174/jetty3/index
[junit4:junit4] 2> 159556 T3173 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 159557 T3173 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> 159557 T3173 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 159557 T3173 oasc.LeaderElector$1.process WARNING org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[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.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:236)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:233)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:233)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[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> 159558 T3173 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=ar_DZ, timezone=Europe/Tiraspol
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=219695832,total=384172032
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestComponentsName, BasicFunctionalityTest, TestPluginEnable, TermVectorComponentTest, TestSort, TestCSVResponseWriter, TestRealTimeGet, PrimitiveFieldTypeTest, TestRemoteStreaming, URLClassifyProcessorTest, TestStressLucene, TestDistributedGrouping, TestSolrCoreProperties, OverseerTest, IndexSchemaRuntimeFieldTest, OpenExchangeRatesOrgProviderTest, SliceStateUpdateTest, HardAutoCommitTest, TestSolrDeletionPolicy1, PingRequestHandlerTest, TestDocumentBuilder, ZkNodePropsTest, TestSurroundQueryParser, TestTrie, SuggesterTest, ShowFileRequestHandlerTest, SynonymTokenizerTest, TestAnalyzedSuggestions, ReturnFieldsTest, TestRecovery, IndexReaderFactoryTest, UpdateParamsTest, TestUtils, DirectSolrSpellCheckerTest, IndexSchemaTest, FullSolrCloudDistribCmdsTest, TestFunctionQuery, SoftAutoCommitTest, TestSolr4Spatial, EchoParamsTest, XmlUpdateRequestHandlerTest, TestOmitPositions, TestReplicationHandler, HighlighterTest, TestBM25SimilarityFactory, TimeZoneUtilsTest, ResponseLogComponentTest, DebugComponentTest, TestBinaryField, TestUpdate, MultiTermTest, OutputWriterTest, StatsComponentTest, TestWriterPerf, DocumentAnalysisRequestHandlerTest, DOMUtilTest, TestCSVLoader, TestCharFilters, BasicZkTest, FileUtilsTest, LukeRequestHandlerTest, RecoveryZkTest, SpellCheckComponentTest, LeaderElectionTest, ZkControllerTest, TestRandomFaceting, TestDistributedSearch, AutoCommitTest, ZkSolrClientTest, WordBreakSolrSpellCheckerTest, TestHashPartitioner, DistributedTermsComponentTest, SolrCoreTest, DirectUpdateHandlerTest, TestMultiCoreConfBootstrap, TestCoreContainer, TestFiltering, FileBasedSpellCheckerTest, ConvertedLegacyTest, PeerSyncTest, SortByFunctionTest, SignatureUpdateProcessorFactoryTest, TestJmxIntegration, CoreAdminHandlerTest, DirectSolrConnectionTest, QueryEqualityTest, TestWordDelimiterFilterFactory, PolyFieldTest, SpatialFilterTest, DocumentBuilderTest, MBeansHandlerTest, DistributedQueryElevationComponentTest, CurrencyFieldTest, DisMaxRequestHandlerTest, BinaryUpdateRequestHandlerTest, QueryParsingTest, DistanceFunctionTest, SolrInfoMBeanTest, XsltUpdateRequestHandlerTest, MinimalSchemaTest, StandardRequestHandlerTest, TestQueryTypes, DirectUpdateHandlerOptimizeTest, SolrPluginUtilsTest, TestValueSourceCache, FastVectorHighlighterTest, TestReversedWildcardFilterFactory, SearchHandlerTest, RequiredFieldsTest, CopyFieldTest, TestArbitraryIndexDir, TestQueryUtils, LoggingHandlerTest, SuggesterTSTTest, SolrCmdDistributorTest, TestSearchPerf, NotRequiredUniqueKeyTest, BadIndexSchemaTest, TestFoldingMultitermQuery, UpdateRequestProcessorFactoryTest, TestPropInject, AlternateDirectoryTest, FieldMutatingUpdateProcessorTest, BadComponentTest, TestSolrDeletionPolicy2, SOLR749Test, TestPropInjectDefaults, DefaultValueUpdateProcessorTest, TestMergePolicyConfig, TestDocSet, TestQuerySenderListener, SolrIndexConfigTest, TestQuerySenderNoQuery, NumericFieldsTest, TestJmxMonitoredMap, SpellPossibilityIteratorTest, TestPhraseSuggestions, TestLMDirichletSimilarityFactory, TestPerFieldSimilarity, LegacyHTMLStripCharFilterTest, TestDFRSimilarityFactory, TestCodecSupport, DateMathParserTest, PluginInfoTest, PrimUtilsTest, TestSolrXMLSerializer, SpellingQueryConverterTest, TestSuggestSpellingConverter, TestBadConfig, TestLRUCache, UUIDFieldTest, RAMDirectoryFactoryTest, SystemInfoHandlerTest, CircularListTest, AnalysisAfterCoreReloadTest, TestCollationKeyRangeQueries, BasicDistributedZk2Test, OverseerCollectionProcessorTest, SliceStateTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 159.98s, 1 test, 1 failure <<< FAILURES!
[...truncated 67 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:361: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1202: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:865: There were test failures: 255 suites, 1056 tests, 1 failure, 22 ignored (4 assumptions)
Total time: 45 minutes 15 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure