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/03/05 01:47:49 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1391 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1391/
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:63699/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:63707/collection1], CloudJettyRunner [url=http://127.0.0.1:63707/collection1]]
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:63699/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:63707/collection1], CloudJettyRunner [url=http://127.0.0.1:63707/collection1]]
at __randomizedtesting.SeedInfo.seed([162B1498722038CD:97CD9A80057F58F1]: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:212)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
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 8596 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T533 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 5 T533 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/J0/./solrtest-SyncSliceTest-1362443308157
[junit4:junit4] 2> 7 T533 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 7 T534 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 10 T534 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 11 T534 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 11 T534 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 11 T534 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 12 T534 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 108 T533 oasc.ZkTestServer.run start zk server on port:63689
[junit4:junit4] 2> 108 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@40983fb
[junit4:junit4] 2> 110 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 110 T539 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 111 T539 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 111 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63690
[junit4:junit4] 2> 112 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63690
[junit4:junit4] 2> 112 T537 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 115 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840000 with negotiated timeout 10000 for client /140.211.11.196:63690
[junit4:junit4] 2> 115 T539 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840000, negotiated timeout = 10000
[junit4:junit4] 2> 115 T540 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40983fb name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 115 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 116 T533 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 129 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840000
[junit4:junit4] 2> 130 T540 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 130 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63690 which had sessionid 0x13d37f30c840000
[junit4:junit4] 2> 130 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840000 closed
[junit4:junit4] 2> 131 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@60ebeb19
[junit4:junit4] 2> 132 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 132 T541 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 133 T541 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 133 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63691
[junit4:junit4] 2> 133 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63691
[junit4:junit4] 2> 135 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840001 with negotiated timeout 10000 for client /140.211.11.196:63691
[junit4:junit4] 2> 135 T541 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840001, negotiated timeout = 10000
[junit4:junit4] 2> 135 T542 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60ebeb19 name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 136 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 136 T533 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 141 T533 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 150 T533 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 154 T533 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 158 T533 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> 159 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 166 T533 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> 167 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 271 T533 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> 272 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 276 T533 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> 277 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 281 T533 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> 282 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 286 T533 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> 286 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 291 T533 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> 291 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 295 T533 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> 296 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 300 T533 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> 301 T533 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 305 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840001
[junit4:junit4] 2> 306 T542 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 306 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63691 which had sessionid 0x13d37f30c840001
[junit4:junit4] 2> 306 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840001 closed
[junit4:junit4] 2> 480 T533 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 485 T533 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63692
[junit4:junit4] 2> 486 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 486 T533 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 487 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457
[junit4:junit4] 2> 487 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/solr.xml
[junit4:junit4] 2> 488 T533 oasc.CoreContainer.<init> New CoreContainer 1527807570
[junit4:junit4] 2> 488 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/'
[junit4:junit4] 2> 489 T533 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/'
[junit4:junit4] 2> 536 T533 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 536 T533 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 537 T533 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 537 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 538 T533 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 538 T533 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 539 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 539 T533 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 540 T533 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 540 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 562 T533 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 579 T533 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:63689/solr
[junit4:junit4] 2> 580 T533 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 581 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3babf87e
[junit4:junit4] 2> 582 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 582 T552 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 583 T552 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 583 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63693
[junit4:junit4] 2> 584 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63693
[junit4:junit4] 2> 586 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840002 with negotiated timeout 20000 for client /140.211.11.196:63693
[junit4:junit4] 2> 586 T552 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840002, negotiated timeout = 20000
[junit4:junit4] 2> 586 T553 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3babf87e name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 586 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 588 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840002
[junit4:junit4] 2> 598 T553 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 598 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63693 which had sessionid 0x13d37f30c840002
[junit4:junit4] 2> 598 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840002 closed
[junit4:junit4] 2> 598 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 610 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@5ce08e48
[junit4:junit4] 2> 611 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612 T554 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 612 T554 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 613 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63694
[junit4:junit4] 2> 613 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63694
[junit4:junit4] 2> 614 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840003 with negotiated timeout 20000 for client /140.211.11.196:63694
[junit4:junit4] 2> 614 T554 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840003, negotiated timeout = 20000
[junit4:junit4] 2> 615 T555 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5ce08e48 name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 615 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 618 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 625 T533 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 628 T533 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63692_
[junit4:junit4] 2> 629 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63692_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63692_
[junit4:junit4] 2> 631 T533 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63692_
[junit4:junit4] 2> 635 T533 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 648 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 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> 650 T533 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 659 T533 oasc.Overseer.start Overseer (id=89289084643835907-127.0.0.1:63692_-n_0000000000) starting
[junit4:junit4] 2> 660 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 661 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 663 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 672 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 673 T557 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 674 T533 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 678 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 681 T556 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 686 T558 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/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/collection1
[junit4:junit4] 2> 686 T558 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 687 T558 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 687 T558 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 689 T558 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/collection1/'
[junit4:junit4] 2> 690 T558 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 690 T558 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/collection1/lib/README' to classloader
[junit4:junit4] 2> 737 T558 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 792 T558 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 893 T558 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 900 T558 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1501 T558 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1512 T558 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1516 T558 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1536 T558 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1541 T558 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1546 T558 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1547 T558 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1548 T558 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1548 T558 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1549 T558 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1550 T558 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1550 T558 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/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362443308457/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/
[junit4:junit4] 2> 1550 T558 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1d34263a
[junit4:junit4] 2> 1551 T558 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1552 T558 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data forceNew:false
[junit4:junit4] 2> 1552 T558 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 1552 T558 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/index/
[junit4:junit4] 2> 1553 T558 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1553 T558 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/index forceNew:false
[junit4:junit4] 2> 1556 T558 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ea3e75d lockFactory=org.apache.lucene.store.NativeFSLockFactory@231e51d0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1557 T558 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1558 T558 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/index
[junit4:junit4] 2> 1559 T558 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1560 T558 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1560 T558 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1561 T558 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1561 T558 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1561 T558 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1562 T558 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1562 T558 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1563 T558 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1570 T558 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1575 T558 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 1576 T558 oass.SolrIndexSearcher.<init> Opening Searcher@4184178e main
[junit4:junit4] 2> 1576 T558 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/tlog
[junit4:junit4] 2> 1577 T558 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1577 T558 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1580 T558 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 1581 T559 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4184178e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1582 T558 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1582 T558 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1583 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 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> 2186 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2187 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63692_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63692"}
[junit4:junit4] 2> 2187 T556 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2188 T556 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2188 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 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> 2205 T555 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> 2600 T558 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2600 T558 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63692 collection:control_collection shard:shard1
[junit4:junit4] 2> 2601 T558 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2661 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 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> 2703 T558 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2704 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2720 T558 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2721 T558 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2721 T558 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63692/collection1/
[junit4:junit4] 2> 2721 T558 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2722 T558 oasc.SyncStrategy.syncToMe http://127.0.0.1:63692/collection1/ has no replicas
[junit4:junit4] 2> 2722 T558 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63692/collection1/
[junit4:junit4] 2> 2722 T558 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2777 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3717 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3774 T555 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> 3799 T558 oasc.ZkController.register We are http://127.0.0.1:63692/collection1/ and leader is http://127.0.0.1:63692/collection1/
[junit4:junit4] 2> 3799 T558 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63692
[junit4:junit4] 2> 3799 T558 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3799 T558 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3800 T558 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3802 T558 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3803 T533 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3804 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3804 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3818 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3820 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1b4e0f0e
[junit4:junit4] 2> 3821 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3821 T560 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 3822 T560 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 3822 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63695
[junit4:junit4] 2> 3822 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63695
[junit4:junit4] 2> 3823 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840004 with negotiated timeout 10000 for client /140.211.11.196:63695
[junit4:junit4] 2> 3824 T560 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840004, negotiated timeout = 10000
[junit4:junit4] 2> 3824 T561 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b4e0f0e name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3824 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3826 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3828 T533 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4003 T533 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4006 T533 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63696
[junit4:junit4] 2> 4006 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4007 T533 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4007 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979
[junit4:junit4] 2> 4008 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/solr.xml
[junit4:junit4] 2> 4008 T533 oasc.CoreContainer.<init> New CoreContainer 105946566
[junit4:junit4] 2> 4009 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/'
[junit4:junit4] 2> 4009 T533 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/'
[junit4:junit4] 2> 4057 T533 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4057 T533 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4058 T533 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4058 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4059 T533 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4059 T533 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4059 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4060 T533 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4060 T533 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4061 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4080 T533 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4098 T533 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:63689/solr
[junit4:junit4] 2> 4099 T533 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4099 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@79fc08ce
[junit4:junit4] 2> 4101 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4101 T571 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4102 T571 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 4102 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63697
[junit4:junit4] 2> 4102 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63697
[junit4:junit4] 2> 4105 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840005 with negotiated timeout 20000 for client /140.211.11.196:63697
[junit4:junit4] 2> 4105 T571 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840005, negotiated timeout = 20000
[junit4:junit4] 2> 4106 T572 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79fc08ce name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4106 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4107 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840005
[junit4:junit4] 2> 4117 T572 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4117 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63697 which had sessionid 0x13d37f30c840005
[junit4:junit4] 2> 4117 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840005 closed
[junit4:junit4] 2> 4118 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4129 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3f279e56
[junit4:junit4] 2> 4130 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4130 T573 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 4130 T573 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 4131 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63698
[junit4:junit4] 2> 4131 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63698
[junit4:junit4] 2> 4132 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840006 with negotiated timeout 20000 for client /140.211.11.196:63698
[junit4:junit4] 2> 4132 T573 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840006, negotiated timeout = 20000
[junit4:junit4] 2> 4133 T574 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f279e56 name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4133 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4134 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4136 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4139 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5142 T533 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63696_
[junit4:junit4] 2> 5143 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63696_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63696_
[junit4:junit4] 2> 5145 T533 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63696_
[junit4:junit4] 2> 5149 T561 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5149 T574 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5149 T555 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5149 T555 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> 5171 T575 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/collection1
[junit4:junit4] 2> 5171 T575 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5172 T575 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5172 T575 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5174 T575 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/collection1/'
[junit4:junit4] 2> 5175 T575 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5175 T575 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/collection1/lib/README' to classloader
[junit4:junit4] 2> 5223 T575 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 5277 T575 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5282 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5283 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63692_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63692"}
[junit4:junit4] 2> 5296 T561 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 5296 T555 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> 5378 T575 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5378 T574 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> 5385 T575 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 5982 T575 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 5993 T575 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 5997 T575 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 6019 T575 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6024 T575 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6028 T575 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6030 T575 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6030 T575 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6030 T575 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6032 T575 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6032 T575 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6032 T575 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362443311979/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/
[junit4:junit4] 2> 6033 T575 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1d34263a
[junit4:junit4] 2> 6033 T575 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6034 T575 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1 forceNew:false
[junit4:junit4] 2> 6034 T575 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 6034 T575 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index/
[junit4:junit4] 2> 6035 T575 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 6036 T575 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index forceNew:false
[junit4:junit4] 2> 6038 T575 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 6038 T575 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 6039 T575 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 6041 T575 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 6041 T575 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 6042 T575 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 6043 T575 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 6043 T575 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 6044 T575 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 6044 T575 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 6044 T575 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 6045 T575 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6052 T575 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6057 T575 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 6058 T575 oass.SolrIndexSearcher.<init> Opening Searcher@129f8ab4 main
[junit4:junit4] 2> 6058 T575 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/tlog
[junit4:junit4] 2> 6059 T575 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6059 T575 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6063 T576 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@129f8ab4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6065 T575 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 6066 T575 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6802 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6803 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63696_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63696"}
[junit4:junit4] 2> 6804 T556 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6804 T556 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6818 T561 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> 6818 T574 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> 6818 T555 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> 7068 T575 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7068 T575 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63696 collection:collection1 shard:shard1
[junit4:junit4] 2> 7069 T575 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7087 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 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> 7088 T575 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7089 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7091 T575 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7092 T575 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7092 T575 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 7092 T575 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7092 T575 oasc.SyncStrategy.syncToMe http://127.0.0.1:63696/collection1/ has no replicas
[junit4:junit4] 2> 7093 T575 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 7093 T575 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7099 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8324 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8367 T555 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> 8367 T561 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> 8367 T574 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> 8385 T575 oasc.ZkController.register We are http://127.0.0.1:63696/collection1/ and leader is http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 8385 T575 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63696
[junit4:junit4] 2> 8385 T575 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8385 T575 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8386 T575 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8388 T575 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8389 T533 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8390 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8390 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8583 T533 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8586 T533 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63699
[junit4:junit4] 2> 8586 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8587 T533 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8587 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556
[junit4:junit4] 2> 8588 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/solr.xml
[junit4:junit4] 2> 8588 T533 oasc.CoreContainer.<init> New CoreContainer 667819911
[junit4:junit4] 2> 8589 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/'
[junit4:junit4] 2> 8590 T533 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/'
[junit4:junit4] 2> 8637 T533 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8638 T533 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8638 T533 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8639 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8639 T533 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8640 T533 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8640 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8641 T533 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8641 T533 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8641 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8662 T533 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8679 T533 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:63689/solr
[junit4:junit4] 2> 8680 T533 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8681 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7c46a6f8
[junit4:junit4] 2> 8682 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8682 T586 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8683 T586 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 8683 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63700
[junit4:junit4] 2> 8684 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63700
[junit4:junit4] 2> 8686 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840007 with negotiated timeout 20000 for client /140.211.11.196:63700
[junit4:junit4] 2> 8686 T586 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840007, negotiated timeout = 20000
[junit4:junit4] 2> 8686 T587 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c46a6f8 name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8686 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8688 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840007
[junit4:junit4] 2> 8699 T587 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8699 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63700 which had sessionid 0x13d37f30c840007
[junit4:junit4] 2> 8699 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840007 closed
[junit4:junit4] 2> 8700 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8713 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2dbd9f3d
[junit4:junit4] 2> 8714 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8714 T588 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 8715 T588 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 8715 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63701
[junit4:junit4] 2> 8716 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63701
[junit4:junit4] 2> 8717 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840008 with negotiated timeout 20000 for client /140.211.11.196:63701
[junit4:junit4] 2> 8717 T588 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840008, negotiated timeout = 20000
[junit4:junit4] 2> 8717 T589 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2dbd9f3d name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8717 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8719 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8720 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8728 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9732 T533 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63699_
[junit4:junit4] 2> 9734 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c840008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63699_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63699_
[junit4:junit4] 2> 9768 T533 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63699_
[junit4:junit4] 2> 9771 T574 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> 9772 T561 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9772 T555 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9772 T561 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> 9772 T555 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> 9772 T589 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9773 T574 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9781 T590 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/collection1
[junit4:junit4] 2> 9782 T590 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9782 T590 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9783 T590 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9785 T590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/collection1/'
[junit4:junit4] 2> 9786 T590 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9786 T590 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/collection1/lib/README' to classloader
[junit4:junit4] 2> 9832 T590 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 9882 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9883 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63696_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63696"}
[junit4:junit4] 2> 9888 T590 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9896 T561 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> 9896 T555 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> 9896 T589 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> 9896 T590 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9896 T574 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> 9904 T590 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10502 T590 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10513 T590 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10517 T590 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10536 T590 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10541 T590 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10546 T590 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10547 T590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10548 T590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10548 T590 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10550 T590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10550 T590 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10550 T590 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362443316556/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/
[junit4:junit4] 2> 10551 T590 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1d34263a
[junit4:junit4] 2> 10551 T590 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10552 T590 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2 forceNew:false
[junit4:junit4] 2> 10552 T590 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 10553 T590 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index/
[junit4:junit4] 2> 10553 T590 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10554 T590 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index forceNew:false
[junit4:junit4] 2> 10556 T590 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5841be48 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16cc601f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10556 T590 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10557 T590 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index
[junit4:junit4] 2> 10559 T590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10560 T590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10560 T590 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10561 T590 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10561 T590 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10562 T590 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10562 T590 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10563 T590 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10563 T590 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10570 T590 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10575 T590 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 10576 T590 oass.SolrIndexSearcher.<init> Opening Searcher@25c1e75a main
[junit4:junit4] 2> 10576 T590 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/tlog
[junit4:junit4] 2> 10577 T590 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10577 T590 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10582 T591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25c1e75a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10584 T590 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10584 T590 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11402 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11403 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63699_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63699"}
[junit4:junit4] 2> 11403 T556 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11404 T556 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11417 T561 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> 11417 T574 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> 11417 T589 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> 11417 T555 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> 11587 T590 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11587 T590 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63699 collection:collection1 shard:shard1
[junit4:junit4] 2> 11591 T590 oasc.ZkController.register We are http://127.0.0.1:63699/collection1/ and leader is http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 11591 T590 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63699
[junit4:junit4] 2> 11591 T590 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11591 T590 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C40 name=collection1 org.apache.solr.core.SolrCore@729ed172 url=http://127.0.0.1:63699/collection1 node=127.0.0.1:63699_ C40_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:63699_, base_url=http://127.0.0.1:63699}
[junit4:junit4] 2> 11592 T592 C40 P63699 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11593 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11593 T590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11593 T592 C40 P63699 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11593 T592 C40 P63699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11594 T533 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11595 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11595 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11597 T592 C40 P63699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11791 T533 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 11794 T533 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63703
[junit4:junit4] 2> 11794 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 11795 T533 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 11795 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766
[junit4:junit4] 2> 11796 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/solr.xml
[junit4:junit4] 2> 11796 T533 oasc.CoreContainer.<init> New CoreContainer 1808427429
[junit4:junit4] 2> 11797 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/'
[junit4:junit4] 2> 11797 T533 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/'
[junit4:junit4] 2> 11845 T533 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 11845 T533 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 11846 T533 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 11846 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 11847 T533 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 11847 T533 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 11848 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 11848 T533 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 11848 T533 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 11849 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 11868 T533 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 11886 T533 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:63689/solr
[junit4:junit4] 2> 11887 T533 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 11887 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3988b95
[junit4:junit4] 2> 11889 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11889 T602 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11890 T602 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 11890 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63704
[junit4:junit4] 2> 11890 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63704
[junit4:junit4] 2> 11892 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c840009 with negotiated timeout 20000 for client /140.211.11.196:63704
[junit4:junit4] 2> 11893 T602 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c840009, negotiated timeout = 20000
[junit4:junit4] 2> 11893 T603 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3988b95 name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11893 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11895 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c840009
[junit4:junit4] 2> 11906 T603 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 11906 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63704 which had sessionid 0x13d37f30c840009
[junit4:junit4] 2> 11906 T533 oaz.ZooKeeper.close Session: 0x13d37f30c840009 closed
[junit4:junit4] 2> 11906 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 11917 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@630f83c9
[junit4:junit4] 2> 11918 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 11918 T604 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 11919 T604 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 11919 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63705
[junit4:junit4] 2> 11919 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63705
[junit4:junit4] 2> 11921 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c84000a with negotiated timeout 20000 for client /140.211.11.196:63705
[junit4:junit4] 2> 11921 T604 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c84000a, negotiated timeout = 20000
[junit4:junit4] 2> 11921 T605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@630f83c9 name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 11921 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 11922 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11928 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11931 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12929 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12930 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63699_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63699"}
[junit4:junit4] 2> 12964 T533 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63703_
[junit4:junit4] 2> 12965 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000a type:delete cxid:0x9 zxid:0x83 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63703_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63703_
[junit4:junit4] 2> 12967 T533 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63703_
[junit4:junit4] 2> 12973 T574 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> 12973 T561 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12973 T589 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12973 T605 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12974 T589 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> 12973 T561 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> 12974 T605 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> 12975 T589 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12977 T561 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 12977 T574 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12977 T574 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> 12986 T555 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 12986 T555 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> 12987 T555 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> 12991 T606 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/collection1
[junit4:junit4] 2> 12991 T606 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 12992 T606 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 12992 T606 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 12994 T606 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/collection1/'
[junit4:junit4] 2> 12995 T606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 12996 T606 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/collection1/lib/README' to classloader
[junit4:junit4] 2> 13047 T606 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 13102 T606 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13203 T606 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13210 T606 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13780 T606 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13787 T606 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13790 T606 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13806 T606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13810 T606 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13813 T606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13815 T606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13815 T606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13815 T606 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13816 T606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13817 T606 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13817 T606 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362443319766/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/
[junit4:junit4] 2> 13817 T606 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1d34263a
[junit4:junit4] 2> 13817 T606 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 13818 T606 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3 forceNew:false
[junit4:junit4] 2> 13818 T606 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 13818 T606 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index/
[junit4:junit4] 2> 13819 T606 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13819 T606 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index forceNew:false
[junit4:junit4] 2> 13821 T606 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e1859e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@660d402e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13821 T606 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13821 T606 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index
[junit4:junit4] 2> 13823 T606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13823 T606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13823 T606 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13824 T606 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13824 T606 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13824 T606 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13825 T606 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13825 T606 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13825 T606 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13830 T606 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13834 T606 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 13834 T606 oass.SolrIndexSearcher.<init> Opening Searcher@5480ab02 main
[junit4:junit4] 2> 13834 T606 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/tlog
[junit4:junit4] 2> 13835 T606 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13835 T606 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13838 T607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5480ab02 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13839 T606 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13840 T606 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14487 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14488 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63703_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63703"}
[junit4:junit4] 2> 14488 T556 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 14488 T556 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14507 T555 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> 14507 T589 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> 14507 T605 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> 14507 T574 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> 14507 T561 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> 14868 T606 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 14868 T606 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63703 collection:collection1 shard:shard1
[junit4:junit4] 2> 14872 T606 oasc.ZkController.register We are http://127.0.0.1:63703/collection1/ and leader is http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 14872 T606 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63703
[junit4:junit4] 2> 14873 T606 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 14873 T606 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C41 name=collection1 org.apache.solr.core.SolrCore@6ea7cba9 url=http://127.0.0.1:63703/collection1 node=127.0.0.1:63703_ C41_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:63703_, base_url=http://127.0.0.1:63703}
[junit4:junit4] 2> 14874 T608 C41 P63703 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 14874 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 14874 T608 C41 P63703 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 14874 T606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14875 T608 C41 P63703 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14876 T533 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 14876 T608 C41 P63703 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 14876 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 14877 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15072 T533 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 15075 T533 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63707
[junit4:junit4] 2> 15076 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 15076 T533 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 15077 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048
[junit4:junit4] 2> 15077 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/solr.xml
[junit4:junit4] 2> 15078 T533 oasc.CoreContainer.<init> New CoreContainer 798147976
[junit4:junit4] 2> 15078 T533 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/'
[junit4:junit4] 2> 15079 T533 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/'
[junit4:junit4] 2> 15126 T533 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 15126 T533 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 15127 T533 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 15127 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 15128 T533 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 15128 T533 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 15129 T533 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 15129 T533 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 15130 T533 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 15130 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15152 T533 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 15170 T533 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:63689/solr
[junit4:junit4] 2> 15170 T533 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15171 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2fdebd03
[junit4:junit4] 2> 15172 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15172 T618 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15173 T618 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 15173 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63708
[junit4:junit4] 2> 15174 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63708
[junit4:junit4] 2> 15176 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c84000b with negotiated timeout 20000 for client /140.211.11.196:63708
[junit4:junit4] 2> 15176 T618 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c84000b, negotiated timeout = 20000
[junit4:junit4] 2> 15176 T619 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fdebd03 name:ZooKeeperConnection Watcher:127.0.0.1:63689 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15177 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15178 T538 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d37f30c84000b
[junit4:junit4] 2> 15190 T619 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15190 T535 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:63708 which had sessionid 0x13d37f30c84000b
[junit4:junit4] 2> 15190 T533 oaz.ZooKeeper.close Session: 0x13d37f30c84000b closed
[junit4:junit4] 2> 15190 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 15202 T533 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:63689/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@194019b9
[junit4:junit4] 2> 15204 T533 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15204 T620 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:63689. Will not attempt to authenticate using SASL (access denied (javax.security.auth.AuthPermission getLoginConfiguration))
[junit4:junit4] 2> 15204 T620 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:63689, initiating session
[junit4:junit4] 2> 15205 T535 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:63709
[junit4:junit4] 2> 15205 T535 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:63709
[junit4:junit4] 2> 15206 T537 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d37f30c84000c with negotiated timeout 20000 for client /140.211.11.196:63709
[junit4:junit4] 2> 15206 T620 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:63689, sessionid = 0x13d37f30c84000c, negotiated timeout = 20000
[junit4:junit4] 2> 15207 T621 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@194019b9 name:ZooKeeperConnection Watcher:127.0.0.1:63689/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15207 T533 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15208 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000c type:create cxid:0x1 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15210 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000c type:create cxid:0x2 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15219 T533 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C40_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:63699_, base_url=http://127.0.0.1:63699}
[junit4:junit4] 2> 15620 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63696/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15620 T592 C40 P63699 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:63699 START replicas=[http://127.0.0.1:63696/collection1/] nUpdates=100
[junit4:junit4] 2> 15621 T592 C40 P63699 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15621 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15621 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15621 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15622 T592 C40 P63699 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15622 T592 C40 P63699 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63696/collection1/. core=collection1
[junit4:junit4] 2> 15622 T592 C40 P63699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C42 name=collection1 org.apache.solr.core.SolrCore@bd3671 url=http://127.0.0.1:63696/collection1 node=127.0.0.1:63696_ C42_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63696_, base_url=http://127.0.0.1:63696, leader=true}
[junit4:junit4] 2> 15628 T566 C42 P63696 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 15635 T567 C42 P63696 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 15636 T567 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 15638 T567 C42 P63696 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15638 T567 C42 P63696 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15639 T567 C42 P63696 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15640 T567 C42 P63696 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15640 T567 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 15640 T567 C42 P63696 oass.SolrIndexSearcher.<init> Opening Searcher@10198cc realtime
[junit4:junit4] 2> 15641 T567 C42 P63696 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15641 T567 C42 P63696 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 15642 T592 C40 P63699 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15642 T592 C40 P63699 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15644 T568 C42 P63696 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15645 T568 C42 P63696 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 15645 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15645 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15646 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15648 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 15648 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 15649 T568 C42 P63696 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 15649 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15650 T592 C40 P63699 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index.20130305012843801 forceNew:false
[junit4:junit4] 2> 15651 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 15651 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@223279 lockFactory=org.apache.lucene.store.NativeFSLockFactory@20cb6d74) fullCopy=false
[junit4:junit4] 2> 15654 T568 C42 P63696 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 15655 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index
[junit4:junit4] 2> 15655 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15656 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 15657 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 15657 T592 C40 P63699 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15657 T592 C40 P63699 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15657 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 15659 T592 C40 P63699 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5841be48 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16cc601f),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5841be48 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16cc601f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15659 T592 C40 P63699 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15660 T592 C40 P63699 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15660 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 15660 T592 C40 P63699 oass.SolrIndexSearcher.<init> Opening Searcher@b0e6d6e main
[junit4:junit4] 2> 15661 T591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b0e6d6e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15662 T591 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index
[junit4:junit4] 2> 15662 T592 C40 P63699 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@223279 lockFactory=org.apache.lucene.store.NativeFSLockFactory@20cb6d74)
[junit4:junit4] 2> 15662 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index.20130305012843801
[junit4:junit4] 2> 15662 T592 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index
[junit4:junit4] 2> 15663 T592 C40 P63699 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15663 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15663 T592 C40 P63699 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15663 T592 C40 P63699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15665 T592 C40 P63699 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 16013 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16014 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63703_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63703"}
[junit4:junit4] 2> 16019 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63699_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63699"}
[junit4:junit4] 2> 16033 T561 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> 16033 T621 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> 16033 T555 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> 16033 T574 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> 16033 T605 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> 16033 T589 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> 16222 T533 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63707_
[junit4:junit4] 2> 16223 T538 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d37f30c84000c type:delete cxid:0xb zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:63707_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:63707_
[junit4:junit4] 2> 16224 T533 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63707_
[junit4:junit4] 2> 16227 T605 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> 16227 T574 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> 16228 T561 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16228 T621 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16228 T555 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16228 T621 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> 16228 T561 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> 16228 T589 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16228 T555 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> 16229 T589 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> 16229 T605 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16230 T574 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16244 T624 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/collection1
[junit4:junit4] 2> 16245 T624 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 16245 T624 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 16246 T624 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 16247 T624 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/collection1/'
[junit4:junit4] 2> 16248 T624 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 16249 T624 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/collection1/lib/README' to classloader
[junit4:junit4] 2> 16296 T624 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_42
[junit4:junit4] 2> 16352 T624 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 16453 T624 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 16460 T624 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 17060 T624 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 17071 T624 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 17075 T624 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 17093 T624 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17097 T624 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17102 T624 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17103 T624 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 17104 T624 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 17104 T624 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17105 T624 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 17106 T624 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 17106 T624 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/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362443323048/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/
[junit4:junit4] 2> 17106 T624 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1d34263a
[junit4:junit4] 2> 17107 T624 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 17108 T624 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4 forceNew:false
[junit4:junit4] 2> 17108 T624 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 17108 T624 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index/
[junit4:junit4] 2> 17109 T624 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 17109 T624 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index forceNew:false
[junit4:junit4] 2> 17112 T624 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4d3b82d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e11fee),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 17112 T624 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 17113 T624 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 17115 T624 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 17115 T624 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 17116 T624 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 17116 T624 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 17117 T624 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 17117 T624 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 17118 T624 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 17118 T624 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 17119 T624 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 17126 T624 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 17131 T624 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 17132 T624 oass.SolrIndexSearcher.<init> Opening Searcher@2e57d154 main
[junit4:junit4] 2> 17132 T624 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/tlog
[junit4:junit4] 2> 17133 T624 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 17133 T624 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 17137 T625 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e57d154 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 17139 T624 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 17140 T624 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17548 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17549 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63707_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63707"}
[junit4:junit4] 2> 17550 T556 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 17550 T556 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 17582 T561 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> 17582 T621 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> 17582 T605 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> 17582 T574 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> 17582 T555 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> 17582 T589 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> 18142 T624 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18142 T624 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63707 collection:collection1 shard:shard1
[junit4:junit4] 2> 18148 T624 oasc.ZkController.register We are http://127.0.0.1:63707/collection1/ and leader is http://127.0.0.1:63696/collection1/
[junit4:junit4] 2> 18148 T624 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63707
[junit4:junit4] 2> 18148 T624 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 18148 T624 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C43 name=collection1 org.apache.solr.core.SolrCore@381c2f40 url=http://127.0.0.1:63707/collection1 node=127.0.0.1:63707_ C43_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:63707_, base_url=http://127.0.0.1:63707}
[junit4:junit4] 2> 18149 T626 C43 P63707 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 18150 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 18150 T624 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18150 T626 C43 P63707 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 18150 T626 C43 P63707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18151 T533 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 18152 T533 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 18152 T626 C43 P63707 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18152 T533 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18169 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18170 T533 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 18170 T533 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 18171 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C41_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:63703_, base_url=http://127.0.0.1:63703}
[junit4:junit4] 2> 18901 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63696/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 18901 T608 C41 P63703 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:63703 START replicas=[http://127.0.0.1:63696/collection1/] nUpdates=100
[junit4:junit4] 2> 18901 T608 C41 P63703 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 18902 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 18902 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 18902 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 18902 T608 C41 P63703 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 18902 T608 C41 P63703 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63696/collection1/. core=collection1
[junit4:junit4] 2> 18903 T608 C41 P63703 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18904 T566 C42 P63696 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 18915 T570 C42 P63696 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 18916 T570 C42 P63696 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18917 T570 C42 P63696 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18917 T570 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 18917 T570 C42 P63696 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18918 T570 C42 P63696 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 18919 T608 C41 P63703 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18919 T608 C41 P63703 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18921 T568 C42 P63696 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 18922 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 18922 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18922 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18924 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 18924 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 18925 T568 C42 P63696 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 18925 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18926 T608 C41 P63703 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index.20130305012847077 forceNew:false
[junit4:junit4] 2> 18927 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 18927 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@12830606 lockFactory=org.apache.lucene.store.NativeFSLockFactory@82963fb) fullCopy=false
[junit4:junit4] 2> 18929 T568 C42 P63696 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 18930 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index
[junit4:junit4] 2> 18930 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18931 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 18931 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 18932 T608 C41 P63703 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18932 T608 C41 P63703 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18932 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 18934 T608 C41 P63703 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e1859e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@660d402e),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e1859e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@660d402e),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18934 T608 C41 P63703 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18935 T608 C41 P63703 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18935 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 18935 T608 C41 P63703 oass.SolrIndexSearcher.<init> Opening Searcher@55f97846 main
[junit4:junit4] 2> 18936 T607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55f97846 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 18937 T607 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index
[junit4:junit4] 2> 18937 T608 C41 P63703 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@12830606 lockFactory=org.apache.lucene.store.NativeFSLockFactory@82963fb)
[junit4:junit4] 2> 18937 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index.20130305012847077
[junit4:junit4] 2> 18937 T608 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index
[junit4:junit4] 2> 18938 T608 C41 P63703 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18938 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18938 T608 C41 P63703 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18938 T608 C41 P63703 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18976 T608 C41 P63703 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 19091 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19092 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63707_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63707"}
[junit4:junit4] 2> 19096 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63703_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63703"}
[junit4:junit4] 2> 19109 T561 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> 19109 T555 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> 19109 T574 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> 19109 T621 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> 19109 T605 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> 19109 T589 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> 19173 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20175 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C43_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:63707_, base_url=http://127.0.0.1:63707}
[junit4:junit4] 2> 21171 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63696/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21171 T626 C43 P63707 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:63707 START replicas=[http://127.0.0.1:63696/collection1/] nUpdates=100
[junit4:junit4] 2> 21172 T626 C43 P63707 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21172 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21172 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21172 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21172 T626 C43 P63707 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21173 T626 C43 P63707 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63696/collection1/. core=collection1
[junit4:junit4] 2> 21173 T626 C43 P63707 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21174 T566 C42 P63696 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 21178 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21184 T564 C42 P63696 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 21185 T564 C42 P63696 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21186 T564 C42 P63696 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21186 T564 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 21187 T564 C42 P63696 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21187 T564 C42 P63696 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 21188 T626 C43 P63707 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21188 T626 C43 P63707 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21190 T568 C42 P63696 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 21191 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 21191 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21191 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21193 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 21193 T568 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 21194 T568 C42 P63696 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 21194 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21196 T626 C43 P63707 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index.20130305012849346 forceNew:false
[junit4:junit4] 2> 21196 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 21197 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@885a6fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c1cd99) fullCopy=false
[junit4:junit4] 2> 21199 T568 C42 P63696 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 21200 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 21200 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21201 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 21202 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 21202 T626 C43 P63707 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21202 T626 C43 P63707 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21202 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 21204 T626 C43 P63707 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4d3b82d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e11fee),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4d3b82d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e11fee),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21204 T626 C43 P63707 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21205 T626 C43 P63707 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21205 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 21205 T626 C43 P63707 oass.SolrIndexSearcher.<init> Opening Searcher@5e6e5c0f main
[junit4:junit4] 2> 21206 T625 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5e6e5c0f main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 21207 T625 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 21207 T626 C43 P63707 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@885a6fa lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c1cd99)
[junit4:junit4] 2> 21207 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index.20130305012849346
[junit4:junit4] 2> 21208 T626 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 21208 T626 C43 P63707 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21208 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21208 T626 C43 P63707 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21208 T626 C43 P63707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21211 T626 C43 P63707 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 22126 T556 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22127 T556 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:63707_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63707"}
[junit4:junit4] 2> 22140 T561 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> 22140 T621 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> 22140 T574 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> 22140 T555 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> 22140 T589 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> 22140 T605 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> 22180 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22181 T533 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C44 name=collection1 org.apache.solr.core.SolrCore@52aaf223 url=http://127.0.0.1:63692/collection1 node=127.0.0.1:63692_ C44_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:63692_, base_url=http://127.0.0.1:63692, leader=true}
[junit4:junit4] 2> 22189 T545 C44 P63692 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22190 T545 C44 P63692 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 22192 T545 C44 P63692 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ea3e75d lockFactory=org.apache.lucene.store.NativeFSLockFactory@231e51d0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22193 T545 C44 P63692 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22194 T545 C44 P63692 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ea3e75d lockFactory=org.apache.lucene.store.NativeFSLockFactory@231e51d0),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ea3e75d lockFactory=org.apache.lucene.store.NativeFSLockFactory@231e51d0),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22194 T545 C44 P63692 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22195 T545 C44 P63692 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 22195 T545 C44 P63692 oass.SolrIndexSearcher.<init> Opening Searcher@1b0c3117 main
[junit4:junit4] 2> 22196 T545 C44 P63692 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22196 T559 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b0c3117 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22197 T559 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data/index
[junit4:junit4] 2> 22197 T545 C44 P63692 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 22214 T567 C42 P63696 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22215 T567 C42 P63696 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@12063acc lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a16841c),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22215 T567 C42 P63696 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22216 T567 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 22216 T567 C42 P63696 oass.SolrIndexSearcher.<init> Opening Searcher@7cb7ef95 main
[junit4:junit4] 2> 22217 T567 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 22217 T567 C42 P63696 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22218 T576 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7cb7ef95 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22218 T576 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1/index
[junit4:junit4] 2> 22219 T567 C42 P63696 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:63699/collection1/, StdNode: http://127.0.0.1:63703/collection1/, StdNode: http://127.0.0.1:63707/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C41_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63703_, base_url=http://127.0.0.1:63703}
[junit4:junit4] 2> 22227 T595 C41 P63703 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C40_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63699_, base_url=http://127.0.0.1:63699}
[junit4:junit4] 2> 22227 T579 C40 P63699 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C43_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63707_, base_url=http://127.0.0.1:63707}
[junit4:junit4] 2> 22228 T611 C43 P63707 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22229 T595 C41 P63703 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e1859e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@660d402e),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e1859e4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@660d402e),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 22229 T611 C43 P63707 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4d3b82d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e11fee),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4d3b82d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@68e11fee),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22229 T595 C41 P63703 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 22230 T611 C43 P63707 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22229 T579 C40 P63699 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5841be48 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16cc601f),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5841be48 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16cc601f),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 22230 T611 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 22230 T579 C40 P63699 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 22230 T595 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 22231 T611 C43 P63707 oass.SolrIndexSearcher.<init> Opening Searcher@59f74900 main
[junit4:junit4] 2> 22231 T579 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 22231 T595 C41 P63703 oass.SolrIndexSearcher.<init> Opening Searcher@4a2b34fb main
[junit4:junit4] 2> 22231 T611 C43 P63707 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22231 T579 C40 P63699 oass.SolrIndexSearcher.<init> Opening Searcher@2041474e main
[junit4:junit4] 2> 22232 T625 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@59f74900 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 22232 T595 C41 P63703 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22232 T579 C40 P63699 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22232 T607 oasc.JmxMonitoredMap.put WARNING Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:467)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1520)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:986)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:938)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:330)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:516)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:239)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1749)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:129)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1626)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] 2>
[junit4:junit4] 2> 22232 T591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2041474e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22232 T625 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 22234 T591 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2/index
[junit4:junit4] 2> 22234 T611 C43 P63707 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 22234 T579 C40 P63699 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 22234 T607 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a2b34fb main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 22235 T607 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3/index
[junit4:junit4] 2> 22235 T595 C41 P63703 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 22236 T567 C42 P63696 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 22237 T533 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22240 T565 C42 P63696 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 22242 T580 C40 P63699 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22246 T596 C41 P63703 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22248 T612 C43 P63707 REQ /select {tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 24257 T545 C44 P63692 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/control/data
[junit4:junit4] 2> 24257 T545 C44 P63692 oass.SolrIndexSearcher.<init> Opening Searcher@1fa62593 realtime
[junit4:junit4] 2> 24258 T545 C44 P63692 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1428625379716759552)} 0 7
[junit4:junit4] 2> 24262 T567 C42 P63696 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty1
[junit4:junit4] 2> 24266 T595 C41 P63703 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty3
[junit4:junit4] 2> 24266 T579 C40 P63699 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty2
[junit4:junit4] 2> 24266 T611 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 24267 T595 C41 P63703 /update {update.distrib=FROMLEADER&_version_=-1428625379727245312&update.from=http://127.0.0.1:63696/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1428625379727245312)} 0 2
[junit4:junit4] 2> 24267 T579 C40 P63699 /update {update.distrib=FROMLEADER&_version_=-1428625379727245312&update.from=http://127.0.0.1:63696/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1428625379727245312)} 0 2
[junit4:junit4] 2> 24267 T611 C43 P63707 /update {update.distrib=FROMLEADER&_version_=-1428625379727245312&update.from=http://127.0.0.1:63696/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1428625379727245312)} 0 2
[junit4:junit4] 2> 24268 T567 C42 P63696 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1428625379727245312)} 0 7
[junit4:junit4] 2> 24273 T545 C44 P63692 /update {wt=javabin&version=2} {add=[0 (1428625379737731072)]} 0 2
[junit4:junit4] 2> 24280 T595 C41 P63703 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1428625379741925376)]} 0 1
[junit4:junit4] 2> 24281 T579 C40 P63699 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1428625379741925376)]} 0 2
[junit4:junit4] 2> 24281 T611 C43 P63707 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1428625379741925376)]} 0 2
[junit4:junit4] 2> 24282 T567 C42 P63696 /update {wt=javabin&version=2} {add=[0 (1428625379741925376)]} 0 7
[junit4:junit4] 2> 24285 T545 C44 P63692 /update {wt=javabin&version=2} {add=[1 (1428625379751362560)]} 0 1
[junit4:junit4] 2> 24291 T579 C40 P63699 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1428625379754508288)]} 0 1
[junit4:junit4] 2> 24291 T611 C43 P63707 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1428625379754508288)]} 0 1
[junit4:junit4] 2> 24291 T595 C41 P63703 /update {distrib.from=http://127.0.0.1:63696/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1428625379754508288)]} 0 1
[junit4:junit4] 2> 24292 T567 C42 P63696 /update {wt=javabin&version=2} {add=[1 (1428625379754508288)]} 0 5
[juni
[...truncated too long message...]
junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] 2> 138161 T533 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 138850 T536 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4] 2> 166825 T621 oasu.PeerSync.handleResponse WARNING PeerSync: core=collection1 url=http://127.0.0.1:63707 couldn't connect to http://127.0.0.1:63703/collection1/, counting as success
[junit4:junit4] 2> 166825 T621 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:63707 DONE. sync succeeded
[junit4:junit4] 2> 166826 T621 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 166827 T621 oasc.ShardLeaderElectionContext.runLeaderProcess Sync was not a success but no one else is active! I am the leader
[junit4:junit4] 2> 166827 T621 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63707/collection1/
[junit4:junit4] 2> 166827 T621 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@381c2f40
[junit4:junit4] 2> 166828 T621 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=10,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=305,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 166829 T621 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 166829 T621 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 166829 T621 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 166829 T621 C43 P63707 oasu.TransactionLog.forceClose SEVERE Error: Forcing close of tlog{file=./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/tlog/tlog.0000000000000000005 refcount=1}
[junit4:junit4] 2> 166832 T621 C43 P63707 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 166832 T621 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 166833 T621 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 166833 T621 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/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 166833 T621 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4
[junit4:junit4] 2> 166833 T621 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/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 166834 T621 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index
[junit4:junit4] 2> 166834 T621 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/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index.20130305012849346
[junit4:junit4] 2> 166834 T621 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362443308157/jetty4/index.20130305012849346
[junit4:junit4] 2> 166834 T621 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 166835 T621 oasc.LeaderElector$1.process WARNING org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard1/election/89289084643835916-127.0.0.1:63707__collection1-n_0000000003
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:153)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:150)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:150)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:243)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 166835 T621 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 166836 T621 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 166836 T621 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 166836 T621 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> 166836 T621 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 166837 T621 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=Direct), text=PostingsFormat(name=Lucene41WithOrds), _version_=PostingsFormat(name=Direct), rnd_b=Pulsing41(freqCutoff=19 minBlockSize=19 maxBlockSize=122), intDefault=PostingsFormat(name=Direct), id=Pulsing41(freqCutoff=19 minBlockSize=19 maxBlockSize=122), timestamp=PostingsFormat(name=Direct), a_t=PostingsFormat(name=Direct), range_facet_sl=PostingsFormat(name=Lucene41WithOrds), range_facet_si=PostingsFormat(name=MockSep), other_tl1=PostingsFormat(name=Direct), multiDefault=PostingsFormat(name=MockSep), a_si=PostingsFormat(name=MockSep)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=ru_RU, timezone=Europe/Warsaw
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=228169160,total=453115904
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestPseudoReturnFields, ResourceLoaderTest, ShowFileRequestHandlerTest, FieldAnalysisRequestHandlerTest, SuggesterTSTTest, SpatialFilterTest, RequiredFieldsTest, HardAutoCommitTest, TestIndexSearcher, PluginInfoTest, CSVRequestHandlerTest, TestStressRecovery, PrimUtilsTest, BinaryUpdateRequestHandlerTest, RecoveryZkTest, UUIDFieldTest, TestDistributedSearch, TestCharFilters, DistributedSpellCheckComponentTest, TestCoreContainer, TestLFUCache, TestSolrDeletionPolicy2, BasicZkTest, CacheHeaderTest, ChaosMonkeyNothingIsSafeTest, TestCollationKeyRangeQueries, SearchHandlerTest, DateFieldTest, AlternateDirectoryTest, CurrencyFieldOpenExchangeTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 167.22s, 1 test, 1 failure <<< FAILURES!
[...truncated 595 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:449: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1213: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:877: There were test failures: 260 suites, 1097 tests, 1 failure, 23 ignored (4 assumptions)
Total time: 51 minutes 12 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure